[SERVER-10583] index_killop.js segfault and/or assertion failure on Linux 64 debug Created: 20/Aug/13  Updated: 11/Jul/16  Resolved: 22/Aug/13

Status: Closed
Project: Core Server
Component/s: Testing Infrastructure
Affects Version/s: None
Fix Version/s: 2.5.2

Type: Bug Priority: Critical - P2
Reporter: Matt Kangas Assignee: hari.khalsa@10gen.com
Resolution: Done Votes: 0
Labels: buildbot
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Operating System: ALL
Participants:

 Description   

Drew, I don't know if both of these are yours, but one of them is in your wheelhouse.

http://mci.10gen.com/ui/task/mongodb_mongo_master_linux_64_duroff_07c221086ff5c20d4d62ba69837d90404459c335_13_08_20_18_54_06_slow_nightly_tests_linux_64
http://buildlogs.mongodb.org/mci_0.9_linux_64_duroff/builds/565/test/slow_nightly_tests_0/index_killop.js

2013-08-20T20:59:39.108+0000 [conn39] info DFM::findAll(): extent 0:c69000 was empty, skipping ahead. ns:test.push2
2013-08-20T20:59:39.148+0000 [conn39] update test.push2 update: { $push: { a: ",,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,..." } } nscanned:1 nmoved:1 nupdated:1 keyUpdates:0 locks(micros) w:40134 40ms
2013-08-20T20:59:39.191+0000 [conn39] update test.push2 update: { $push: { a: ",,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,..." } } nscanned:1 nmoved:1 nupdated:1 keyUpdates:0 locks(micros) w:41814 41ms
2013-08-20T20:59:39.235+0000 [conn39] update test.push2 update: { $push: { a: ",,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,..." } } nscanned:1 nmoved:1 nupdated:1 keyUpdates:0 locks(micros) w:43207 43ms
2013-08-20T20:59:39.281+0000 [conn39] update test.push2 update: { $push: { a: ",,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,..." } } nscanned:1 nmoved:1 nupdated:1 keyUpdates:0 locks(micros) w:45073 45ms
2013-08-20T20:59:39.309+0000 [conn39] Assertion: 10334:BSONObj size: 16800187 (0x10059BB) is invalid. Size must be between 0 and 16793600(16MB) First element: 0: ",,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,..."
2013-08-20T20:59:39.315+0000 [conn39] test.push2 0xcde3c3 0xcbeba5 0xca8781 0xca882c 0x76d9b6 0x76e2b0 0x76ce5d 0x76d8f8 0x78cbb1 0x789bfe 0x789d4c 0xa33f8c 0xa4cfaf 0xa48cfc 0x9d179f 0x9d6f0b 0x76ba12 0xccdff7 0x7f15c0118c6b 0x7f15bf4be5ed 
 ./mongod(_ZN5mongo15printStackTraceERSo+0x23) [0xcde3c3]
 ./mongod(_ZN5mongo10logContextEPKc+0x245) [0xcbeba5]
 ./mongod(_ZN5mongo11msgassertedEiPKc+0x91) [0xca8781]
 ./mongod() [0xca882c]
 ./mongod(_ZNK5mongo7BSONObj14_assertInvalidEv+0x276) [0x76d9b6]
 ./mongod(_ZNK5mongo11BSONElement14embeddedObjectEv+0x60) [0x76e2b0]
 ./mongod(_ZNK5mongo11BSONElement8toStringERNS_17StringBuilderImplINS_16TrivialAllocatorEEEbbi+0x5dd) [0x76ce5d]
 ./mongod(_ZNK5mongo7BSONObj14_assertInvalidEv+0x1b8) [0x76d8f8]
 ./mongod(_ZN5mongo11mutablebson8Document4Impl17insertLeafElementEi+0x161) [0x78cbb1]
 ./mongod(_ZN5mongo11mutablebson8Document11makeElementENS0_12ConstElementEPKNS_10StringDataE+0x4e) [0x789bfe]
 ./mongod(_ZN5mongo11mutablebson8Document27makeElementWithNewFieldNameERKNS_10StringDataENS0_12ConstElementE+0x1c) [0x789d4c]
 ./mongod(_ZNK5mongo12ModifierPush3logEPNS_10LogBuilderE+0x6c) [0xa33f8c]
 ./mongod(_ZN5mongo12UpdateDriver6updateERKNS_10StringDataEPNS_11mutablebson8DocumentEPNS_7BSONObjE+0x2cf) [0xa4cfaf]
 ./mongod(_ZN5mongo6updateERKNS_13UpdateRequestEPNS_7OpDebugEPNS_12UpdateDriverE+0x94c) [0xa48cfc]
 ./mongod(_ZN5mongo14receivedUpdateERNS_7MessageERNS_5CurOpE+0x6bf) [0x9d179f]
 ./mongod(_ZN5mongo16assembleResponseERNS_7MessageERNS_10DbResponseERKNS_11HostAndPortE+0x197b) [0x9d6f0b]
 ./mongod(_ZN5mongo16MyMessageHandler7processERNS_7MessageEPNS_21AbstractMessagingPortEPNS_9LastErrorE+0x92) [0x76ba12]
 ./mongod(_ZN5mongo17PortMessageServer17handleIncomingMsgEPv+0x427) [0xccdff7]
 /lib64/libpthread.so.0(+0x7c6b) [0x7f15c0118c6b]
 /lib64/libc.so.6(clone+0x6d) [0x7f15bf4be5ed]
2013-08-20T20:59:39.315+0000 [conn39] Assertion: 10334:BSONObj size: 16800195 (0x10059C3) is invalid. Size must be between 0 and 16793600(16MB)
2013-08-20T20:59:39.321+0000 [conn39] test.push2 0xcde3c3 0xcbeba5 0xca8781 0xca882c 0x76d9b6 0x78cbb1 0x789bfe 0x789d4c 0xa33f8c 0xa4cfaf 0xa48cfc 0x9d179f 0x9d6f0b 0x76ba12 0xccdff7 0x7f15c0118c6b 0x7f15bf4be5ed 
 ./mongod(_ZN5mongo15printStackTraceERSo+0x23) [0xcde3c3]
 ./mongod(_ZN5mongo10logContextEPKc+0x245) [0xcbeba5]
 ./mongod(_ZN5mongo11msgassertedEiPKc+0x91) [0xca8781]
 ./mongod() [0xca882c]
 ./mongod(_ZNK5mongo7BSONObj14_assertInvalidEv+0x276) [0x76d9b6]
 ./mongod(_ZN5mongo11mutablebson8Document4Impl17insertLeafElementEi+0x161) [0x78cbb1]
 ./mongod(_ZN5mongo11mutablebson8Document11makeElementENS0_12ConstElementEPKNS_10StringDataE+0x4e) [0x789bfe]
 ./mongod(_ZN5mongo11mutablebson8Document27makeElementWithNewFieldNameERKNS_10StringDataENS0_12ConstElementE+0x1c) [0x789d4c]
 ./mongod(_ZNK5mongo12ModifierPush3logEPNS_10LogBuilderE+0x6c) [0xa33f8c]
 ./mongod(_ZN5mongo12UpdateDriver6updateERKNS_10StringDataEPNS_11mutablebson8DocumentEPNS_7BSONObjE+0x2cf) [0xa4cfaf]
 ./mongod(_ZN5mongo6updateERKNS_13UpdateRequestEPNS_7OpDebugEPNS_12UpdateDriverE+0x94c) [0xa48cfc]
 ./mongod(_ZN5mongo14receivedUpdateERNS_7MessageERNS_5CurOpE+0x6bf) [0x9d179f]
 ./mongod(_ZN5mongo16assembleResponseERNS_7MessageERNS_10DbResponseERKNS_11HostAndPortE+0x197b) [0x9d6f0b]
 ./mongod(_ZN5mongo16MyMessageHandler7processERNS_7MessageEPNS_21AbstractMessagingPortEPNS_9LastErrorE+0x92) [0x76ba12]
 ./mongod(_ZN5mongo17PortMessageServer17handleIncomingMsgEPv+0x427) [0xccdff7]
 /lib64/libpthread.so.0(+0x7c6b) [0x7f15c0118c6b]
 /lib64/libc.so.6(clone+0x6d) [0x7f15bf4be5ed]

I also saw this fail on MCI with no useful output:

http://buildlogs.mongodb.org/mci_0.9_linux_64/builds/570/test/slow_nightly_tests_0/index_killop.js

MongoDB shell version: 2.5.2-pre-
connecting to: 127.0.0.1:27999/test
MONGODB-CR
2013-08-20T20:09:06.924+0000 DBClientCursor::init call() failed
2013-08-20T20:09:06.924+0000 Error: error doing query: failed at src/mongo/shell/query.js:81
failed to load: /data/mci/git@github.commongodb/mongo.git/master/jstests/slowNightly/index_killop.js

So I tried to repro on Linux 64 debug and got... a segfault instead.

 *******************************************
         Test : index_killop.js ...
      Command : /home/kangas/workspace/mongo/mongo --port 27999 --authenticationMechanism MONGODB-CR /home/kangas/workspace/mongo/jstests/slowNightly/index_killop.js --eval TestData = new Object();TestData.testPath = "/home/kangas/workspace/mongo/jstests/slowNightly/index_killop.js";TestData.testFile = "index_killop.js";TestData.testName = "index_killop";TestData.setParameters = "";TestData.noJournal = false;TestData.noJournalPrealloc = false;TestData.auth = false;TestData.keyFile = null;TestData.keyFileData = null;TestData.authMechanism = "MONGODB-CR";
         Date : Tue Aug 20 15:55:09 2013
2013-08-20T15:55:09.446-0500 [conn1] end connection 127.0.0.1:33478 (0 connections now open)
2013-08-20T15:55:09.446-0500 [conn1] thread conn1 stack usage was 6224 bytes,  which is the most so far
MongoDB shell version: 2.5.2-pre-
connecting to: 127.0.0.1:27999/test
2013-08-20T15:55:09.750-0500 [initandlisten] connection accepted from 127.0.0.1:33479 #2 (1 connection now open)
MONGODB-CR
2013-08-20T15:55:09.760-0500 [conn2] opening db:  test
2013-08-20T15:55:09.760-0500 [conn2] CMD: drop test.jstests_slownightly_index_killop
2013-08-20T15:55:09.764-0500 [FileAllocator] allocating new datafile /data/db/sconsTests/test.0, filling with zeroes...
2013-08-20T15:55:09.764-0500 [FileAllocator] done allocating datafile /data/db/sconsTests/test.0, size: 64MB,  took 0 secs
2013-08-20T15:55:09.765-0500 [conn2] datafileheader::init initializing /data/db/sconsTests/test.0 n:0
2013-08-20T15:55:09.765-0500 [FileAllocator] allocating new datafile /data/db/sconsTests/test.ns, filling with zeroes...
2013-08-20T15:55:09.765-0500 [FileAllocator] done allocating datafile /data/db/sconsTests/test.ns, size: 16MB,  took 0 secs
2013-08-20T15:55:09.767-0500 [conn2] build index test.jstests_slownightly_index_killop { _id: 1 }
2013-08-20T15:55:09.768-0500 [conn2] build index done.  scanned 0 total records. 0 secs
2013-08-20T15:56:09.220-0500 [clientcursormon] mem (MB) res:59 virt:634
2013-08-20T15:56:09.220-0500 [clientcursormon]  mapped (incl journal view):320
2013-08-20T15:56:09.220-0500 [clientcursormon]  connections:1
2013-08-20T15:57:09.223-0500 [clientcursormon] mem (MB) res:70 virt:634
2013-08-20T15:57:09.223-0500 [clientcursormon]  mapped (incl journal view):320
2013-08-20T15:57:09.223-0500 [clientcursormon]  connections:1
2013-08-20T15:58:09.225-0500 [clientcursormon] mem (MB) res:81 virt:634
2013-08-20T15:58:09.225-0500 [clientcursormon]  mapped (incl journal view):320
2013-08-20T15:58:09.225-0500 [clientcursormon]  connections:1
2013-08-20T15:59:09.227-0500 [clientcursormon] mem (MB) res:92 virt:634
2013-08-20T15:59:09.227-0500 [clientcursormon]  mapped (incl journal view):320
2013-08-20T15:59:09.227-0500 [clientcursormon]  connections:1
2013-08-20T15:59:23.266-0500 [FileAllocator] allocating new datafile /data/db/sconsTests/test.1, filling with zeroes...
2013-08-20T15:59:23.266-0500 [FileAllocator] done allocating datafile /data/db/sconsTests/test.1, size: 128MB,  took 0 secs
2013-08-20T15:59:23.266-0500 [conn2] datafileheader::init initializing /data/db/sconsTests/test.1 n:1
2013-08-20T16:00:09.229-0500 [clientcursormon] mem (MB) res:102 virt:890
2013-08-20T16:00:09.229-0500 [clientcursormon]  mapped (incl journal view):576
2013-08-20T16:00:09.229-0500 [clientcursormon]  connections:1
2013-08-20T16:01:09.231-0500 [clientcursormon] mem (MB) res:113 virt:890
2013-08-20T16:01:09.231-0500 [clientcursormon]  mapped (incl journal view):576
2013-08-20T16:01:09.231-0500 [clientcursormon]  connections:1
2013-08-20T16:02:40.662-0500 [initandlisten] connection accepted from 127.0.0.1:33502 #3 (2 connections now open)
2013-08-20T16:02:40.669-0500 [conn3] build index test.jstests_slownightly_index_killop { a: 1.0 }
2013-08-20T16:02:40.677-0500 [conn2] going to kill op: op: 1000031.0
2013-08-20T16:02:40.894-0500 [initandlisten] connection accepted from 127.0.0.1:33503 #4 (3 connections now open)
2013-08-20T16:02:40.898-0500 [conn4] build index test.jstests_slownightly_index_killop { a: 1.0 } background
2013-08-20T16:02:40.901-0500 [conn2] going to kill op: op: 1000035.0
Invalid access at address: 0x4b from thread: conn4
Got signal: 11 (Segmentation fault).
Backtrace:
0x131852d 0xd097c2 0xd099bb 0x3deda0f500 0xe37574 0x10579d7 0x1057752 0x1027d63 0x1056ce0 0xf88745 0x1059dc9 0x105ad8f 0x1058b9b 0xfd5010 0xfd5605 0xfd2481 0xd14201 0x130962d 0x3deda07851 0x3ded6e890d
 /home/kangas/workspace/mongo/mongod(_ZN5mongo15printStackTraceERSo+0x29) [0x131852d]
 /home/kangas/workspace/mongo/mongod(_ZN5mongo10abruptQuitEi+0x143) [0xd097c2]
 /home/kangas/workspace/mongo/mongod(_ZN5mongo24abruptQuitWithAddrSignalEiP7siginfoPv+0x155) [0xd099bb]
 /lib64/libpthread.so.0() [0x3deda0f500]
 /home/kangas/workspace/mongo/mongod(_ZN5mongo12ClientCursor13aboutToDeleteERKNS_10StringDataEPKNS_16NamespaceDetailsERKNS_7DiskLocE+0xea) [0xe37574]
 /home/kangas/workspace/mongo/mongod(_ZN5mongo11DataFileMgr12deleteRecordEPNS_16NamespaceDetailsEPKcPNS_6RecordERKNS_7DiskLocEbbb+0x277) [0x10579d7]
 /home/kangas/workspace/mongo/mongod(_ZN5mongo11DataFileMgr12deleteRecordEPKcPNS_6RecordERKNS_7DiskLocEbbb+0x8c) [0x1057752]
 /home/kangas/workspace/mongo/mongod(_ZN5mongo13deleteObjectsEPKcNS_7BSONObjEbbbPNS_11RemoveSaverE+0xb8f) [0x1027d63]
 /home/kangas/workspace/mongo/mongod(_ZN5mongo6dropNSERKSs+0x4a4) [0x1056ce0]
 /home/kangas/workspace/mongo/mongod(_ZN5mongo12IndexDetails8kill_idxEv+0xaf) [0xf88745]
 /home/kangas/workspace/mongo/mongod(_ZN5mongo16insert_makeIndexEPNS_16NamespaceDetailsERKSsRKNS_7DiskLocEb+0x32a) [0x1059dc9]
 /home/kangas/workspace/mongo/mongod(_ZN5mongo11DataFileMgr6insertEPKcPKvibbbPb+0xa33) [0x105ad8f]
 /home/kangas/workspace/mongo/mongod(_ZN5mongo11DataFileMgr16insertWithObjModEPKcRNS_7BSONObjEbb+0x89) [0x1058b9b]
 /home/kangas/workspace/mongo/mongod(_ZN5mongo14checkAndInsertEPKcRNS_7BSONObjE+0x1f8) [0xfd5010]
 /home/kangas/workspace/mongo/mongod(_ZN5mongo14receivedInsertERNS_7MessageERNS_5CurOpE+0x441) [0xfd5605]
 /home/kangas/workspace/mongo/mongod(_ZN5mongo16assembleResponseERNS_7MessageERNS_10DbResponseERKNS_11HostAndPortE+0x6b3) [0xfd2481]
 /home/kangas/workspace/mongo/mongod(_ZN5mongo16MyMessageHandler7processERNS_7MessageEPNS_21AbstractMessagingPortEPNS_9LastErrorE+0x10f) [0xd14201]
 /home/kangas/workspace/mongo/mongod(_ZN5mongo17PortMessageServer17handleIncomingMsgEPv+0x5b8) [0x130962d]
 /lib64/libpthread.so.0() [0x3deda07851]
 /lib64/libc.so.6(clone+0x6d) [0x3ded6e890d]
