[SERVER-15933] Repeated assertions in 2.6.5 mongod logs Created: 04/Nov/14  Updated: 07/Apr/23  Resolved: 04/Apr/15

Status: Closed
Project: Core Server
Component/s: Networking, Replication
Affects Version/s: 2.6.5, 3.0.1
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: Aleksey Brek Assignee: Scott Hernandez (Inactive)
Resolution: Incomplete Votes: 1
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Attachments: File mongod_full.log    
Issue Links:
Related
Operating System: ALL
Participants:

 Description   

We have 1 shard with replica set (3 members). Primary was crashed (maybe network problems).
Log:

2014-11-03T16:16:28.454-0800 [conn65746] SocketException handling request, closing client connection: 9001 socket exception [SEND_ERROR] server [192.168.101.251:35711]
2014-11-03T16:16:28.459-0800 [conn65836] 0x11e9b11 0x118b849 0x11703f6 0xed29bb 0xecc162 0xf3dc89 0xa0fa83 0xa1338e 0xa2939a 0xa2a7e2 0xa2c9a6 0xd5f83a 0xba1052 0xba2630 0x770d5f 0x119f93e 0x7ffb32105182 0x7ffb31409fbd
 /usr/bin/mongod(_ZN5mongo15printStackTraceERSo+0x21) [0x11e9b11]
 /usr/bin/mongod(_ZN5mongo10logContextEPKc+0x159) [0x118b849]
 /usr/bin/mongod(_ZN5mongo11msgassertedEiPKc+0xe6) [0x11703f6]
 /usr/bin/mongod(_ZN5mongo13SlaveTracking18opReplicatedEnoughENS_6OpTimeERKSs+0x8b) [0xed29bb]
 /usr/bin/mongod(_ZN5mongo18opReplicatedEnoughENS_6OpTimeERKSs+0x22) [0xecc162]
 /usr/bin/mongod(_ZN5mongo19waitForWriteConcernERKNS_19WriteConcernOptionsERKNS_6OpTimeEPNS_18WriteConcernResultE+0x209) [0xf3dc89]
 /usr/bin/mongod(_ZN5mongo18WriteBatchExecutor12executeBatchERKNS_21BatchedCommandRequestEPNS_22BatchedCommandResponseE+0xba3) [0xa0fa83]
 /usr/bin/mongod(_ZN5mongo8WriteCmd3runERKSsRNS_7BSONObjEiRSsRNS_14BSONObjBuilderEb+0x3de) [0xa1338e]
 /usr/bin/mongod(_ZN5mongo12_execCommandEPNS_7CommandERKSsRNS_7BSONObjEiRSsRNS_14BSONObjBuilderEb+0x3a) [0xa2939a]
 /usr/bin/mongod(_ZN5mongo7Command11execCommandEPS0_RNS_6ClientEiPKcRNS_7BSONObjERNS_14BSONObjBuilderEb+0x1042) [0xa2a7e2]
 /usr/bin/mongod(_ZN5mongo12_runCommandsEPKcRNS_7BSONObjERNS_11_BufBuilderINS_16TrivialAllocatorEEERNS_14BSONObjBuilderEbi+0x6c6) [0xa2c9a6]
 /usr/bin/mongod(_ZN5mongo11newRunQueryERNS_7MessageERNS_12QueryMessageERNS_5CurOpES1_+0x230a) [0xd5f83a]
 /usr/bin/mongod() [0xba1052]
 /usr/bin/mongod(_ZN5mongo16assembleResponseERNS_7MessageERNS_10DbResponseERKNS_11HostAndPortE+0x580) [0xba2630]
 /usr/bin/mongod(_ZN5mongo16MyMessageHandler7processERNS_7MessageEPNS_21AbstractMessagingPortEPNS_9LastErrorE+0x9f) [0x770d5f]
 /usr/bin/mongod(_ZN5mongo17PortMessageServer17handleIncomingMsgEPv+0x4ee) [0x119f93e]
 /lib/x86_64-linux-gnu/libpthread.so.0(+0x8182) [0x7ffb32105182]
 /lib/x86_64-linux-gnu/libc.so.6(clone+0x6d) [0x7ffb31409fbd]
2014-11-03T16:16:28.459-0800 [conn65836] command xsf-content-live.$cmd command: update { $msg: "query not recording (too large)" } ntoreturn:1 keyUpdates:0 numYields:0  reslen:187 27232ms
2014-11-03T16:16:28.459-0800 [conn65836] SocketException handling request, closing client connection: 9001 socket exception [SEND_ERROR] server [192.168.101.251:35877]
2014-11-03T16:16:29.300-0800 [rsBackgroundSync] Assertion: 16235:going to start syncing, but buffer is not empty
2014-11-03T16:16:29.314-0800 [rsBackgroundSync] 0x11e9b11 0x118b849 0x11703f6 0xe08c85 0xe0f8b5 0xe0f8ed 0x122e4a9 0x7ffb32105182 0x7ffb31409fbd
 /usr/bin/mongod(_ZN5mongo15printStackTraceERSo+0x21) [0x11e9b11]
 /usr/bin/mongod(_ZN5mongo10logContextEPKc+0x159) [0x118b849]
 /usr/bin/mongod(_ZN5mongo11msgassertedEiPKc+0xe6) [0x11703f6]
 /usr/bin/mongod(_ZN5mongo7replset14BackgroundSync5startEv+0x2a5) [0xe08c85]
 /usr/bin/mongod(_ZN5mongo7replset14BackgroundSync15_producerThreadEv+0xc5) [0xe0f8b5]
 /usr/bin/mongod(_ZN5mongo7replset14BackgroundSync14producerThreadEv+0x2d) [0xe0f8ed]
 /usr/bin/mongod() [0x122e4a9]
 /lib/x86_64-linux-gnu/libpthread.so.0(+0x8182) [0x7ffb32105182]
 /lib/x86_64-linux-gnu/libc.so.6(clone+0x6d) [0x7ffb31409fbd]
2014-11-03T16:16:29.314-0800 [rsBackgroundSync] replSet sync source problem: 16235 going to start syncing, but buffer is not empty
2014-11-03T16:16:29.314-0800 [rsBackgroundSync] Assertion: 16235:going to start syncing, but buffer is not empty
2014-11-03T16:16:29.325-0800 [rsBackgroundSync] 0x11e9b11 0x118b849 0x11703f6 0xe08c85 0xe0f8b5 0xe0f8ed 0x122e4a9 0x7ffb32105182 0x7ffb31409fbd
 /usr/bin/mongod(_ZN5mongo15printStackTraceERSo+0x21) [0x11e9b11]
 /usr/bin/mongod(_ZN5mongo10logContextEPKc+0x159) [0x118b849]
 /usr/bin/mongod(_ZN5mongo11msgassertedEiPKc+0xe6) [0x11703f6]
 /usr/bin/mongod(_ZN5mongo7replset14BackgroundSync5startEv+0x2a5) [0xe08c85]
 /usr/bin/mongod(_ZN5mongo7replset14BackgroundSync15_producerThreadEv+0xc5) [0xe0f8b5]
 /usr/bin/mongod(_ZN5mongo7replset14BackgroundSync14producerThreadEv+0x2d) [0xe0f8ed]
 /usr/bin/mongod() [0x122e4a9]
 /lib/x86_64-linux-gnu/libpthread.so.0(+0x8182) [0x7ffb32105182]
 /lib/x86_64-linux-gnu/libc.so.6(clone+0x6d) [0x7ffb31409fbd]
2014-11-03T16:16:29.325-0800 [rsBackgroundSync] Assertion: 16235:going to start syncing, but buffer is not empty
2014-11-03T16:16:29.329-0800 [rsBackgroundSync] 0x11e9b11 0x118b849 0x11703f6 0xe08c85 0xe0f8b5 0xe0f8ed 0x122e4a9 0x7ffb32105182 0x7ffb31409fbd
 /usr/bin/mongod(_ZN5mongo15printStackTraceERSo+0x21) [0x11e9b11]
 /usr/bin/mongod(_ZN5mongo10logContextEPKc+0x159) [0x118b849]
 /usr/bin/mongod(_ZN5mongo11msgassertedEiPKc+0xe6) [0x11703f6]
 /usr/bin/mongod(_ZN5mongo7replset14BackgroundSync5startEv+0x2a5) [0xe08c85]
 /usr/bin/mongod(_ZN5mongo7replset14BackgroundSync15_producerThreadEv+0xc5) [0xe0f8b5]
 /usr/bin/mongod(_ZN5mongo7replset14BackgroundSync14producerThreadEv+0x2d) [0xe0f8ed]
 /usr/bin/mongod() [0x122e4a9]
 /lib/x86_64-linux-gnu/libpthread.so.0(+0x8182) [0x7ffb32105182]
 /lib/x86_64-linux-gnu/libc.so.6(clone+0x6d) [0x7ffb31409fbd]
2014-11-03T16:16:29.329-0800 [rsBackgroundSync] Assertion: 16235:going to start syncing, but buffer is not empty
2014-11-03T16:16:29.331-0800 [rsBackgroundSync] 0x11e9b11 0x118b849 0x11703f6 0xe08c85 0xe0f8b5 0xe0f8ed 0x122e4a9 0x7ffb32105182 0x7ffb31409fbd
 /usr/bin/mongod(_ZN5mongo15printStackTraceERSo+0x21) [0x11e9b11]
 /usr/bin/mongod(_ZN5mongo10logContextEPKc+0x159) [0x118b849]
 /usr/bin/mongod(_ZN5mongo11msgassertedEiPKc+0xe6) [0x11703f6]
 /usr/bin/mongod(_ZN5mongo7replset14BackgroundSync5startEv+0x2a5) [0xe08c85]
 /usr/bin/mongod(_ZN5mongo7replset14BackgroundSync15_producerThreadEv+0xc5) [0xe0f8b5]
 /usr/bin/mongod(_ZN5mongo7replset14BackgroundSync14producerThreadEv+0x2d) [0xe0f8ed]
 /usr/bin/mongod() [0x122e4a9]
 /lib/x86_64-linux-gnu/libpthread.so.0(+0x8182) [0x7ffb32105182]
 /lib/x86_64-linux-gnu/libc.so.6(clone+0x6d) [0x7ffb31409fbd]



 Comments   
Comment by Ramon Fernandez Marina [ 23/Jan/15 ]

If this is still an issue with 2.6.7, is it possible to obtain full logs from the mongod processes involved? Unfortunately the log snippets above do not provide enough information.

Thanks,
Ramón.

Comment by Jason Ford [ 19/Nov/14 ]

We have just experienced the same issue immediately after upgrading to 2.6.5. After we failed back over to a 2.6.3 node, the instance recovered just fine. Immediately after failover, as the old primary was closing connections, are logs are full of the following message:

2014-11-19T14:14:59.034-0500 [conn1182] 0x11e9b11 0x118b849 0x11703f6 0xecc065 0xf3dc01 0xa0fa83 0xa1338e 0xa2939a 0xa2a7e2 0xa2c9a6 0xd5f83a 0xba1052 0xba2630 0x770d5f 0x119f93e 0x7f05281d49d1 0x7f05275799dd
/usr/local/mongo/mongodb-linux-x86_64-2.6.5/bin/mongod(_ZN5mongo15printStackTraceERSo+0x21) [0x11e9b11]
/usr/local/mongo/mongodb-linux-x86_64-2.6.5/bin/mongod(_ZN5mongo10logContextEPKc+0x159) [0x118b849]
/usr/local/mongo/mongodb-linux-x86_64-2.6.5/bin/mongod(_ZN5mongo11msgassertedEiPKc+0xe6) [0x11703f6]
/usr/local/mongo/mongodb-linux-x86_64-2.6.5/bin/mongod(_ZN5mongo18opReplicatedEnoughENS_6OpTimeEi+0xe5) [0xecc065]
/usr/local/mongo/mongodb-linux-x86_64-2.6.5/bin/mongod(_ZN5mongo19waitForWriteConcernERKNS_19WriteConcernOptionsERKNS_6OpTimeEPNS_18WriteConcernResultE+0x181) [0xf3dc01]
/usr/local/mongo/mongodb-linux-x86_64-2.6.5/bin/mongod(_ZN5mongo18WriteBatchExecutor12executeBatchERKNS_21BatchedCommandRequestEPNS_22BatchedCommandResponseE+0xba3) [0xa0fa83]
/usr/local/mongo/mongodb-linux-x86_64-2.6.5/bin/mongod(_ZN5mongo8WriteCmd3runERKSsRNS_7BSONObjEiRSsRNS_14BSONObjBuilderEb+0x3de) [0xa1338e]
/usr/local/mongo/mongodb-linux-x86_64-2.6.5/bin/mongod(_ZN5mongo12_execCommandEPNS_7CommandERKSsRNS_7BSONObjEiRSsRNS_14BSONObjBuilderEb+0x3a) [0xa2939a]
/usr/local/mongo/mongodb-linux-x86_64-2.6.5/bin/mongod(_ZN5mongo7Command11execCommandEPS0_RNS_6ClientEiPKcRNS_7BSONObjERNS_14BSONObjBuilderEb+0x1042) [0xa2a7e2]
/usr/local/mongo/mongodb-linux-x86_64-2.6.5/bin/mongod(_ZN5mongo12_runCommandsEPKcRNS_7BSONObjERNS_11_BufBuilderINS_16TrivialAllocatorEEERNS_14BSONObjBuilderEbi+0x6c6) [0xa2c9a6]
/usr/local/mongo/mongodb-linux-x86_64-2.6.5/bin/mongod(ZN5mongo11newRunQueryERNS_7MessageERNS_12QueryMessageERNS_5CurOpES1+0x230a) [0xd5f83a]
/usr/local/mongo/mongodb-linux-x86_64-2.6.5/bin/mongod() [0xba1052]
/usr/local/mongo/mongodb-linux-x86_64-2.6.5/bin/mongod(_ZN5mongo16assembleResponseERNS_7MessageERNS_10DbResponseERKNS_11HostAndPortE+0x580) [0xba2630]
/usr/local/mongo/mongodb-linux-x86_64-2.6.5/bin/mongod(_ZN5mongo16MyMessageHandler7processERNS_7MessageEPNS_21AbstractMessagingPortEPNS_9LastErrorE+0x9f) [0x770d5f]
/usr/local/mongo/mongodb-linux-x86_64-2.6.5/bin/mongod(_ZN5mongo17PortMessageServer17handleIncomingMsgEPv+0x4ee) [0x119f93e]
/lib64/libpthread.so.0(+0x79d1) [0x7f05281d49d1]
/lib64/libc.so.6(clone+0x6d) [0x7f05275799dd]

Comment by Ramon Fernandez Marina [ 05/Nov/14 ]

zlosnijdani, as pointed out by Matt the mongod processes do not appear to crash, they're just complaining about a problem – can you please check whether the mongod processes are still running? Have you tried re-starting the mongod process to see if replication is able to proceed?

Generated at Thu Feb 08 03:39:27 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.