[SERVER-27399] TRACKING logger is too verbose Created: 13/Dec/16  Updated: 05/Apr/17  Resolved: 26/Jan/17

Status: Closed
Project: Core Server
Component/s: Sharding
Affects Version/s: 3.4.0, 3.5.1
Fix Version/s: 3.5.3

Type: Task Priority: Major - P3
Reporter: Kaloian Manassiev Assignee: Misha Tyulenev
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Related
Backwards Compatibility: Fully Compatible
Sprint: Sharding 2017-01-02, Sharding 2017-02-13
Participants:
Linked BF Score: 0

 Description   

The TRACKING logger was introduced with the idea to help trace requests across multiple nodes (for example mongos -> shard -> config server). It is enabled by default for every command when the testCommands server setting is enabled.

Unfortunately it generates too much log and pollutes the test logging output and in addition we have seen tests fail with time limit exceeded errors, most likely due to the device holding the logs getting overloaded.

This ticket is to assess the usefulness of this component in diagnosing test failures and possibly turning it off.

Here is an example of the output:

s20003| 2016-12-13T09:58:49.404-0500 D TRACKING [Uptime reporter] Cmd: NotSet, TrackingId: 58500ca987716a124220c02f
c20002| 2016-12-13T09:58:49.407-0500 D TRACKING [conn4] Cmd: update, TrackingId: 58500ca987716a124220c02f|58500ca987716a124220c030
c20002| 2016-12-13T09:58:49.428-0500 D TRACKING [conn4] Cmd: find, TrackingId: 58500ca987716a124220c02f|58500ca987716a124220c031
c20002| 2016-12-13T09:58:49.439-0500 D TRACKING [conn4] Cmd: find, TrackingId: 58500ca987716a124220c02f|58500ca987716a124220c032
c20002| 2016-12-13T09:58:49.448-0500 D TRACKING [conn4] Cmd: find, TrackingId: 58500ca987716a124220c02f|58500ca987716a124220c033
d20000| 2016-12-13T09:58:51.996-0500 D TRACKING [conn3] Cmd: features, TrackingId: 58500b4f26108c37af891a3d|58500cab26108c37af891b3b
d20001| 2016-12-13T09:58:51.998-0500 D TRACKING [conn3] Cmd: features, TrackingId: 58500b4f26108c37af891a3d|58500cab26108c37af891b3c
d20000| 2016-12-13T09:58:52.013-0500 D TRACKING [conn3] Cmd: listDatabases, TrackingId: 58500b4f26108c37af891a3d|58500cac26108c37af891b3d
d20000| 2016-12-13T09:58:52.025-0500 D TRACKING [conn3] Cmd: serverStatus, TrackingId: 58500b4f26108c37af891a3d|58500cac26108c37af891b3e
d20001| 2016-12-13T09:58:52.040-0500 D TRACKING [conn3] Cmd: listDatabases, TrackingId: 58500b4f26108c37af891a3d|58500cac26108c37af891b3f
d20001| 2016-12-13T09:58:52.046-0500 D TRACKING [conn3] Cmd: serverStatus, TrackingId: 58500b4f26108c37af891a3d|58500cac26108c37af891b40
d20000| 2016-12-13T09:58:52.173-0500 D TRACKING [conn3] Cmd: listDatabases, TrackingId: 58500b4f26108c37af891a3d|58500cac26108c37af891b41
d20000| 2016-12-13T09:58:52.187-0500 D TRACKING [conn3] Cmd: serverStatus, TrackingId: 58500b4f26108c37af891a3d|58500cac26108c37af891b42
d20001| 2016-12-13T09:58:52.198-0500 D TRACKING [conn3] Cmd: listDatabases, TrackingId: 58500b4f26108c37af891a3d|58500cac26108c37af891b43
d20001| 2016-12-13T09:58:52.202-0500 D TRACKING [conn3] Cmd: serverStatus, TrackingId: 58500b4f26108c37af891a3d|58500cac26108c37af891b44
s20003| 2016-12-13T09:58:59.455-0500 D TRACKING [Uptime reporter] Cmd: NotSet, TrackingId: 58500cb387716a124220c034
c20002| 2016-12-13T09:58:59.459-0500 D TRACKING [conn4] Cmd: update, TrackingId: 58500cb387716a124220c034|58500cb387716a124220c035
c20002| 2016-12-13T09:58:59.476-0500 D TRACKING [conn4] Cmd: find, TrackingId: 58500cb387716a124220c034|58500cb387716a124220c036
c20002| 2016-12-13T09:58:59.482-0500 D TRACKING [conn4] Cmd: find, TrackingId: 58500cb387716a124220c034|58500cb387716a124220c037
c20002| 2016-12-13T09:58:59.489-0500 D TRACKING [conn4] Cmd: find, TrackingId: 58500cb387716a124220c034|58500cb387716a124220c038
d20000| 2016-12-13T09:59:02.330-0500 D TRACKING [conn3] Cmd: features, TrackingId: 58500b4f26108c37af891a3d|58500cb626108c37af891b46
d20001| 2016-12-13T09:59:02.334-0500 D TRACKING [conn3] Cmd: features, TrackingId: 58500b4f26108c37af891a3d|58500cb626108c37af891b47
d20000| 2016-12-13T09:59:02.357-0500 D TRACKING [conn3] Cmd: listDatabases, TrackingId: 58500b4f26108c37af891a3d|58500cb626108c37af891b48
d20000| 2016-12-13T09:59:02.371-0500 D TRACKING [conn3] Cmd: serverStatus, TrackingId: 58500b4f26108c37af891a3d|58500cb626108c37af891b49
d20001| 2016-12-13T09:59:02.388-0500 D TRACKING [conn3] Cmd: listDatabases, TrackingId: 58500b4f26108c37af891a3d|58500cb626108c37af891b4a
d20001| 2016-12-13T09:59:02.391-0500 D TRACKING [conn3] Cmd: serverStatus, TrackingId: 58500b4f26108c37af891a3d|58500cb626108c37af891b4b
d20000| 2016-12-13T09:59:02.508-0500 D TRACKING [conn3] Cmd: listDatabases, TrackingId: 58500b4f26108c37af891a3d|58500cb626108c37af891b4c
d20000| 2016-12-13T09:59:02.528-0500 D TRACKING [conn3] Cmd: serverStatus, TrackingId: 58500b4f26108c37af891a3d|58500cb626108c37af891b4d
d20001| 2016-12-13T09:59:02.549-0500 D TRACKING [conn3] Cmd: listDatabases, TrackingId: 58500b4f26108c37af891a3d|58500cb626108c37af891b4e
d20001| 2016-12-13T09:59:02.553-0500 D TRACKING [conn3] Cmd: serverStatus, TrackingId: 58500b4f26108c37af891a3d|58500cb626108c37af891b4f
s20003| 2016-12-13T09:59:03.856-0500 D NETWORK  [ReplicaSetMonitor-TaskExecutor-0] Refreshing replica set test-configRS took 4 msec
s20003| 2016-12-13T09:59:06.007-0500 D SHARDING [shard registry reload] Reloading shardRegistry
c20002| 2016-12-13T09:59:06.011-0500 D TRACKING [conn4] Cmd: find, TrackingId: 58500cba87716a124220c039|58500cba87716a124220c03a
s20003| 2016-12-13T09:59:06.008-0500 D TRACKING [shard registry reload] Cmd: NotSet, TrackingId: 58500cba87716a124220c039
s20003| 2016-12-13T09:59:06.021-0500 D SHARDING [shard registry reload] found 2 shards listed on config server(s) with lastVisibleOpTime: { ts: Timestamp 1481641139000|1, t
s20003| 2016-12-13T09:59:06.045-0500 D TRACKING [replSetDistLockPinger] Cmd: NotSet, TrackingId: 58500cba87716a124220c03b
c20002| 2016-12-13T09:59:06.047-0500 D TRACKING [conn4] Cmd: findAndModify, TrackingId: 58500cba87716a124220c03b|58500cba87716a124220c03c
s20003| 2016-12-13T09:59:07.865-0500 D TRACKING [UserCacheInvalidator] Cmd: NotSet, TrackingId: 58500cbb87716a124220c03d
c20002| 2016-12-13T09:59:07.869-0500 D TRACKING [conn4] Cmd: _getUserCacheGeneration, TrackingId: 58500cbb87716a124220c03d|58500cbb87716a124220c03e
s20003| 2016-12-13T09:59:09.494-0500 D TRACKING [Uptime reporter] Cmd: NotSet, TrackingId: 58500cbd87716a124220c03f
c20002| 2016-12-13T09:59:09.498-0500 D TRACKING [conn4] Cmd: update, TrackingId: 58500cbd87716a124220c03f|58500cbd87716a124220c040
c20002| 2016-12-13T09:59:09.518-0500 D TRACKING [conn4] Cmd: find, TrackingId: 58500cbd87716a124220c03f|58500cbd87716a124220c041
c20002| 2016-12-13T09:59:09.526-0500 D TRACKING [conn4] Cmd: find, TrackingId: 58500cbd87716a124220c03f|58500cbd87716a124220c042
c20002| 2016-12-13T09:59:09.531-0500 D TRACKING [conn4] Cmd: find, TrackingId: 58500cbd87716a124220c03f|58500cbd87716a124220c043
d20000| 2016-12-13T09:59:12.576-0500 D TRACKING [shard registry reload] Cmd: NotSet, TrackingId: 58500cc020ff32c1dd7aa20b
c20002| 2016-12-13T09:59:12.579-0500 D TRACKING [conn9] Cmd: find, TrackingId: 58500cc020ff32c1dd7aa20b|58500cc020ff32c1dd7aa20c
d20000| 2016-12-13T09:59:12.639-0500 D TRACKING [replSetDistLockPinger] Cmd: NotSet, TrackingId: 58500cc020ff32c1dd7aa20d
c20002| 2016-12-13T09:59:12.641-0500 D TRACKING [conn9] Cmd: findAndModify, TrackingId: 58500cc020ff32c1dd7aa20d|58500cc020ff32c1dd7aa20e
d20000| 2016-12-13T09:59:12.686-0500 D TRACKING [conn3] Cmd: features, TrackingId: 58500b4f26108c37af891a3d|58500cc026108c37af891b55
d20001| 2016-12-13T09:59:12.689-0500 D TRACKING [conn3] Cmd: features, TrackingId: 58500b4f26108c37af891a3d|58500cc026108c37af891b56
d20000| 2016-12-13T09:59:12.703-0500 D TRACKING [conn3] Cmd: listDatabases, TrackingId: 58500b4f26108c37af891a3d|58500cc026108c37af891b57
d20000| 2016-12-13T09:59:12.716-0500 D TRACKING [conn3] Cmd: serverStatus, TrackingId: 58500b4f26108c37af891a3d|58500cc026108c37af891b58
d20001| 2016-12-13T09:59:12.734-0500 D TRACKING [conn3] Cmd: listDatabases, TrackingId: 58500b4f26108c37af891a3d|58500cc026108c37af891b59
d20001| 2016-12-13T09:59:12.737-0500 D TRACKING [conn3] Cmd: serverStatus, TrackingId: 58500b4f26108c37af891a3d|58500cc026108c37af891b5a
d20000| 2016-12-13T09:59:12.859-0500 D TRACKING [conn3] Cmd: listDatabases, TrackingId: 58500b4f26108c37af891a3d|58500cc026108c37af891b5b
d20000| 2016-12-13T09:59:12.874-0500 D TRACKING [conn3] Cmd: serverStatus, TrackingId: 58500b4f26108c37af891a3d|58500cc026108c37af891b5c
d20001| 2016-12-13T09:59:12.890-0500 D TRACKING [conn3] Cmd: listDatabases, TrackingId: 58500b4f26108c37af891a3d|58500cc026108c37af891b5d
d20001| 2016-12-13T09:59:12.894-0500 D TRACKING [conn3] Cmd: serverStatus, TrackingId: 58500b4f26108c37af891a3d|58500cc026108c37af891b5e
d20001| 2016-12-13T09:59:14.782-0500 D TRACKING [shard registry reload] Cmd: NotSet, TrackingId: 58500cc2fa8803b4913d4306
c20002| 2016-12-13T09:59:14.785-0500 D TRACKING [conn12] Cmd: find, TrackingId: 58500cc2fa8803b4913d4306|58500cc2fa8803b4913d4307
d20001| 2016-12-13T09:59:14.873-0500 D TRACKING [replSetDistLockPinger] Cmd: NotSet, TrackingId: 58500cc2fa8803b4913d4308
c20002| 2016-12-13T09:59:14.876-0500 D TRACKING [conn12] Cmd: findAndModify, TrackingId: 58500cc2fa8803b4913d4308|58500cc2fa8803b4913d4309
s20003| 2016-12-13T09:59:19.535-0500 D TRACKING [Uptime reporter] Cmd: NotSet, TrackingId: 58500cc787716a124220c044
c20002| 2016-12-13T09:59:19.539-0500 D TRACKING [conn4] Cmd: update, TrackingId: 58500cc787716a124220c044|58500cc787716a124220c045
c20002| 2016-12-13T09:59:19.560-0500 D TRACKING [conn4] Cmd: find, TrackingId: 58500cc787716a124220c044|58500cc787716a124220c046
c20002| 2016-12-13T09:59:19.570-0500 D TRACKING [conn4] Cmd: find, TrackingId: 58500cc787716a124220c044|58500cc787716a124220c047
c20002| 2016-12-13T09:59:19.577-0500 D TRACKING [conn4] Cmd: find, TrackingId: 58500cc787716a124220c044|58500cc787716a124220c048



 Comments   
Comment by Githook User [ 26/Jan/17 ]

Author:

{u'username': u'mikety', u'name': u'Misha Tyulenev', u'email': u'misha@mongodb.com'}

Message: SERVER-27399: disable printing tracking data in integration tests
Branch: master
https://github.com/mongodb/mongo/commit/eb83a4f177daa298691becc4f26ebb306557ab19

Comment by Misha Tyulenev [ 23/Jan/17 ]

The usefulness of TRACKING is pretty self-evident from the included snapshot. It allows to track the execution of the commands, so in the case there is a failure its clear what chain of execution has caused it. For example the search for "58500b4f26108c37af891a3d" shows the commands that were executed across all the nodes on the cluster to implement it (unfortunately the included fragment does not contain the root command, but it must be in the original log). Should any of the related commands have a failure it will take no time to get to the originated command that has issued the failed one with this data.

So this is useful, especially to someone who is not familiar with all details of sharding execution.
The issue will be addressed on the basis that its too verbose. Its not a bug as it works according to the spec and do not have errors. The fix will temporarily disable it to make reassessment of what TRACKING information should be included and how it can be filtered to present a more compact view.

Generated at Thu Feb 08 04:15:04 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.