2013-08-20T16:02:41.104-0500 DBClientCursor::init call() failed
2013-08-20T16:02:41.108-0500 Error: error doing query: failed at src/mongo/shell/query.js:81
failed to load: /home/kangas/workspace/mongo/jstests/slowNightly/index_killop.js
                    7.5277 minutes
test /home/kangas/workspace/mongo/jstests/slowNightly/index_killop.js exited with status 253
0 tests succeeded
The following tests failed (with exit code):
/home/kangas/workspace/mongo/jstests/slowNightly/index_killop.js        253



 Comments   
Comment by auto [ 21/Aug/13 ]

Author:

{u'username': u'hkhalsa', u'name': u'Hari Khalsa', u'email': u'hkhalsa@10gen.com'}

Message: SERVER-10026 RAII-ify Runner yielding SERVER-10583
Branch: master
https://github.com/mongodb/mongo/commit/2fb049df6f695179a02bd71cd4a6be53fd0b9bfc

Comment by auto [ 20/Aug/13 ]

Author:

{u'username': u'hkhalsa', u'name': u'Hari Khalsa', u'email': u'hkhalsa@10gen.com'}

Message: SERVER-10026 SERVER-10583 internal runners deregister themselves in dtor
Branch: master
https://github.com/mongodb/mongo/commit/3ae747331fc37e7826f6cd20088bee76b3a7bb00

Comment by Andrew Morrow (Inactive) [ 20/Aug/13 ]

I was able to repro this against eab481bd1a0a58418e80d087462edf3d80231951:

Program received signal SIGSEGV, Segmentation fault.
[Switching to Thread 0x7f6db1ef8700 (LWP 25111)]
0x0000000000894521 in mongo::ClientCursor::aboutToDelete (ns=..., nsd=nsd@entry=0x7f6dc2d83910, dl=...)
    at src/mongo/db/clientcursor.cpp:243
243	            if (0 == ns.compare(runner->ns())) {
(gdb) print ns
$1 = (const mongo::StringData &) @0x7f6db1ef68f0: {_data = 0x7f6ddde7b818 "test.system.namespaces", _size = 18446744073709551615}
(gdb) print runner
$2 = (mongo::Runner *) 0x7f6dde093c80
(gdb) print *runner
$3 = {_vptr.Runner = 0x3}
(gdb) where
#0  0x0000000000894521 in mongo::ClientCursor::aboutToDelete (ns=..., nsd=nsd@entry=0x7f6dc2d83910, dl=...)
    at src/mongo/db/clientcursor.cpp:243
#1  0x0000000000a65764 in mongo::DataFileMgr::deleteRecord (this=this@entry=0x1818280 <mongo::theDataFileMgr>, d=0x7f6dc2d83910,
    ns=ns@entry=0x7f6ddde7b818 "test.system.namespaces", todelete=todelete@entry=0x7f6dc410017c, dl=...,
    cappedOK=cappedOK@entry=false, noWarn=noWarn@entry=false, doLog=doLog@entry=false) at src/mongo/db/pdfile.cpp:751
#2  0x0000000000a65a15 in mongo::DataFileMgr::deleteRecord (this=0x1818280 <mongo::theDataFileMgr>,
    ns=ns@entry=0x7f6ddde7b818 "test.system.namespaces", todelete=0x7f6dc410017c, dl=..., cappedOK=cappedOK@entry=false,
    noWarn=noWarn@entry=false, doLog=doLog@entry=false) at src/mongo/db/pdfile.cpp:730
#3  0x0000000000a38d6c in mongo::deleteObjects (ns=0x7f6ddde7b818 "test.system.namespaces", pattern=...,
    justOne=justOne@entry=false, logop=logop@entry=false, god=god@entry=true, rs=rs@entry=0x0) at src/mongo/db/ops/delete.cpp:135
#4  0x0000000000a64e9d in mongo::dropNS (nsToDrop=...) at src/mongo/db/pdfile.cpp:632
#5  0x00000000009ac2b8 in mongo::IndexDetails::kill_idx (this=this@entry=0x7f6dc28c0dfc) at src/mongo/db/index.cpp:102
#6  0x0000000000a63641 in mongo::insert_makeIndex (tableToIndex=<optimized out>, tabletoidxns=..., loc=...,
    mayInterrupt=mayInterrupt@entry=true) at src/mongo/db/pdfile.cpp:1100
#7  0x0000000000a671a3 in mongo::DataFileMgr::insert (this=0x1818280 <mongo::theDataFileMgr>,
    ns=ns@entry=0x7f6dddec8014 "test.system.indexes", obuf=0x7f6dddec46c4, len=106, mayInterrupt=<optimized out>,
    god=god@entry=false, mayAddIndex=mayAddIndex@entry=true, addedID=addedID@entry=0x7f6db1ef6fa0) at src/mongo/db/pdfile.cpp:1292
#8  0x0000000000a6780d in mongo::DataFileMgr::insertWithObjMod (this=<optimized out>,
    ns=ns@entry=0x7f6dddec8014 "test.system.indexes", o=..., mayInterrupt=<optimized out>, god=god@entry=false)
    at src/mongo/db/pdfile.cpp:926
#9  0x00000000009ec69c in mongo::checkAndInsert (ns=ns@entry=0x7f6dddec8014 "test.system.indexes", js=...)
    at src/mongo/db/instance.cpp:860

This was a release build. I'm going to try a debug build and see if the mutable assertion shows up (note that it is really an assertion in the builder, under mutable, complaining about object size).

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