Conversation
|
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
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
Co-authored-by: Neel Shah <neel.shah@sentry.io>
| 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.
solnic
left a comment
There was a problem hiding this comment.
✅ but I left a bunch of minor 💅🏻 suggestions 🙃
| # @param env [Hash] Rack env | ||
| # @return [Float, nil] queue time in milliseconds or nil | ||
| def extract_queue_time(env) | ||
| return nil unless Sentry.configuration&.capture_queue_time |
There was a problem hiding this comment.
| return nil unless Sentry.configuration&.capture_queue_time | |
| return unless Sentry.configuration&.capture_queue_time |
| return nil unless Sentry.configuration&.capture_queue_time | ||
|
|
||
| header_value = env["HTTP_X_REQUEST_START"] | ||
| return nil unless header_value |
There was a problem hiding this comment.
| return nil unless header_value | |
| return unless header_value |
| return nil unless header_value | ||
|
|
||
| request_start = parse_request_start_header(header_value) | ||
| return nil unless request_start |
There was a problem hiding this comment.
| return nil unless request_start | |
| return unless request_start |
| total_time_ms = ((Time.now.to_f - request_start) * 1000).round(2) | ||
|
|
||
| # reject negative (clock skew between proxy & app server) | ||
| return nil unless total_time_ms >= 0 |
There was a problem hiding this comment.
| return nil unless total_time_ms >= 0 | |
| return unless total_time_ms >= 0 |
| total_time_ms | ||
| end | ||
| rescue StandardError | ||
| nil |
| elsif header_value.match?(/\A\d+(?:\.\d+)?\z/) | ||
| header_value.to_f | ||
| else | ||
| return nil |
There was a problem hiding this comment.
| return nil | |
| return |
Co-authored-by: Peter Solnica <peter@solnica.online>
Co-authored-by: Peter Solnica <peter@solnica.online>
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