feat: queue time capture for Rack #2838
Conversation
|
![github-advanced-security[bot]](https://avatars.githubusercontent.com/in/57789?s=60&v=4){kind=small}
dingsdax
requested review from
sl0thentr0py and
solnic
and removed request for
solnic
sentry-ruby/lib/sentry/span.rb
Outdated
| MESSAGING_MESSAGE_RETRY_COUNT = "messaging.message.retry.count" | ||
|
|
||
| # Time in ms the request spent in the server queue before processing began. | ||
| HTTP_QUEUE_TIME_MS = "http.queue_time_ms" |
There was a problem hiding this comment.
@AbhiPrasad @lcian is there an attribute convention for time spent in queue waiting for the http request to be picked up in an HTTP server?
The closest I could find is http.client.request.time_in_queue but that's for clients.
There was a problem hiding this comment.
Hmmm I cannot find anything like that. Maybe we introduce our own http.server.request.time_in_queue counterpart?
There was a problem hiding this comment.
sounds good; shall I add to sentry-conventions too?
sl0thentr0py
left a comment
sl0thentr0py
left a comment
There was a problem hiding this comment.
some small stuff, and mainly want to wait for feedback on the attribute convention name
| total_time_ms = ((Time.now.to_f - request_start) * 1000).round(2) | ||
|
|
||
| # reject negative (clock skew between proxy & app server) or very large values (> 60 seconds) | ||
| return nil unless total_time_ms >= 0 && total_time_ms < 60_000 |
There was a problem hiding this comment.
not sure about the upper bound here, would still be useful to know right?
There was a problem hiding this comment.
wdym? remove upper bound here? should be fine too
There was a problem hiding this comment.
yes let's remove the upper bound
There was a problem hiding this comment.
yes let's remove the upper bound
![cursor[bot]](https://avatars.githubusercontent.com/in/1210556?s=60&v=4){kind=small}
| header_value.to_f | ||
| else | ||
| return nil | ||
| end |
There was a problem hiding this comment.
Non-numeric t= prefixed header values produce incorrect queue time
Medium Severity
The parse_request_start_header function validates format with a regex for raw numeric timestamps but not for t= prefixed values. When receiving a malformed header like t=invalid, "invalid".to_f silently returns 0.0 (Ruby's behavior for non-numeric strings). This results in a timestamp of Unix epoch (1970), causing the queue time calculation to return ~56 years of queue time instead of nil. The issue affects any malformed t= prefixed header value including t=, t=abc, etc.
Captures how long requests wait for a e.g. Puma thread from
X-Request-Startheaders and attaches it to transactions ashttp.queue_time_ms. Sentry only measures after Puma picks up the request. Under load, requests might wait long in the queue but only take a fraction to process. Similar to what judoscale and scout do.works with all major reverse proxies:
X-Request-Start: t=1234567890.123(seconds)X-Request-Start: t=1234567890123456(microseconds)X-Request-Start: t=1234567890123456(microseconds)X-Request-Start: t=1234567890(seconds)subtracts
puma.request_body_waitfor accuracy (excludes slow client uploads from queue time).Usage
works 🤞 if your reverse proxy sets the header:
opt-out