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

CallbackCanceled for ShardRegistry

XMLWordPrintableJSON

    • Type: Icon: Bug Bug
    • Resolution: Done
    • Priority: Icon: Major - P3 Major - P3
    • None
    • Affects Version/s: 4.0.12
    • Component/s: Networking, Querying
    • Labels:
      None
    • ALL
    • Hide

      2020-09-07T05:04:07.366+0300 I COMMAND  [conn17] command admin.$cmd command: isMaster { isMaster: 1, $db: "admin", $readPreference:

      { mode: "primaryPreferred" }

      } numYields:0 reslen:356 protocol:op_msg 0ms

      2020-09-07T05:04:07.366+0300 D SHARDING [conn17] Command begin db: admin msg id: 69856
      2020-09-07T05:04:07.366+0300 D SHARDING [conn17] Command end db: admin msg id: 69856
      2020-09-07T05:04:07.366+0300 I COMMAND  [conn17] command admin.$cmd command: buildInfo { buildInfo: 1, $db: "admin", $readPreference:

      { mode: "primaryPreferred" }

      } numYields:0 reslen:1117 protocol:op_msg 0ms
      2020-09-07T05:04:08.127+0300 D TRACKING [UserCacheInvalidator] Cmd: NotSet, TrackingId: 5f559518c9a42f286841b901
      2020-09-07T05:04:08.127+0300 D EXECUTOR [UserCacheInvalidator] Scheduling remote command request: RemoteCommand 217104 – target:10.97.154.17:27019 db:admin expDate:2020-09-07T05:04:38.127+0300 cmd:{ _getUserCacheGeneration: 1, maxTimeMS: 30000 }
      2020-09-07T05:04:08.127+0300 D ASIO     [UserCacheInvalidator] startCommand: RemoteCommand 217104 – target:10.97.154.17:27019 db:admin expDate:2020-09-07T05:04:38.127+0300 cmd:{ _getUserCacheGeneration: 1, maxTimeMS: 30000 }
      2020-09-07T05:04:08.128+0300 D NETWORK  [ShardRegistry] Compressing message with snappy
      2020-09-07T05:04:08.128+0300 D NETWORK  [ShardRegistry] Timer received error: CallbackCanceled: Callback was canceled
      2020-09-07T05:04:08.128+0300 D NETWORK  [ShardRegistry] Timer received error: CallbackCanceled: Callback was canceled
      2020-09-07T05:04:08.128+0300 D NETWORK  [ShardRegistry] Timer received error: CallbackCanceled: Callback was canceled
      2020-09-07T05:04:08.128+0300 D NETWORK  [ShardRegistry] Decompressing message with snappy
      2020-09-07T05:04:08.128+0300 D ASIO     [ShardRegistry] Request 217104 finished with response: { cacheGeneration: ObjectId('5f4625d7c1984c8aa2b03492'), ok: 1.0, operationTime: Timestamp(1599444247, 1), $replData: { term: 20, lastOpCommitted:

      { ts: Timestamp(1599444247, 1), t: 20 }

      , lastOpVisible: { ts: Timestamp(1599444247, 1), t: 20 }, configVersion: 1, replicaSetId: ObjectId('5da5ddd6eefff9aba165cd92'), primaryIndex: 1, syncSourceIndex: -1 }, $gleStats: { lastOpTime:

      { ts: Timestamp(1599444237, 1), t: 20 }

      , electionId: ObjectId('7fffffff0000000000000014') }, lastCommittedOpTime: Timestamp(1599444247, 1), $clusterTime: { clusterTime: Timestamp(1599444247, 1), signature:

      { hash: BinData(0, 0000000000000000000000000000000000000000), keyId: 0 }

      } }

      Show
      2020-09-07T05:04:07.366+0300 I COMMAND   [conn17] command admin.$cmd command: isMaster { isMaster: 1, $db: "admin", $readPreference: { mode: "primaryPreferred" } } numYields:0 reslen:356 protocol:op_msg 0ms 2020-09-07T05:04:07.366+0300 D SHARDING [conn17] Command begin db: admin msg id: 69856 2020-09-07T05:04:07.366+0300 D SHARDING [conn17] Command end db: admin msg id: 69856 2020-09-07T05:04:07.366+0300 I COMMAND   [conn17] command admin.$cmd command: buildInfo { buildInfo: 1, $db: "admin", $readPreference: { mode: "primaryPreferred" } } numYields:0 reslen:1117 protocol:op_msg 0ms 2020-09-07T05:04:08.127+0300 D TRACKING [UserCacheInvalidator] Cmd: NotSet, TrackingId: 5f559518c9a42f286841b901 2020-09-07T05:04:08.127+0300 D EXECUTOR [UserCacheInvalidator] Scheduling remote command request: RemoteCommand 217104 – target:10.97.154.17:27019 db:admin expDate:2020-09-07T05:04:38.127+0300 cmd:{ _getUserCacheGeneration: 1, maxTimeMS: 30000 } 2020-09-07T05:04:08.127+0300 D ASIO     [UserCacheInvalidator] startCommand: RemoteCommand 217104 – target:10.97.154.17:27019 db:admin expDate:2020-09-07T05:04:38.127+0300 cmd:{ _getUserCacheGeneration: 1, maxTimeMS: 30000 } 2020-09-07T05:04:08.128+0300 D NETWORK   [ShardRegistry] Compressing message with snappy 2020-09-07T05:04:08.128+0300 D NETWORK   [ShardRegistry] Timer received error: CallbackCanceled: Callback was canceled 2020-09-07T05:04:08.128+0300 D NETWORK   [ShardRegistry] Timer received error: CallbackCanceled: Callback was canceled 2020-09-07T05:04:08.128+0300 D NETWORK   [ShardRegistry] Timer received error: CallbackCanceled: Callback was canceled 2020-09-07T05:04:08.128+0300 D NETWORK   [ShardRegistry] Decompressing message with snappy 2020-09-07T05:04:08.128+0300 D ASIO     [ShardRegistry] Request 217104 finished with response: { cacheGeneration: ObjectId('5f4625d7c1984c8aa2b03492'), ok: 1.0, operationTime: Timestamp(1599444247, 1), $replData: { term: 20, lastOpCommitted: { ts: Timestamp(1599444247, 1), t: 20 } , lastOpVisible: { ts: Timestamp(1599444247, 1), t: 20 }, configVersion: 1, replicaSetId: ObjectId('5da5ddd6eefff9aba165cd92'), primaryIndex: 1, syncSourceIndex: -1 }, $gleStats: { lastOpTime: { ts: Timestamp(1599444237, 1), t: 20 } , electionId: ObjectId('7fffffff0000000000000014') }, lastCommittedOpTime: Timestamp(1599444247, 1), $clusterTime: { clusterTime: Timestamp(1599444247, 1), signature: { hash: BinData(0, 0000000000000000000000000000000000000000), keyId: 0 } } }

      Hello, in our MongoDB Cluster (3 mongos, 3 data-replica, 3 config-replica)
      sometime we catch errors like this (with logging level 5)
      2020-09-07T05:04:08.128+0300 D NETWORK [ShardRegistry] Timer received error: CallbackCanceled: Callback was canceled

      What's wrong, what can be a reason of this timeouts?

            Assignee:
            eric.sedor@mongodb.com Eric Sedor
            Reporter:
            andy_lar@mail.ru Andrey Larionov
            Votes:
            0 Vote for this issue
            Watchers:
            3 Start watching this issue

              Created:
              Updated:
              Resolved: