Explain format of Heroku logs

Question

By default, Heroku generates two log messages for each request to a (Ruby) app. In each case, there are a few fields whose meanings are not obvious. First, the router message (as it appears in a logplex drain):

<158>1 2014-08-04T18:28:43.078581+00:00 host heroku router - at=info method=GET path="/foo" host=app-name-7277.herokuapp.com request_id=e5bb3580-44b0-46d2-aad3-185263641044 fwd="50.168.96.221" dyno=web.1 connect=0ms service=2ms status=200 bytes=415

Most of this is fairly obvious, but I have no idea about the <158>1 at the beginning, the word host after the timestamp, and the - after "router".

Next, the web app message:

<190>1 2014-08-04T18:28:43.015630+00:00 host app web.1 - 50.168.96.221 - - [04/Aug/2014 18:28:43] "GET /foo HTTP/1.1" 200 12 0.0019

This has the same mysteries as the router message, plus two more dashes after the IP address.

Does anyone know of complete documentation for the Heroku log format? All of the sources I've been able to find online are quite vague.

Answer 1

Heroku logs have a long history of being relayed over syslog and are roughly RFC5424 formatted.

Everything before the first - is the syslog header, who's format is detailed here: https://www.rfc-editor.org/rfc/rfc5424#section-6.2

Everything after that is the original message from the app.

So let's break the first message down:

• <158>: This is the PRI, see https://www.rfc-editor.org/rfc/rfc5424#section-6.2.1
• 1: This is the "version", see https://www.rfc-editor.org/rfc/rfc5424#section-6.2.2
• 2014-08-04T18:28:43.078581+00:00: Is the date stamp, including TZ, see https://www.rfc-editor.org/rfc/rfc5424#section-6.2.3
• host: Is the "hostname" of the originating system, see https://www.rfc-editor.org/rfc/rfc5424#section-6.2.4. This is effectively stripped though and replaced with "host"
• heroku: The "app name", see https://www.rfc-editor.org/rfc/rfc5424#section-6.2.5. ATM: This will be either be "heroku" or "app" depending on what generated the message. If the log message was generated by a heroku piece of infrastructure this will be "heroku". If the log message was generated by the user's app (or an add-on) this will be "app".
• router: The PROCID, see https://www.rfc-editor.org/rfc/rfc5424#section-6.2.6. This will be the name of the component / dyno that generated the message.
• -: The MSGID field, see https://www.rfc-editor.org/rfc/rfc5424#section-6.2.7. We don't use it, so it's a - instead.

In the first example message you've posted the rest of the line is the message that the router sent:

at=info method=GET path="/foo" host=app-name-7277.herokuapp.com request_id=e5bb3580-44b0-46d2-aad3-185263641044 fwd="50.168.96.221" dyno=web.1 connect=0ms service=2ms status=200 bytes=415

In the second example message you've posted the rest of the line is the line emitted by the application in question:

I don't know what that app is, but generating something that looks apache like to me. Heroku doesn't generate these, apps heroku runs for customers do. Some apps will duplicate router log related information for each request, some won't. It depends on the apps logging setup.

You can find more info about the format of data in the heroku generated messages here: https://devcenter.heroku.com

Specifically:

• Heroku Router Logs: https://devcenter.heroku.com/articles/http-routing#heroku-router-log-format
• Heroku Runtime Metrics: https://devcenter.heroku.com/articles/log-runtime-metrics
• Heroku Postgres: https://devcenter.heroku.com/articles/heroku-postgres-metrics-logs