Uploaded image for project: 'Core Server'
  1. Core Server
  2. SERVER-27399

TRACKING logger is too verbose

    XMLWordPrintable

    Details

    • Type: Task
    • Status: Closed
    • Priority: Major - P3
    • Resolution: Fixed
    • Affects Version/s: 3.4.0, 3.5.1
    • Fix Version/s: 3.5.3
    • Component/s: Sharding
    • Labels:
      None
    • Backwards Compatibility:
      Fully Compatible
    • Sprint:
      Sharding 2017-01-02, Sharding 2017-02-13
    • 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
      

        Attachments

          Activity

            People

            Assignee:
            misha.tyulenev Misha Tyulenev
            Reporter:
            kaloian.manassiev Kaloian Manassiev
            Participants:
            Votes:
            0 Vote for this issue
            Watchers:
            4 Start watching this issue

              Dates

              Created:
              Updated:
              Resolved: