[SERVER-81542] Improve logging in FSM suites Created: 28/Sep/23  Updated: 29/Oct/23  Resolved: 09/Oct/23

Status: Closed
Project: Core Server
Component/s: None
Affects Version/s: None
Fix Version/s: 7.2.0-rc0

Type: Improvement Priority: Major - P3
Reporter: Sean Zimmerman Assignee: Sean Zimmerman
Resolution: Fixed Votes: 0
Labels: repl-shortlist
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Related
is related to SERVER-32095 Attach client.application.name to con... Closed
Assigned Teams:
Replication
Backwards Compatibility: Fully Compatible
Sprint: Repl 2023-10-16
Participants:

 Description   

Debugging can be hard in FSM suites since it is difficult to track the progress a specific thread is making. It would be helpful if the current thread ID was logged automatically in the message for fsm workloads

 

SERVER-32095 already includes the tid in calls to print which jsTestLog uses, but since jsTestLog adds newlines in the thread ID gets separated from the actual log message, meaning that doing jsTestLog("Example log line") in thread 11 will result in

[tid:11]
 
[jsTest] ----
Example log line
[jsTest] ----

It would be ideal if the thread ID was included in the actual logged message, something like

[jsTest] ----
[tid:11] Example log line
[jsTest] ---- 

This can likely be achieved by worker_thread.js overriding jsTestLog function to include the ID into each message line



 Comments   
Comment by Githook User [ 09/Oct/23 ]

Author:

{'name': 'seanzimm', 'email': 'sean.zimmerman@mongodb.com', 'username': 'seanzimm'}

Message: SERVER-81542: Log tid in message within fsm workers
Branch: master
https://github.com/mongodb/mongo/commit/3120daebe84101c44dcff43d21ca420bbd3b73cb

Comment by Sean Zimmerman [ 28/Sep/23 ]

My intention with this was that it would be helpful to include thread ID automatically in jsTestLog calls, for suites that use logging this would be helpful to track thread progress without needing to rely on the test writes putting it in their logs manually (for example random_DDL_CRUD_operations logs each state with TID in the beginning but when it logs the state being complete there is no thread ID so finding the corresponding success log is more difficult

Comment by Max Hirschhorn [ 28/Sep/23 ]

Is there an example of a log message which doesn't contain the thread ID? SERVER-32095 was some previous work done in this area to have calls to print() include the thread ID as well as the connection ID (aka Client::_desc) and I'm curious what got missed.

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