[SERVER-41097] Segfault in the collstats command execution on mongos Created: 10/May/19  Updated: 05/Dec/22  Resolved: 24/Feb/22

Status: Closed
Project: Core Server
Component/s: Sharding
Affects Version/s: None
Fix Version/s: Needs Further Definition

Type: Task Priority: Major - P3
Reporter: Misha Tyulenev Assignee: Backlog - Service Architecture
Resolution: Won't Do Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Depends
Assigned Teams:
Service Arch
Participants:
Linked BF Score: 17

 Description   

Apparent memory corruption in the command execution on mongos.

[ShardedClusterFixture:job0:configsvr:node0] 2019-04-03T05:58:07.630+0000 I REPL     [replexec-12] transition to PRIMARY from SECONDARY
[ShardedClusterFixture:job0:configsvr:node0] 2019-04-03T05:58:08.793+0000 I REPL     [rsSync-0] transition to primary complete; database writes are now permitted
...
[ShardedClusterFixture:job0:configsvr:node2] 2019-04-03T05:58:08.822+0000 I CONTROL  [signalProcessingThread] got signal 15 (Terminated), will terminate after current cmd ends
[ShardedClusterFixture:job0:configsvr:node2] 2019-04-03T05:58:08.864+0000 I CONTROL  [signalProcessingThread] shutting down with code:0
[ShardedClusterFixture:job0:configsvr:node2] Successfully stopped the mongod on port 20002.
...
[ShardedClusterFixture:job0:configsvr:node1] 2019-04-03T05:58:08.873+0000 I CONTROL  [signalProcessingThread] got signal 15 (Terminated), will terminate after current cmd ends
[ShardedClusterFixture:job0:configsvr:node1] 2019-04-03T05:58:10.009+0000 I CONTROL  [signalProcessingThread] shutting down with code:0
[ShardedClusterFixture:job0:configsvr:node1] Successfully stopped the mongod on port 20001.
...
[ShardedClusterFixture:job0:configsvr:node0] 2019-04-03T05:58:10.017+0000 I CONTROL  [signalProcessingThread] got signal 15 (Terminated), will terminate after current cmd ends
[ShardedClusterFixture:job0:configsvr:node0] 2019-04-03T05:58:10.017+0000 I COMMAND  [conn58] Timed out obtaining lock while trying to gather storage statistics for a slow operation
[ShardedClusterFixture:job0:configsvr:node0] 2019-04-03T05:58:10.017+0000 I COMMAND  [conn58] command config.lockpings command: findAndModify { findAndModify: "lockpings", query: { _id: "ip-10-122-29-79:20008:1554270806:-6701597684633815355" }, update: { $set: { ping: new Date(1554271087853) } }, upsert: true, writeConcern: { w: "majority", wtimeout: 15000 }, maxTimeMS: 30000, $replData: 1, $clusterTime: { clusterTime: Timestamp(1554271088, 1), signature: { hash: BinData(0, 41AC32E76A9C92E5A8B056F53B1AE810014BAA17), keyId: 6675542225062985757 } }, $configServerState: { opTime: { ts: Timestamp(1554271086, 12), t: 27 } }, $db: "config" } planSummary: IDHACK keysExamined:1 docsExamined:1 nMatched:1 nModified:1 keysInserted:1 keysDeleted:1 numYields:0 reslen:732 locks:{ Global: { acquireCount: { r: 1, w: 1 } }, Database: { acquireCount: { w: 1 } }, Collection: { acquireCount: { w: 1 } } } protocol:op_msg 1159ms
[ShardedClusterFixture:job0:configsvr:node0] 2019-04-03T05:58:10.017+0000 I COMMAND  [conn42] Timed out obtaining lock while trying to gather storage statistics for a slow operation
[ShardedClusterFixture:job0:configsvr:node0] 2019-04-03T05:58:10.017+0000 I COMMAND  [conn42] command config.lockpings command: findAndModify { findAndModify: "lockpings", query: { _id: "ip-10-122-29-79:20004:1554270806:765596494582915214" }, update: { $set: { ping: new Date(1554271087839) } }, upsert: true, writeConcern: { w: "majority", wtimeout: 15000 }, maxTimeMS: 30000, $replData: 1, $clusterTime: { clusterTime: Timestamp(1554271088, 1), signature: { hash: BinData(0, 41AC32E76A9C92E5A8B056F53B1AE810014BAA17), keyId: 6675542225062985757 } }, $configServerState: { opTime: { ts: Timestamp(1554271086, 12), t: 27 } }, $db: "config" } planSummary: IDHACK keysExamined:1 docsExamined:1 nMatched:1 nModified:1 keysInserted:1 keysDeleted:1 numYields:0 reslen:730 locks:{ Global: { acquireCount: { r: 1, w: 1 } }, Database: { acquireCount: { w: 1 } }, Collection: { acquireCount: { w: 1 } } } protocol:op_msg 1174ms
[ShardedClusterFixture:job0:configsvr:node0] 2019-04-03T05:58:10.017+0000 I COMMAND  [conn390] Timed out obtaining lock while trying to gather storage statistics for a slow operation
[ShardedClusterFixture:job0:configsvr:node0] 2019-04-03T05:58:10.017+0000 I COMMAND  [conn390] command config.$cmd command: update { update: "mongos", bypassDocumentValidation: false, ordered: true, updates: [ { q: { _id: "ip-10-122-29-79:20009" }, u: { $set: { _id: "ip-10-122-29-79:20009", ping: new Date(1554271088643), up: 282, waiting: true, mongoVersion: "4.0.8-18-g57edce7396", advisoryHostFQDNs: [ "ip-10-122-29-79.ec2.internal" ] } }, multi: false, upsert: true } ], writeConcern: { w: "majority", wtimeout: 60000 }, allowImplicitCollectionCreation: true, maxTimeMS: 30000, $replData: 1, $clusterTime: { clusterTime: Timestamp(1554271088, 3), signature: { hash: BinData(0, 41AC32E76A9C92E5A8B056F53B1AE810014BAA17), keyId: 6675542225062985757 } }, $configServerState: { opTime: { ts: Timestamp(1554271088, 3), t: 28 } }, $db: "config" } numYields:0 reslen:678 locks:{ Global: { acquireCount: { r: 1, w: 1 } }, Database: { acquireCount: { w: 1 } }, Collection: { acquireCount: { w: 1 } } } protocol:op_msg 871ms
[ShardedClusterFixture:job0:configsvr:node0] 2019-04-03T05:58:10.017+0000 I COMMAND  [conn45] Timed out obtaining lock while trying to gather storage statistics for a slow operation
[ShardedClusterFixture:job0:configsvr:node0] 2019-04-03T05:58:10.017+0000 I COMMAND  [conn45] command config.lockpings command: findAndModify { findAndModify: "lockpings", query: { _id: "ip-10-122-29-79:20005:1554270806:-4758601724122253121" }, update: { $set: { ping: new Date(1554271087835) } }, upsert: true, writeConcern: { w: "majority", wtimeout: 15000 }, maxTimeMS: 30000, $replData: 1, $clusterTime: { clusterTime: Timestamp(1554271087, 1), signature: { hash: BinData(0, B31C77A13DF90FED05319D6D16D0EB70B6E17179), keyId: 6675542225062985757 } }, $configServerState: { opTime: { ts: Timestamp(1554271086, 12), t: 27 } }, $db: "config" } planSummary: IDHACK keysExamined:1 docsExamined:1 nMatched:1 nModified:1 keysInserted:1 keysDeleted:1 numYields:0 reslen:732 locks:{ Global: { acquireCount: { r: 1, w: 1 } }, Database: { acquireCount: { w: 1 } }, Collection: { acquireCount: { w: 1 } } } protocol:op_msg 1177ms
[ShardedClusterFixture:job0:configsvr:node0] 2019-04-03T05:58:10.017+0000 I COMMAND  [conn59] Timed out obtaining lock while trying to gather storage statistics for a slow operation
[ShardedClusterFixture:job0:configsvr:node0] 2019-04-03T05:58:10.017+0000 I COMMAND  [conn59] command config.lockpings command: findAndModify { findAndModify: "lockpings", query: { _id: "ip-10-122-29-79:20007:1554270806:2082168933714807912" }, update: { $set: { ping: new Date(1554271087831) } }, upsert: true, writeConcern: { w: "majority", wtimeout: 15000 }, maxTimeMS: 30000, $replData: 1, $clusterTime: { clusterTime: Timestamp(1554271087, 1), signature: { hash: BinData(0, B31C77A13DF90FED05319D6D16D0EB70B6E17179), keyId: 6675542225062985757 } }, $configServerState: { opTime: { ts: Timestamp(1554271086, 12), t: 27 } }, $db: "config" } planSummary: IDHACK keysExamined:1 docsExamined:1 nMatched:1 nModified:1 keysInserted:1 keysDeleted:1 numYields:0 reslen:731 locks:{ Global: { acquireCount: { r: 1, w: 1 } }, Database: { acquireCount: { w: 1 } }, Collection: { acquireCount: { w: 1 } } } protocol:op_msg 1181ms
[ShardedClusterFixture:job0:configsvr:node0] 2019-04-03T05:58:10.017+0000 I COMMAND  [conn60] Timed out obtaining lock while trying to gather storage statistics for a slow operation
[ShardedClusterFixture:job0:configsvr:node0] 2019-04-03T05:58:10.018+0000 I COMMAND  [conn60] command config.lockpings command: findAndModify { findAndModify: "lockpings", query: { _id: "ip-10-122-29-79:20006:1554270806:-7144896684610494338" }, update: { $set: { ping: new Date(1554271087844) } }, upsert: true, writeConcern: { w: "majority", wtimeout: 15000 }, maxTimeMS: 30000, $replData: 1, $clusterTime: { clusterTime: Timestamp(1554271087, 1), signature: { hash: BinData(0, B31C77A13DF90FED05319D6D16D0EB70B6E17179), keyId: 6675542225062985757 } }, $configServerState: { opTime: { ts: Timestamp(1554271086, 12), t: 27 } }, $db: "config" } planSummary: IDHACK keysExamined:1 docsExamined:1 nMatched:1 nModified:1 keysInserted:1 keysDeleted:1 numYields:0 reslen:732 locks:{ Global: { acquireCount: { r: 1, w: 1 } }, Database: { acquireCount: { w: 1 } }, Collection: { acquireCount: { w: 1 } } } protocol:op_msg 1169ms
[ShardedClusterFixture:job0:configsvr:node0] 2019-04-03T05:58:10.018+0000 I COMMAND  [conn46] Timed out obtaining lock while trying to gather storage statistics for a slow operation
[ShardedClusterFixture:job0:configsvr:node0] 2019-04-03T05:58:10.018+0000 I COMMAND  [conn46] command config.lockpings command: findAndModify { findAndModify: "lockpings", query: { _id: "ip-10-122-29-79:20003:1554270806:4471450513314286609" }, update: { $set: { ping: new Date(1554271087817) } }, upsert: true, writeConcern: { w: "majority", wtimeout: 15000 }, maxTimeMS: 30000, $replData: 1, $clusterTime: { clusterTime: Timestamp(1554271088, 1), signature: { hash: BinData(0, 41AC32E76A9C92E5A8B056F53B1AE810014BAA17), keyId: 6675542225062985757 } }, $configServerState: { opTime: { ts: Timestamp(1554271086, 12), t: 27 } }, $db: "config" } planSummary: IDHACK keysExamined:1 docsExamined:1 nMatched:1 nModified:1 keysInserted:1 keysDeleted:1 numYields:0 reslen:731 locks:{ Global: { acquireCount: { r: 1, w: 1 } }, Database: { acquireCount: { w: 1 } }, Collection: { acquireCount: { w: 1 } } } protocol:op_msg 1196ms
[ShardedClusterFixture:job0:configsvr:node0] 2019-04-03T05:58:10.927+0000 W SHARDING [replSetDistLockPinger] Failed to unlock lock with ts: 5ca44a887b55d5eac92903cd :: caused by :: NotMaster: Not primary while running findAndModify command on collection config.locks
[ShardedClusterFixture:job0:configsvr:node0] 2019-04-03T05:58:10.928+0000 W SHARDING [replSetDistLockPinger] Failed to unlock lock with ts: 5ca44a887b55d5eac92903c8 :: caused by :: NotMaster: Not primary while running findAndModify command on collection config.locks
[ShardedClusterFixture:job0:configsvr:node0] 2019-04-03T05:58:10.928+0000 W SHARDING [replSetDistLockPinger] Failed to unlock lock with ts: 5ca44a9d7b55d5eac92915e0 :: caused by :: NotMaster: Not primary while running findAndModify command on collection config.locks
[ShardedClusterFixture:job0:configsvr:node0] 2019-04-03T05:58:10.928+0000 W SHARDING [replSetDistLockPinger] Failed to unlock lock with ts: 5ca44a9d7b55d5eac92915da :: caused by :: NotMaster: Not primary while running findAndModify command on collection config.locks



 Comments   
Comment by Lauren Lewis (Inactive) [ 24/Feb/22 ]

We haven’t heard back from you for at least one calendar year, so this issue is being closed. If this is still an issue for you, please provide additional information and we will reopen the ticket.

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