Log rack-timeout ready and completed messages in DEBUG mode

[dacook]

What? Why?

I noticed heaps of unnecessary rack-timeout lines in server logs. There's one at the start and end of each request, but it doesn't provide any helpful info:

I, [2025-01-29 23:10:48 #2546762]  INFO -- : source=rack-timeout id=615f34b0-f409-4109-ab1a-534251436f77 wait=2ms timeout=29998ms state=ready
I, [2025-01-29 23:10:48 #2546762]  INFO -- : [615f34b0-f409-4109-ab1a-534251436f77] Started GET "/" for 172.105.161.249 at 2025-01-29 23:10:48 +0000
I, [2025-01-29 23:10:48 #2546762]  INFO -- : [615f34b0-f409-4109-ab1a-534251436f77] Processing by HomeController#index as */*
I, [2025-01-29 23:10:48 #2546762]  INFO -- : [615f34b0-f409-4109-ab1a-534251436f77]   Rendered home/index.html.haml within layouts/darkswarm (Duration: 17.5ms | Allocations: 5719)
I, [2025-01-29 23:10:48 #2546762]  INFO -- : [615f34b0-f409-4109-ab1a-534251436f77]   Rendered layout layouts/darkswarm.html.haml (Duration: 37.3ms | Allocations: 13696)
I, [2025-01-29 23:10:48 #2546762]  INFO -- : [615f34b0-f409-4109-ab1a-534251436f77] Completed 200 OK in 41ms (Views: 34.4ms | ActiveRecord: 3.4ms | Allocations: 14897)
I, [2025-01-29 23:10:48 #2546762]  INFO -- : source=rack-timeout id=615f34b0-f409-4109-ab1a-534251436f77 wait=2ms timeout=29998ms service=49ms state=completed

So we don't need these lines, but we still want to know when timeouts occur.

What should we test?

Note that rack-timeout is disabled on dev by default.
I tested this in dev by adding a sleep to HomeController and enabling rack timeout in .env.development.local:

RACK_TIMEOUT_SERVICE_TIMEOUT="10"
RACK_TIMEOUT_WAIT_TIMEOUT="10"
RACK_TIMEOUT_WAIT_OVERTIME="10"

DEV_LOG_LEVEL = info

Looks good: no unnecessary "ready" or "completed" messages, and it correctly shows "timed_out"

Started GET "/" for ::1 at 2025-01-30 10:24:55 +1100
Processing by HomeController#index as HTML
source=rack-timeout id=1088070d-ac06-4899-a096-01e4c60ec81d timeout=10000ms service=10001ms state=timed_out
  Rendered public/500.html (Duration: 0.4ms | Allocations: 99)
Completed 504 Gateway Timeout in 9899ms (Views: 8.0ms | ActiveRecord: 33.4ms | SQL Queries: 7 (0 cached) | Allocations: 192342)

[mkllnk]

I tested and can confirm that it's doing the right thing. Unfortunately the log doesn't show which request timed out. I think that we would need to add request ids to the log format for that. That's another task though.

Merging.

[dacook]

Actually it does include the process id (eg id=1088070d-ac06-4899-a096-01e4c60ec81d), so I think that could be matched up with the log line that shows the request URL. It probably didn't show in my example because I was on my dev environment (I had a feeling it was worth staging for a better test, oh well).
But I agree the format could be better: it should match the format using square brackets []. The key message "timed_out" could be clearer too. Ok I couldn't resist, I'll have a quick look and see what I can do.

[dacook]

I had a try, but failed: dacook@31d0570

Oh well.