TRACKING logger is too verbose

XMLWordPrintableJSON

    • Type: Task
    • Resolution: Done
    • Priority: Major - P3
    • 3.5.3
    • Affects Version/s: 3.4.0, 3.5.1
    • Component/s: Sharding
    • None
    • Fully Compatible
    • Sharding 2017-01-02, Sharding 2017-02-13
    • 0
    • None
    • None
    • None
    • None
    • None
    • None
    • None

      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

            Assignee:
            Misha Tyulenev (Inactive)
            Reporter:
            Kaloian Manassiev
            Votes:
            0 Vote for this issue
            Watchers:
            4 Start watching this issue

              Created:
              Updated:
              Resolved: