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

index_killop.js segfault and/or assertion failure on Linux 64 debug

XMLWordPrintableJSON

    • ALL

      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

            Assignee:
            hari.khalsa@10gen.com hari.khalsa@10gen.com
            Reporter:
            matt.kangas Matt Kangas
            Votes:
            0 Vote for this issue
            Watchers:
            3 Start watching this issue

              Created:
              Updated:
              Resolved: