Rails' Tagged Logging + Heroku Dyno Metadata

Posted on January 23, 2016

Rails added “tagged logging” awhile back, but it’s never seemed like a particularly useful thing to me. I care far more about the log output than a request ID or other data.But the more and more I debug odd edge-cases in other people’s Rails apps, the more I see the need the potential benefits.

“request_id” may be what most people think of with Rails’ tagged logging. Adding this to your production.rb:

config.log_tags += [ :uuid ]

Gives you a unique ID for each request:

[d50fcd66-97c9-4f9e-9a76-d828e1485a8d]
[d50fcd66-97c9-4f9e-9a76-d828e1485a8d]
[d50fcd66-97c9-4f9e-9a76-d828e1485a8d] Started GET "/" for ::1 at 2016-01-13 09:22:54 -0800
[d50fcd66-97c9-4f9e-9a76-d828e1485a8d]   ActiveRecord::SchemaMigration Load (0.5ms)  SELECT "schema_migrations".* FROM "schema_migrations"
[d50fcd66-97c9-4f9e-9a76-d828e1485a8d] Processing by PostsController#index as HTML
[d50fcd66-97c9-4f9e-9a76-d828e1485a8d]   Post Load (0.6ms)  SELECT "posts".* FROM "posts"
[d50fcd66-97c9-4f9e-9a76-d828e1485a8d]   Rendered posts/index.html.erb within layouts/application (20.0ms)
[d50fcd66-97c9-4f9e-9a76-d828e1485a8d] Completed 200 OK in 283ms (Views: 276.8ms | ActiveRecord: 4.4ms)

This can be very handy to use when filtering a noisy log stream. (FYI: logging request ID’s is about to become a default in Rails)

But the full power of this feature is that you can shove whatever data you want in there. UUID, server name, or even a Git SHA.

In a recent Heroku support ticket, a customer mentioned he was using Heroku’s Preboot feature. With Preboot, Heroku will deploy your code to a new dyno, then cut over the requests to it, thus avoiding any request queueing while your app restarts.

The customer wanted to be able to see which version of his code was serving incoming requests at a particular time. This is a great use-case for Rails’ tagged logging, and Heroku’s new “dyno metadata”.

“Dyno metadata” adds a ton of information on your running dyno like: app id, dyno id, release version, and Git SHA. This information is saved as an ENV var for easy reference. Here’s a sampling:

HEROKU_APP_ID:                   9daa2797-e49b-4624-932f-ec3f9688e3da
HEROKU_APP_NAME:                 example-app
HEROKU_DYNO_ID:                  1vac4117-c29f-4312-521e-ba4d8638c1ac
HEROKU_RELEASE_VERSION:          v42
HEROKU_SLUG_COMMIT:              2c3a0b24069af49b3de35b8e8c26765c1dba9ff0
HEROKU_SLUG_DESCRIPTION:         Deploy 2c3a0b2

This feature is currently as “Labs” feature, so add it to your app with this command:

heroku labs:enable runtime-dyno-metadata -a <app_name>

You can then pass the ENV["HEROKU_SLUG_COMMIT"] into your Rails’ logging:

config.log_tags += [ ENV["HEROKU_SLUG_COMMIT"] ]

Now you’ll know exactly which Git version your app is running. Very handy for Preboot or otherwise! (Alternatively, your might choose to use ENV["HEROKU_RELEASE_VERSION"] instead, since the Git SHA length might be bothersome)

2016-01-13T17:41:16.857263+00:00 app[web.1]: [f8ce293494e4fa6634cdb30995bade8817047a7f] Started GET "/" for 70.209.200.115 at 2016-01-13 17:41:16 +0000
2016-01-13T17:41:17.084326+00:00 app[web.1]: [f8ce293494e4fa6634cdb30995bade8817047a7f]   Post Load (6.7ms)  SELECT "posts".* FROM "posts"
2016-01-13T17:41:16.984597+00:00 app[web.1]: [f8ce293494e4fa6634cdb30995bade8817047a7f] Processing by PostsController#index as HTML
2016-01-13T17:41:17.119678+00:00 app[web.1]: [f8ce293494e4fa6634cdb30995bade8817047a7f]   Rendered posts/index.html.erb within layouts/application (108.8ms)
2016-01-13T17:41:17.146112+00:00 app[web.1]: [f8ce293494e4fa6634cdb30995bade8817047a7f] Completed 200 OK in 161ms (Views: 140.3ms | ActiveRecord: 16.5ms)

