Default new apps to tag logs with `request_id` #22949

Merged
merged 1 commit into from Jan 7, 2016

Conversation

Projects
None yet
7 participants
@schneems
Member

schneems commented Jan 6, 2016

In high volume applications it can be very difficult to figure out what is happening in logs because each request is not easily identified. For example 3 requests could look something like this:

Started GET "/" for 72.48.77.213 at 2016-01-06 20:30:21 +0000
  Rendered welcome/index.html.erb within layouts/application (0.1ms)
Started GET "/" for 72.48.77.213 at 2016-01-06 20:30:22 +0000
Started GET "/" for 72.48.77.213 at 2016-01-06 20:30:23 +0000
  Rendered welcome/index.html.erb within layouts/application (0.1ms)
Processing by WelcomeController#index as HTML
Completed 200 OK in 5ms (Views: 3.8ms | ActiveRecord: 0.0ms)
Processing by WelcomeController#index as HTML
  Rendered welcome/index.html.erb within layouts/application (0.1ms)
Completed 200 OK in 5ms (Views: 3.8ms | ActiveRecord: 0.0ms)
  Processing by WelcomeController#index as HTML
Completed 200 OK in 5ms (Views: 3.8ms | ActiveRecord: 0.0ms)

The :request_id log tag ensures that each request is tagged with a unique identifier. While they are still interleaved it is possible to figure out which lines belong to which requests. Like:

[c6034478-4026-4ded-9e3c-088c76d056f1] Started GET "/" for 72.48.77.213 at 2016-01-06 20:30:21 +0000
[c6034478-4026-4ded-9e3c-088c76d056f1]  Rendered welcome/index.html.erb within layouts/application (0.1ms)
[abuqw781-5026-6ded-7e2v-788c7md0L6fQ] Started GET "/" for 72.48.77.213 at 2016-01-06 20:30:22 +0000
[acfab2a7-f1b7-4e15-8bf6-cdaa008d102c] Started GET "/" for 72.48.77.213 at 2016-01-06 20:30:23 +0000
[abuqw781-5026-6ded-7e2v-788c7md0L6fQ]  Rendered welcome/index.html.erb within layouts/application (0.1ms)
[c6034478-4026-4ded-9e3c-088c76d056f1] Processing by WelcomeController#index as HTML
[c6034478-4026-4ded-9e3c-088c76d056f1] Completed 200 OK in 5ms (Views: 3.8ms | ActiveRecord: 0.0ms)
[abuqw781-5026-6ded-7e2v-788c7md0L6fQ] Processing by WelcomeController#index as HTML
[abuqw781-5026-6ded-7e2v-788c7md0L6fQ]  Rendered welcome/index.html.erb within layouts/application (0.1ms)
[abuqw781-5026-6ded-7e2v-788c7md0L6fQ] Completed 200 OK in 5ms (Views: 3.8ms | ActiveRecord: 0.0ms)
[acfab2a7-f1b7-4e15-8bf6-cdaa008d102c]  Processing by WelcomeController#index as HTML
[acfab2a7-f1b7-4e15-8bf6-cdaa008d102c] Completed 200 OK in 5ms (Views: 3.8ms | ActiveRecord: 0.0ms)

Now if you have the logs and you find this unique ID you can filter to only look at information from that request. So a filtered log output would be very clear:

[c6034478-4026-4ded-9e3c-088c76d056f1] Started GET "/" for 72.48.77.213 at 2016-01-06 20:30:21 +0000
[c6034478-4026-4ded-9e3c-088c76d056f1]  Rendered welcome/index.html.erb within layouts/application (0.1ms)
[c6034478-4026-4ded-9e3c-088c76d056f1] Processing by WelcomeController#index as HTML
[c6034478-4026-4ded-9e3c-088c76d056f1] Completed 200 OK in 5ms (Views: 3.8ms | ActiveRecord: 0.0ms)

In addition to this benefit the :request_id can be set via the X-Request-ID header so that the same request could be traced between multiple components. For example a request comes in Nginx (or another load balancer) could assign a request id. As the load balancer processes the request I can log using that id, then when the request is passed on to Rails, the same id is used. That way if a problem is determined to be not caused in Rails it could be traced back to other components with the same ID. You can set a value in nginx for example using something like this:

  location / {
      proxy_pass http://upstream;
      proxy_set_header X-Request-Id $pid-$msec-$remote_addr-$request_length;
  }
# http://stackoverflow.com/questions/17748735/setting-a-trace-id-in-nginx-load-balancer

Heroku sets this header value so problems like timeouts that are logged by like router can be traced back to specific request within the application.

Whether you are using components that are setting request ID or not, all production applications can benefit from the additional debugging information of having a unique identifier for all requests. This change will only affect new applications, anyone can opt out by commenting or removing the line in config/production.rb.

+
+ with_rails_env "development" do
+ app 'development'
+ assert_equal [:request_id], Rails.application.config.log_tags

This comment has been minimized.

@kaspth

kaspth Jan 6, 2016

Member

Shouldn't this be assert_not_equal?

@kaspth

kaspth Jan 6, 2016

Member

Shouldn't this be assert_not_equal?

This comment has been minimized.

@schneems

schneems Jan 6, 2016

Member

Fixed.

@schneems

schneems Jan 6, 2016

Member

Fixed.

@@ -55,6 +55,7 @@ Rails.application.configure do
# Prepend all log lines with the following tags.
# config.log_tags = [ :subdomain, :request_id ]
+ config.log_tags = [ :request_id ]

This comment has been minimized.

@kaspth

kaspth Jan 6, 2016

Member

Feels weird to having this line almost match the comment above. Can we find some better methods to add or should we ditch it altogether since we're showing usage now?

@kaspth

kaspth Jan 6, 2016

Member

Feels weird to having this line almost match the comment above. Can we find some better methods to add or should we ditch it altogether since we're showing usage now?

This comment has been minimized.

@schneems

schneems Jan 6, 2016

Member

Sounds good, updated

@schneems

schneems Jan 6, 2016

Member

Sounds good, updated

Default new apps to tag logs with `request_id`
In high volume applications it can be very difficult to figure out what is happening in logs because each request is not easily identified. For example 3 requests could look something like this:

```
Started GET "/" for 72.48.77.213 at 2016-01-06 20:30:21 +0000
  Rendered welcome/index.html.erb within layouts/application (0.1ms)
Started GET "/" for 72.48.77.213 at 2016-01-06 20:30:22 +0000
Started GET "/" for 72.48.77.213 at 2016-01-06 20:30:23 +0000
  Rendered welcome/index.html.erb within layouts/application (0.1ms)
Processing by WelcomeController#index as HTML
Completed 200 OK in 5ms (Views: 3.8ms | ActiveRecord: 0.0ms)
Processing by WelcomeController#index as HTML
  Rendered welcome/index.html.erb within layouts/application (0.1ms)
Completed 200 OK in 5ms (Views: 3.8ms | ActiveRecord: 0.0ms)
  Processing by WelcomeController#index as HTML
Completed 200 OK in 5ms (Views: 3.8ms | ActiveRecord: 0.0ms)
```

The `:request_id` log tag ensures that each request is tagged with a unique identifier. While they are still interleaved it is possible to figure out which lines belong to which requests. Like:

```
[c6034478-4026-4ded-9e3c-088c76d056f1] Started GET "/" for 72.48.77.213 at 2016-01-06 20:30:21 +0000
[c6034478-4026-4ded-9e3c-088c76d056f1]  Rendered welcome/index.html.erb within layouts/application (0.1ms)
[abuqw781-5026-6ded-7e2v-788c7md0L6fQ] Started GET "/" for 72.48.77.213 at 2016-01-06 20:30:22 +0000
[acfab2a7-f1b7-4e15-8bf6-cdaa008d102c] Started GET "/" for 72.48.77.213 at 2016-01-06 20:30:23 +0000
[abuqw781-5026-6ded-7e2v-788c7md0L6fQ]  Rendered welcome/index.html.erb within layouts/application (0.1ms)
[c6034478-4026-4ded-9e3c-088c76d056f1] Processing by WelcomeController#index as HTML
[c6034478-4026-4ded-9e3c-088c76d056f1] Completed 200 OK in 5ms (Views: 3.8ms | ActiveRecord: 0.0ms)
[abuqw781-5026-6ded-7e2v-788c7md0L6fQ] Processing by WelcomeController#index as HTML
[abuqw781-5026-6ded-7e2v-788c7md0L6fQ]  Rendered welcome/index.html.erb within layouts/application (0.1ms)
[abuqw781-5026-6ded-7e2v-788c7md0L6fQ] Completed 200 OK in 5ms (Views: 3.8ms | ActiveRecord: 0.0ms)
[acfab2a7-f1b7-4e15-8bf6-cdaa008d102c]  Processing by WelcomeController#index as HTML
[acfab2a7-f1b7-4e15-8bf6-cdaa008d102c] Completed 200 OK in 5ms (Views: 3.8ms | ActiveRecord: 0.0ms)
```

Now if you have the logs and you find this unique ID you can filter to only look at information from that request. So a filtered log output would be very clear:

```
[c6034478-4026-4ded-9e3c-088c76d056f1] Started GET "/" for 72.48.77.213 at 2016-01-06 20:30:21 +0000
[c6034478-4026-4ded-9e3c-088c76d056f1]  Rendered welcome/index.html.erb within layouts/application (0.1ms)
[c6034478-4026-4ded-9e3c-088c76d056f1] Processing by WelcomeController#index as HTML
[c6034478-4026-4ded-9e3c-088c76d056f1] Completed 200 OK in 5ms (Views: 3.8ms | ActiveRecord: 0.0ms)
```

In addition to this benefit the `:request_id` can be set via the `X-Request-ID` header so that the same request could be traced between multiple components. For example a request comes in Nginx (or another load balancer) could assign a request id. As the load balancer processes the request I can log using that id, then when the request is passed on to Rails, the same id is used. That way if a problem is determined to be not caused in Rails it could be traced back to other components with the same ID. You can set a value in nginx for example using something like this:

```
  location / {
      proxy_pass http://upstream;
      proxy_set_header X-Request-Id $pid-$msec-$remote_addr-$request_length;
  }
# http://stackoverflow.com/questions/17748735/setting-a-trace-id-in-nginx-load-balancer
```

Heroku sets this header value so problems like timeouts that are logged by like router can be traced back to specific request within the application.

Whether you are using components that are setting request ID or not, all production applications can benefit from the additional debugging information of having a unique identifier for all requests. This change will only affect new applications, anyone can opt out by commenting or removing the line in `config/production.rb`.

@kaspth kaspth added this to the 5.0.0 milestone Jan 6, 2016

@rafaelfranca

This comment has been minimized.

Show comment
Hide comment
@rafaelfranca

rafaelfranca Jan 6, 2016

Member

LGTM but since it is changing a default I'll defer to @dhh.

Member

rafaelfranca commented Jan 6, 2016

LGTM but since it is changing a default I'll defer to @dhh.

dhh added a commit that referenced this pull request Jan 7, 2016

Merge pull request #22949 from schneems/schneems/request-id
Default new apps to tag logs with `request_id`

@dhh dhh merged commit 071cbb3 into rails:master Jan 7, 2016

1 check passed

continuous-integration/travis-ci/pr The Travis CI build passed
Details
@dhh

This comment has been minimized.

Show comment
Hide comment
@dhh

dhh Jan 7, 2016

Member

Sounds good to me! Can't imagine not request-id tagging logging in production either.

Member

dhh commented Jan 7, 2016

Sounds good to me! Can't imagine not request-id tagging logging in production either.

@schneems

This comment has been minimized.

Show comment
Hide comment
@schneems

schneems Jan 7, 2016

Member

❤️🚀😄

Member

schneems commented Jan 7, 2016

❤️🚀😄

@jingweno

This comment has been minimized.

Show comment
Hide comment
@jingweno

jingweno Jan 7, 2016

Contributor

👍

Contributor

jingweno commented Jan 7, 2016

👍

@ridiculous

This comment has been minimized.

Show comment
Hide comment
@ridiculous

ridiculous Jan 9, 2016

Contributor

😍

Contributor

ridiculous commented Jan 9, 2016

😍

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment