[SERVER-50942] CallbackCanceled for ShardRegistry Created: 15/Sep/20  Updated: 19/Nov/20  Resolved: 19/Nov/20

Status: Closed
Project: Core Server
Component/s: Networking, Querying
Affects Version/s: 4.0.12
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: Andrey Larionov Assignee: Eric Sedor
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Operating System: ALL
Steps To Reproduce:

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 }

} }

Participants:

 Description   

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?



 Comments   
Comment by Eric Sedor [ 22/Sep/20 ]

andy_lar@mail.ru, would you be able to start by seek troubleshooting assistance from our community by posting on the MongoDB Developer Community Forums or on Stack Overflow with the mongodb tag?

A timeout error isn't necessarily indicative of a bug, and the SERVER project is for bugs and feature suggestions for the MongoDB server. If there is reason after troubleshooting to suspect a bug, we'd be happy to help here.

Sincerely,
Eric

Comment by Andrey Larionov [ 18/Sep/20 ]

Hello Eric,

> Are you experiencing any specific issues around the logging of this line?

Yes, application get errors/timeouts at this time. In attach fresh logs (application and mongos) from dev-stand. Time of error in application - 2020-09-17 16:25:47,2547.
Application  and mongos working on the same Windows-servers (Windows 2012 R2).
Data and config replicas working on others Linux-servers (4.1.12-124.32.1.el7uek.x86_64).

Comment by Eric Sedor [ 16/Sep/20 ]

andy_lar@mail.ru, this log line is not an issue by itself, and is even omitted in later versions, as of SERVER-37098. Are you experiencing any specific issues around the logging of this line?

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