[SERVER-83858] Include a "request ID" in log lines Created: 04/Dec/23  Updated: 05/Dec/23

Status: Needs Scheduling
Project: Core Server
Component/s: None
Affects Version/s: None
Fix Version/s: None

Type: Improvement Priority: Major - P3
Reporter: David Percy Assignee: Backlog - Service Architecture
Resolution: Unresolved Votes: 0
Labels: make-server-testing-joyful
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Assigned Teams:
Service Arch
Participants:

 Description   

When I'm searching a log file, usually I'm interested in several events that happened during the same request handler. Could we add a unique "request ID" to tie these together?

This would be different than the existing "ctx" field, which lets you separate events from different threads, but not from different requests.

I imagine the implementation would be something like:

  • keep a process-global counter for generating unique IDs
  • add an optional<int> currentRequestId to something (Client? RequestExecutionContext?)
  • when we start handling a request (same place we log "About to run"?), update currentRequestId with a fresh ID
  • look up currentRequestId when we populate log attributes, just like "ctx"
  • clear currentRequestId after we send the response


 Comments   
Comment by David Percy [ 04/Dec/23 ]

For an example how someone could use this: I ran a jstest locally which does many queries.  I can use grep "About to run" out to find which request I’m interested in, and then I want to find exactly the log lines that correspond to that request.  Currently I can use the date + connection ID… something like:

grep conn9 out | sed -n '/20:42:18.*About to run/,/About to run/ p'

But it would be simpler if I could note the request ID (say 123) and run:

jq 'select(.r == 123)'

 
Another use case: I’m debugging a flaky test, so I run with --repeatTests 20.  Once I find all the interesting "About to run" lines, I want the "Estimated cardinality" lines within those requests.  If I could extract a request ID (say 123, 456, 789), then I could run:

jq 'select(.msg == "Estimated cardinality" and .r == (123, 456, 789))'

 

Generated at Thu Feb 08 06:53:22 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.