Here’s an example of one of my Heroku apps cutting over from one version of my code to another. Note the change from adc997c to 7be3dfd:

2016-01-13T17:53:42.704148+00:00 app[web.1]: [adc997cad5e8941b1a085ae3875e2370824cffb6] Started HEAD "/" for 70.209.200.115 at 2016-01-13 17:53:42 +0000
2016-01-13T17:53:42.711699+00:00 app[web.1]: [adc997cad5e8941b1a085ae3875e2370824cffb6]   Post Load (0.9ms)  SELECT "posts".* FROM "posts"
2016-01-13T17:53:42.713734+00:00 app[web.1]: [adc997cad5e8941b1a085ae3875e2370824cffb6] Completed 200 OK in 5ms (Views: 3.0ms | ActiveRecord: 0.9ms)
2016-01-13T17:53:42.708938+00:00 app[web.1]: [adc997cad5e8941b1a085ae3875e2370824cffb6] Processing by PostsController#index as */*
2016-01-13T17:53:42.712343+00:00 app[web.1]: [adc997cad5e8941b1a085ae3875e2370824cffb6]   Rendered posts/index.html.erb within layouts/application (2.1ms)
2016-01-13T17:53:45.379444+00:00 app[web.1]: [7be3dfd2f62e3a876d74212be6a7c9dab8128f1d] Started HEAD "/" for 70.209.200.115 at 2016-01-13 17:53:45 +0000
2016-01-13T17:53:45.477517+00:00 app[web.1]: [7be3dfd2f62e3a876d74212be6a7c9dab8128f1d]   Post Load (3.0ms)  SELECT "posts".* FROM "posts"
2016-01-13T17:53:45.495110+00:00 app[web.1]: [7be3dfd2f62e3a876d74212be6a7c9dab8128f1d] Completed 200 OK in 43ms (Views: 29.6ms | ActiveRecord: 7.3ms)
2016-01-13T17:53:45.498012+00:00 heroku[router]: at=info method=HEAD path="/" host=whispering-eyrie-6721.herokuapp.com request_id=11b40ae8-2cf4-4915-89af-0cecad83005a fwd="70.209.200.115" dyno=web.1 connect=1ms service=123ms status=200 bytes=684
2016-01-13T17:53:45.452038+00:00 app[web.1]: [7be3dfd2f62e3a876d74212be6a7c9dab8128f1d] Processing by PostsController#index as */*
2016-01-13T17:53:45.492969+00:00 app[web.1]: [7be3dfd2f62e3a876d74212be6a7c9dab8128f1d]   Rendered posts/index.html.erb within layouts/application (31.9ms)
2016-01-13T17:53:48.316089+00:00 heroku[router]: at=info method=HEAD path="/" host=whispering-eyrie-6721.herokuapp.com request_id=3f08fd7d-4b40-4c3f-8f25-3f245a1e3188 fwd="70.209.200.115" dyno=web.1 connect=3ms service=9ms status=200 bytes=684
2016-01-13T17:53:48.309340+00:00 app[web.1]: [7be3dfd2f62e3a876d74212be6a7c9dab8128f1d] Started HEAD "/" for 70.209.200.115 at 2016-01-13 17:53:48 +0000
2016-01-13T17:53:48.315024+00:00 app[web.1]: [7be3dfd2f62e3a876d74212be6a7c9dab8128f1d]   Post Load (1.7ms)  SELECT "posts".* FROM "posts"
2016-01-13T17:53:48.316491+00:00 app[web.1]: [7be3dfd2f62e3a876d74212be6a7c9dab8128f1d] Completed 200 OK in 4ms (Views: 2.2ms | ActiveRecord: 1.7ms)
2016-01-13T17:53:48.312092+00:00 app[web.1]: [7be3dfd2f62e3a876d74212be6a7c9dab8128f1d] Processing by PostsController#index as */*
2016-01-13T17:53:48.315465+00:00 app[web.1]: [7be3dfd2f62e3a876d74212be6a7c9dab8128f1d]   Rendered posts/index.html.erb within layouts/application (2.7ms)

Tagged Logging is an incredibly powerful feature in Rails that gets very little attention. Here’s a few other articles I found that give it a more in-depth explanation. Enjoy!

Hi there, I'm Jon.

Writer. Musician. Adventurer. Nerd.

Purveyor of GIFs and dad jokes.