[SERVER-1499] Server crash making index Created: 27/Jul/10  Updated: 12/Jul/16  Resolved: 28/Jul/10

Status: Closed
Project: Core Server
Component/s: Index Maintenance
Affects Version/s: 1.5.4
Fix Version/s: None

Type: Bug Priority: Critical - P2
Reporter: Doug Hudson Assignee: Eliot Horowitz (Inactive)
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

Tue Jul 27 14:45:57 db version v1.5.4, pdfile version 4.5
Tue Jul 27 14:45:57 git version: 6c1361df41d9cabf9026364427a7df44b3c304fd
Tue Jul 27 14:45:57 sys info: Linux domU-12-31-39-06-79-A1 2.6.21.7-2.ec2.v1.2.fc8xen #1 SMP Fri Nov 20 17:48:28 EST 2009 x86_64 BOOST_LIB_VERSION=1_41


Operating System: Linux
Participants:

 Description   

Through ruby driver. Client quits with error: assertion: 9001 socket exception

[conn6] Tue Jul 27 14:52:33 building new index on

{ _id: 1 }

for pubmed.author_score
[conn6] Tue Jul 27 14:52:33 Buildindex pubmed.author_score idxNo:0 { name: "id", ns: "pubmed.author_score", key:

{ _id: 1 }

}

Server stack:
Tue Jul 27 14:54:56 Got signal: 7 (Bus error).
Tue Jul 27 14:54:56 Backtrace:
0x7999a9 0x7fe599950af0 0x67ba09 0x6bb513 0x5f6577 0x5fc4f4 0x5fb270 0x5fb714 0x5fb152 0x5fb714 0x5fb152 0x5fb714 0x6b392c 0x6bc0c2 0x6bd37a 0x69db5e 0x6a13cc 0x79a62d 0x7ae4a0 0x7fe59a4549ca
./mongod(_ZN5mongo10abruptQuitEi+0x399) [0x7999a9]
/lib/libc.so.6(+0x33af0) [0x7fe599950af0]
./mongod(_ZN5mongo16NamespaceDetails5allocEPKciRNS_7DiskLocE+0x159) [0x67ba09]
./mongod(_ZN5mongo11DataFileMgr6insertEPKcPKvibRKNS_11BSONElementEb+0x463) [0x6bb513]
./mongod(_ZN5mongo11BtreeBucket9addBucketERNS_12IndexDetailsE+0x67) [0x5f6577]
./mongod(_ZN5mongo11BtreeBucket10insertHereENS_7DiskLocEiS1_RKNS_7BSONObjERKNS_8OrderingES1_S1_RNS_12IndexDetailsE+0x5e4) [0x5fc4f4]
./mongod(_ZN5mongo11BtreeBucket7_insertENS_7DiskLocES1_RKNS_7BSONObjERKNS_8OrderingEbS1_S1_RNS_12IndexDetailsE+0x2a0) [0x5fb270]
./mongod(_ZN5mongo11BtreeBucket9bt_insertENS_7DiskLocES1_RKNS_7BSONObjERKNS_8OrderingEbRNS_12IndexDetailsEb+0xc4) [0x5fb714]
./mongod(_ZN5mongo11BtreeBucket7_insertENS_7DiskLocES1_RKNS_7BSONObjERKNS_8OrderingEbS1_S1_RNS_12IndexDetailsE+0x182) [0x5fb152]
./mongod(_ZN5mongo11BtreeBucket9bt_insertENS_7DiskLocES1_RKNS_7BSONObjERKNS_8OrderingEbRNS_12IndexDetailsEb+0xc4) [0x5fb714]
./mongod(_ZN5mongo11BtreeBucket7_insertENS_7DiskLocES1_RKNS_7BSONObjERKNS_8OrderingEbS1_S1_RNS_12IndexDetailsE+0x182) [0x5fb152]
./mongod(_ZN5mongo11BtreeBucket9bt_insertENS_7DiskLocES1_RKNS_7BSONObjERKNS_8OrderingEbRNS_12IndexDetailsEb+0xc4) [0x5fb714]
./mongod() [0x6b392c]
./mongod(_ZN5mongo11DataFileMgr6insertEPKcPKvibRKNS_11BSONElementEb+0x1012) [0x6bc0c2]
./mongod(_ZN5mongo11DataFileMgr16insertWithObjModEPKcRNS_7BSONObjEb+0x5a) [0x6bd37a]
./mongod(_ZN5mongo14receivedInsertERNS_7MessageERNS_5CurOpE+0x33e) [0x69db5e]
./mongod(_ZN5mongo16assembleResponseERNS_7MessageERNS_10DbResponseERKNS_8SockAddrE+0x147c) [0x6a13cc]
./mongod(_ZN5mongo10connThreadEv+0x30d) [0x79a62d]
./mongod(thread_proxy+0x80) [0x7ae4a0]
/lib/libpthread.so.0(+0x69ca) [0x7fe59a4549ca]
Tue Jul 27 14:54:56 dbexit:
[conn15] Tue Jul 27 14:54:56 shutdown: going to close listening sockets...
[conn15] Tue Jul 27 14:54:56 going to close listening socket: 5
[conn15] Tue Jul 27 14:54:56 going to close listening socket: 6
[conn15] Tue Jul 27 14:54:56 going to close listening socket: 7
[conn15] Tue Jul 27 14:54:56 going to close listening socket: 8
[conn15] Tue Jul 27 14:54:56 shutdown: going to flush oplog...
[conn15] Tue Jul 27 14:54:56 shutdown: going to close sockets...
[conn15] Tue Jul 27 14:54:56 shutdown: waiting for fs preallocator...
[conn15] Tue Jul 27 14:54:56 shutdown: closing all files...
Tue Jul 27 14:54:56 closeAllFiles() finished
[conn15] Tue Jul 27 14:54:56 shutdown: removing fs lock...
Tue Jul 27 14:54:56 dbexit: really exiting now
ERROR: Client::~Client _context should be NULL: conn

First attempt to create index failed in the following way:

[conn118] Tue Jul 27 14:39:35 Buildindex pubmed.author_score idxNo:1 { ns: "pubmed.author_score", name: "author_1_year_-1", key:

{ author: 1, year: -1 }

}
1923800/17532184 10%
3075300/17532184 17%
3085500/17532184 17%
Tue Jul 27 14:40:30 Got signal: 7 (Bus error).
Tue Jul 27 14:40:31 Backtrace:
0x7999a9 0x7f921ee4faf0 0x4c62f3 0x5919d0 0x592f5a 0x6b8e72 0x6ba403 0x6bb935 0x6bd37a 0x69db5e 0x6a13cc 0x79a62d 0x7ae4a0 0x7f921f9539ca 0x7f921ef026fd
./mongod(_ZN5mongo10abruptQuitEi+0x399) [0x7999a9]
/lib/libc.so.6(+0x33af0) [0x7f921ee4faf0]
./mongod(_ZNK5mongo7BSONObj21getFieldDottedOrArrayERPKc+0xd3) [0x4c62f3]
./mongod(_ZNK5mongo9IndexSpec8_getKeysESt6vectorIPKcSaIS3_EES1_INS_11BSONElementESaIS6_EERKNS_7BSONObjERSt3setIS9_NS_22BSONObjCmpDefaultOrderESaIS9_EE+0x80) [0x5919d0]
./mongod(_ZNK5mongo9IndexSpec7getKeysERKNS_7BSONObjERSt3setIS1_NS_22BSONObjCmpDefaultOrderESaIS1_EE+0x2ea) [0x592f5a]
./mongod(_ZN5mongo14fastBuildIndexEPKcPNS_16NamespaceDetailsERNS_12IndexDetailsEi+0x562) [0x6b8e72]
./mongod() [0x6ba403]
./mongod(_ZN5mongo11DataFileMgr6insertEPKcPKvibRKNS_11BSONElementEb+0x885) [0x6bb935]
./mongod(_ZN5mongo11DataFileMgr16insertWithObjModEPKcRNS_7BSONObjEb+0x5a) [0x6bd37a]
./mongod(_ZN5mongo14receivedInsertERNS_7MessageERNS_5CurOpE+0x33e) [0x69db5e]
./mongod(_ZN5mongo16assembleResponseERNS_7MessageERNS_10DbResponseERKNS_8SockAddrE+0x147c) [0x6a13cc]
./mongod(_ZN5mongo10connThreadEv+0x30d) [0x79a62d]
./mongod(thread_proxy+0x80) [0x7ae4a0]
/lib/libpthread.so.0(+0x69ca) [0x7f921f9539ca]
/lib/libc.so.6(clone+0x6d) [0x7f921ef026fd]
Tue Jul 27 14:40:31 dbexit:
[conn118] Tue Jul 27 14:40:31 shutdown: going to close listening sockets...
[conn118] Tue Jul 27 14:40:31 going to close listening socket: 5
[conn118] Tue Jul 27 14:40:31 going to close listening socket: 6
[conn118] Tue Jul 27 14:40:31 going to close listening socket: 7
[conn118] Tue Jul 27 14:40:31 going to close listening socket: 8
[conn118] Tue Jul 27 14:40:31 shutdown: going to flush oplog...
[conn118] Tue Jul 27 14:40:31 shutdown: going to close sockets...
[conn118] Tue Jul 27 14:40:31 shutdown: waiting for fs preallocator...
[conn118] Tue Jul 27 14:40:31 shutdown: closing all files...
Tue Jul 27 14:40:33 closeAllFiles() finished
[conn118] Tue Jul 27 14:40:33 shutdown: removing fs lock...
Tue Jul 27 14:40:33 dbexit: really exiting now
ERROR: Client::~Client _context should be NULL: conn



 Comments   
Comment by Eliot Horowitz (Inactive) [ 28/Jul/10 ]

S3 copy of the dataset would be great.
We have a # of platforms we could try it on

Comment by Doug Hudson [ 28/Jul/10 ]

Eliot - would be happy to try and determine the cause. Not sure the best way we can do that; perhaps I can give you access to a S3 copy of the dataset, although I have the feeling it is a platform issue (I updated kernel earlier in the day for example).

Comment by Eliot Horowitz (Inactive) [ 28/Jul/10 ]

Ok - great.
If you have time - would love to reproduce just to make sure we understand and its not accidental

Comment by Doug Hudson [ 28/Jul/10 ]

I moved from 1.5.6 to nightly and a big import+index ran fine. Anecdotally it seems that whatever the problem was is no longer evident. Over the next day I will be doing heavy loading/indexing and will comment on whether I see more similar errors.

Comment by Doug Hudson [ 27/Jul/10 ]

I don't think it's a bad document that is causing this (this particular collection hasn't changed in a couple of months.

The Bus Errors seem to be occurring pretty regularly now, through ruby driver and javascript shell.

The following was when I was iterating across all docs to see if one was corrupt. After restarting, the next documents after and including the one it crashed at can be retrieved fine. Not too sure how deterministric this error is and as such it may be tricky to create a reproducible example.

[conn2] Tue Jul 27 18:04:05 getmore pubmed.articles cid:7483872704163850936 getMore: {} bytes:1049205 nreturned:840 1ms
Tue Jul 27 18:04:46 Got signal: 7 (Bus error).

Tue Jul 27 18:04:46 Backtrace:
0x7e5759 0x7fbb97611af0 0x7fbb97664dbb 0x5ef0af 0x5dae53 0x6d7bfe 0x6da2b9 0x7e7ecb 0x7fa960 0x7fbb981159ca 0x7fbb976c46fd
./mongod(_ZN5mongo10abruptQuitEi+0x399) [0x7e5759]
/lib/libc.so.6(+0x33af0) [0x7fbb97611af0]
/lib/libc.so.6(memcpy+0x15b) [0x7fbb97664dbb]
./mongod(_ZN5mongo22fillQueryResultFromObjERNS_10BufBuilderEPNS_12FieldMatcherERNS_7BSONObjEPNS_7DiskLocE+0xbff) [0x5ef0af]
./mongod(_ZN5mongo14processGetMoreEPKcixRNS_5CurOpEiRb+0x393) [0x5dae53]
./mongod(_ZN5mongo15receivedGetMoreERNS_10DbResponseERNS_7MessageERNS_5CurOpE+0x29e) [0x6d7bfe]
./mongod(_ZN5mongo16assembleResponseERNS_7MessageERNS_10DbResponseERKNS_8SockAddrE+0x1309) [0x6da2b9]
./mongod(_ZN5mongo10connThreadEv+0x31b) [0x7e7ecb]
./mongod(thread_proxy+0x80) [0x7fa960]
/lib/libpthread.so.0(+0x69ca) [0x7fbb981159ca]
/lib/libc.so.6(clone+0x6d) [0x7fbb976c46fd]

Tue Jul 27 18:04:46 dbexit:

[conn2] Tue Jul 27 18:04:46 shutdown: going to close listening sockets...
[conn2] Tue Jul 27 18:04:46 going to close listening socket: 5
[conn2] Tue Jul 27 18:04:46 going to close listening socket: 6
[conn2] Tue Jul 27 18:04:46 going to close listening socket: 7
[conn2] Tue Jul 27 18:04:46 going to close listening socket: 8
[conn2] Tue Jul 27 18:04:46 shutdown: going to flush oplog...
[conn2] Tue Jul 27 18:04:46 shutdown: going to close sockets...
[conn2] Tue Jul 27 18:04:46 shutdown: waiting for fs preallocator...
[conn2] Tue Jul 27 18:04:46 shutdown: closing all files...
Tue Jul 27 18:04:46 closeAllFiles() finished

[conn2] Tue Jul 27 18:04:46 shutdown: removing fs lock...
Tue Jul 27 18:04:46 dbexit: really exiting now

ERROR: Client::~Client _context should be NULL: conn

Comment by Doug Hudson [ 27/Jul/10 ]

I will try and create a small dataset test case.

Comment by Doug Hudson [ 27/Jul/10 ]

Trying to --repair this new db results in the following crash:

> ./mongod -dbpath ../../mongo-data/ --directoryperdb --slowms 0 --repair
Tue Jul 27 17:26:23 MongoDB starting : pid=12051 port=27017 dbpath=../../mongo-data/ 64-bit

    • NOTE: This is a development version (1.5.6) of MongoDB.
    • Not recommended for production.

Tue Jul 27 17:26:23 db version v1.5.6, pdfile version 4.5
Tue Jul 27 17:26:23 git version: 39cdcd202f6377e95f30685098ce14c579670d45
Tue Jul 27 17:26:23 sys info: Linux domU-12-31-39-06-79-A1 2.6.21.7-2.ec2.v1.2.fc8xen #1 SMP Fri Nov 20 17:48:28 EST 2009 x86_64 BOOST_LIB_VERSION=1_41
[initandlisten] Tue Jul 27 17:26:23 query local.system.namespaces reslen:36 nscanned:0

{ name: /^local.temp./ }

nreturned:0 34ms
[initandlisten] Tue Jul 27 17:26:23 ****
[initandlisten] Tue Jul 27 17:26:23 ****
[initandlisten] Tue Jul 27 17:26:23 need to upgrade database pubmed_web with pdfile version 4.5, new version: 4.5
[initandlisten] Tue Jul 27 17:26:23 starting upgrade
[initandlisten] Tue Jul 27 17:26:23 pubmed_web repairDatabase pubmed_web
[initandlisten] Tue Jul 27 17:26:23 query pubmed_web.system.namespaces reslen:155 nscanned:3 {} nreturned:3 25ms
Tue Jul 27 17:26:23 allocating new datafile ../../mongo-data/$tmp_repairDatabase_0/pubmed_web/pubmed_web.ns, filling with zeroes...
Tue Jul 27 17:26:23 done allocating datafile ../../mongo-data/$tmp_repairDatabase_0/pubmed_web/pubmed_web.ns, size: 16MB, took 0.017 secs
Tue Jul 27 17:26:23 allocating new datafile ../../mongo-data/$tmp_repairDatabase_0/pubmed_web/pubmed_web.0, filling with zeroes...
Tue Jul 27 17:26:23 done allocating datafile ../../mongo-data/$tmp_repairDatabase_0/pubmed_web/pubmed_web.0, size: 64MB, took 0 secs
Tue Jul 27 17:26:23 allocating new datafile ../../mongo-data/$tmp_repairDatabase_0/pubmed_web/pubmed_web.1, filling with zeroes...
Tue Jul 27 17:26:23 done allocating datafile ../../mongo-data/$tmp_repairDatabase_0/pubmed_web/pubmed_web.1, size: 128MB, took 0.001 secs
[initandlisten] Tue Jul 27 17:26:23 query pubmed_web.universes reslen:26301 nscanned:4 {} nreturned:4 18ms
[initandlisten] Tue Jul 27 17:26:23 building new index on

{ _id: 1 }

for pubmed_web.universes
[initandlisten] Tue Jul 27 17:26:23 Buildindex pubmed_web.universes idxNo:0 { name: "id", ns: "pubmed_web.universes", key:

{ _id: 1 }

}
[initandlisten] Tue Jul 27 17:26:23 done for 4 records 0.001secs
[initandlisten] Tue Jul 27 17:26:23 query pubmed_web.system.indexes reslen:36 nscanned:1 { name:

{ $ne: "_id_" }

} nreturned:0 3ms
[initandlisten] Tue Jul 27 17:26:23 ****
[initandlisten] Tue Jul 27 17:26:23 ****
[initandlisten] Tue Jul 27 17:26:23 need to upgrade database pubmed with pdfile version 4.5, new version: 4.5
[initandlisten] Tue Jul 27 17:26:23 starting upgrade
[initandlisten] Tue Jul 27 17:26:23 pubmed repairDatabase pubmed
[initandlisten] Tue Jul 27 17:26:23 query pubmed.system.namespaces reslen:141 nscanned:3 {} nreturned:3 15ms
Tue Jul 27 17:26:23 allocating new datafile ../../mongo-data/$tmp_repairDatabase_0/pubmed/pubmed.ns, filling with zeroes...
Tue Jul 27 17:26:23 done allocating datafile ../../mongo-data/$tmp_repairDatabase_0/pubmed/pubmed.ns, size: 16MB, took 0 secs
Tue Jul 27 17:26:23 allocating new datafile ../../mongo-data/$tmp_repairDatabase_0/pubmed/pubmed.0, filling with zeroes...
Tue Jul 27 17:26:23 done allocating datafile ../../mongo-data/$tmp_repairDatabase_0/pubmed/pubmed.0, size: 64MB, took 0.009 secs
Tue Jul 27 17:26:23 allocating new datafile ../../mongo-data/$tmp_repairDatabase_0/pubmed/pubmed.1, filling with zeroes...
Tue Jul 27 17:26:23 done allocating datafile ../../mongo-data/$tmp_repairDatabase_0/pubmed/pubmed.1, size: 128MB, took 0 secs
[initandlisten] Tue Jul 27 17:26:23 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1049097 nreturned:729 2ms
[initandlisten] Tue Jul 27 17:26:23 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1049568 nreturned:744 18ms
[initandlisten] Tue Jul 27 17:26:23 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1048846 nreturned:718 1ms
[initandlisten] Tue Jul 27 17:26:23 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1049770 nreturned:745 2ms
[initandlisten] Tue Jul 27 17:26:23 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1049987 nreturned:750 1ms
[initandlisten] Tue Jul 27 17:26:23 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1050008 nreturned:766 4ms
[initandlisten] Tue Jul 27 17:26:23 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1048840 nreturned:764 1ms
[initandlisten] Tue Jul 27 17:26:23 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1049219 nreturned:752 1ms
[initandlisten] Tue Jul 27 17:26:23 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1049134 nreturned:809 1ms
[initandlisten] Tue Jul 27 17:26:23 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1050037 nreturned:714 5ms
[initandlisten] Tue Jul 27 17:26:23 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1050164 nreturned:780 1ms
[initandlisten] Tue Jul 27 17:26:23 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1048883 nreturned:782 1ms
[initandlisten] Tue Jul 27 17:26:23 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1048979 nreturned:757 1ms
[initandlisten] Tue Jul 27 17:26:23 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1050139 nreturned:751 1ms
[initandlisten] Tue Jul 27 17:26:23 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1049441 nreturned:747 1ms
[initandlisten] Tue Jul 27 17:26:24 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1049871 nreturned:797 1ms
[initandlisten] Tue Jul 27 17:26:24 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1050023 nreturned:785 1ms
[initandlisten] Tue Jul 27 17:26:24 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1049222 nreturned:759 1ms
[initandlisten] Tue Jul 27 17:26:24 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1049155 nreturned:786 1ms
[initandlisten] Tue Jul 27 17:26:24 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1048796 nreturned:779 1ms
[initandlisten] Tue Jul 27 17:26:24 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1048735 nreturned:804 1ms
[initandlisten] Tue Jul 27 17:26:24 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1050201 nreturned:800 1ms
[initandlisten] Tue Jul 27 17:26:24 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1049675 nreturned:795 1ms
[initandlisten] Tue Jul 27 17:26:24 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1049452 nreturned:757 1ms
[initandlisten] Tue Jul 27 17:26:24 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1048879 nreturned:779 1ms
[initandlisten] Tue Jul 27 17:26:24 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1050116 nreturned:770 1ms
[initandlisten] Tue Jul 27 17:26:24 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1049507 nreturned:766 1ms
[initandlisten] Tue Jul 27 17:26:24 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1048591 nreturned:793 1ms
Tue Jul 27 17:26:24 allocating new datafile ../../mongo-data/$tmp_repairDatabase_0/pubmed/pubmed.2, filling with zeroes...
Tue Jul 27 17:26:24 done allocating datafile ../../mongo-data/$tmp_repairDatabase_0/pubmed/pubmed.2, size: 256MB, took 0 secs
[initandlisten] Tue Jul 27 17:26:24 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1050002 nreturned:754 1ms
[initandlisten] Tue Jul 27 17:26:24 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1050166 nreturned:699 1ms
[initandlisten] Tue Jul 27 17:26:24 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1049323 nreturned:776 1ms
[initandlisten] Tue Jul 27 17:26:24 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1048952 nreturned:739 7ms
[initandlisten] Tue Jul 27 17:26:24 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1049148 nreturned:817 1ms
[initandlisten] Tue Jul 27 17:26:24 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1049513 nreturned:800 1ms
[initandlisten] Tue Jul 27 17:26:24 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1049481 nreturned:745 1ms
[initandlisten] Tue Jul 27 17:26:24 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1049110 nreturned:757 1ms
[initandlisten] Tue Jul 27 17:26:24 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1049232 nreturned:811 1ms
[initandlisten] Tue Jul 27 17:26:24 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1049865 nreturned:798 1ms
[initandlisten] Tue Jul 27 17:26:24 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1049682 nreturned:883 1ms
[initandlisten] Tue Jul 27 17:26:24 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1050079 nreturned:754 1ms
[initandlisten] Tue Jul 27 17:26:24 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1049270 nreturned:772 10ms
[initandlisten] Tue Jul 27 17:26:24 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1049054 nreturned:795 1ms
[initandlisten] Tue Jul 27 17:26:24 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1050109 nreturned:801 1ms
[initandlisten] Tue Jul 27 17:26:24 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1048830 nreturned:774 1ms
[initandlisten] Tue Jul 27 17:26:24 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1049447 nreturned:905 1ms
[initandlisten] Tue Jul 27 17:26:24 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1049655 nreturned:721 1ms
[initandlisten] Tue Jul 27 17:26:24 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1048858 nreturned:782 1ms
[initandlisten] Tue Jul 27 17:26:24 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1048943 nreturned:733 1ms
[initandlisten] Tue Jul 27 17:26:24 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1049623 nreturned:776 1ms
[initandlisten] Tue Jul 27 17:26:24 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1049256 nreturned:819 1ms
[initandlisten] Tue Jul 27 17:26:24 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1050051 nreturned:766 6ms
[initandlisten] Tue Jul 27 17:26:24 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1049028 nreturned:804 1ms
[initandlisten] Tue Jul 27 17:26:24 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1049575 nreturned:813 1ms
[initandlisten] Tue Jul 27 17:26:24 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1049513 nreturned:812 6ms
[initandlisten] Tue Jul 27 17:26:24 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1049447 nreturned:812 1ms
[initandlisten] Tue Jul 27 17:26:24 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1050295 nreturned:772 1ms
[initandlisten] Tue Jul 27 17:26:24 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1048752 nreturned:742 13ms
[initandlisten] Tue Jul 27 17:26:24 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1049450 nreturned:844 2ms
[initandlisten] Tue Jul 27 17:26:24 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1049836 nreturned:821 1ms
[initandlisten] Tue Jul 27 17:26:24 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1049479 nreturned:744 1ms
[initandlisten] Tue Jul 27 17:26:24 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1049769 nreturned:898 1ms
[initandlisten] Tue Jul 27 17:26:24 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1048949 nreturned:812 1ms
[initandlisten] Tue Jul 27 17:26:24 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1050311 nreturned:747 13ms
[initandlisten] Tue Jul 27 17:26:24 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1050405 nreturned:811 1ms
[initandlisten] Tue Jul 27 17:26:24 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1049136 nreturned:864 1ms
[initandlisten] Tue Jul 27 17:26:24 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1049809 nreturned:781 1ms
[initandlisten] Tue Jul 27 17:26:24 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1048860 nreturned:832 1ms
[initandlisten] Tue Jul 27 17:26:24 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1049310 nreturned:821 1ms
[initandlisten] Tue Jul 27 17:26:24 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1049515 nreturned:782 13ms
[initandlisten] Tue Jul 27 17:26:25 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1049367 nreturned:753 1ms
[initandlisten] Tue Jul 27 17:26:25 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1049405 nreturned:798 1ms
[initandlisten] Tue Jul 27 17:26:25 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1050252 nreturned:822 14ms
[initandlisten] Tue Jul 27 17:26:25 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1049040 nreturned:804 8ms
[initandlisten] Tue Jul 27 17:26:25 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1049702 nreturned:749 1ms
[initandlisten] Tue Jul 27 17:26:25 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1049009 nreturned:750 18ms
[initandlisten] Tue Jul 27 17:26:25 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1048741 nreturned:748 9ms
[initandlisten] Tue Jul 27 17:26:25 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1049655 nreturned:806 2ms
Tue Jul 27 17:26:25 allocating new datafile ../../mongo-data/$tmp_repairDatabase_0/pubmed/pubmed.3, filling with zeroes...
Tue Jul 27 17:26:25 done allocating datafile ../../mongo-data/$tmp_repairDatabase_0/pubmed/pubmed.3, size: 512MB, took 0.019 secs
[initandlisten] Tue Jul 27 17:26:25 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1049395 nreturned:759 38ms
[initandlisten] Tue Jul 27 17:26:25 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1049765 nreturned:888 1ms
[initandlisten] Tue Jul 27 17:26:25 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1049186 nreturned:761 20ms
[initandlisten] Tue Jul 27 17:26:25 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1048737 nreturned:759 1ms
[initandlisten] Tue Jul 27 17:26:25 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1049728 nreturned:878 16ms
[initandlisten] Tue Jul 27 17:26:25 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1049291 nreturned:878 1ms
[initandlisten] Tue Jul 27 17:26:25 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1048649 nreturned:748 13ms
[initandlisten] Tue Jul 27 17:26:25 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1048988 nreturned:843 14ms
[initandlisten] Tue Jul 27 17:26:25 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1049161 nreturned:885 12ms
[initandlisten] Tue Jul 27 17:26:25 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1049649 nreturned:834 2ms
[initandlisten] Tue Jul 27 17:26:25 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1048688 nreturned:778 3ms
[initandlisten] Tue Jul 27 17:26:25 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1049293 nreturned:790 12ms
[initandlisten] Tue Jul 27 17:26:25 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1049811 nreturned:843 2ms
[initandlisten] Tue Jul 27 17:26:25 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1049103 nreturned:760 1ms
[initandlisten] Tue Jul 27 17:26:25 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1049106 nreturned:800 24ms
[initandlisten] Tue Jul 27 17:26:25 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1050036 nreturned:835 1ms
[initandlisten] Tue Jul 27 17:26:25 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1050404 nreturned:813 7ms
[initandlisten] Tue Jul 27 17:26:25 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1048879 nreturned:873 14ms
[initandlisten] Tue Jul 27 17:26:25 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1048609 nreturned:788 8ms
[initandlisten] Tue Jul 27 17:26:25 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1048728 nreturned:904 5ms
[initandlisten] Tue Jul 27 17:26:25 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1049168 nreturned:795 2ms
[initandlisten] Tue Jul 27 17:26:25 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1048932 nreturned:850 10ms
[initandlisten] Tue Jul 27 17:26:25 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1049380 nreturned:742 1ms
[initandlisten] Tue Jul 27 17:26:25 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1048764 nreturned:764 5ms
[initandlisten] Tue Jul 27 17:26:25 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1049732 nreturned:782 10ms
[initandlisten] Tue Jul 27 17:26:25 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1049718 nreturned:800 1ms
[initandlisten] Tue Jul 27 17:26:25 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1069014 nreturned:827 9ms
[initandlisten] Tue Jul 27 17:26:25 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1049205 nreturned:840 1ms
[initandlisten] Tue Jul 27 17:26:25 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1049602 nreturned:754 16ms
[initandlisten] Tue Jul 27 17:26:25 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1049138 nreturned:802 2ms
[initandlisten] Tue Jul 27 17:26:25 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1049152 nreturned:779 1ms
[initandlisten] Tue Jul 27 17:26:25 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1049128 nreturned:817 9ms
[initandlisten] Tue Jul 27 17:26:25 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1048824 nreturned:751 1ms
[initandlisten] Tue Jul 27 17:26:25 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1049167 nreturned:830 1ms
[initandlisten] Tue Jul 27 17:26:25 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1048935 nreturned:791 1ms
[initandlisten] Tue Jul 27 17:26:25 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1049150 nreturned:831 1ms
[initandlisten] Tue Jul 27 17:26:25 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1049495 nreturned:843 22ms
[initandlisten] Tue Jul 27 17:26:25 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1049144 nreturned:769 5ms
[initandlisten] Tue Jul 27 17:26:25 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1048612 nreturned:784 3ms
[initandlisten] Tue Jul 27 17:26:25 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1049860 nreturned:811 2ms
[initandlisten] Tue Jul 27 17:26:25 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1048727 nreturned:818 1ms
[initandlisten] Tue Jul 27 17:26:25 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1050093 nreturned:790 17ms
[initandlisten] Tue Jul 27 17:26:25 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1048915 nreturned:872 1ms
[initandlisten] Tue Jul 27 17:26:25 getmore pubmed.articles cid:2442835680079681343 getMore: {} bytes:1049279 nreturned:789 24ms
Tue Jul 27 17:26:40 Got signal: 7 (Bus error).

Tue Jul 27 17:26:41 Backtrace:
0x7e5759 0x7fef8326daf0 0x7fef832c0dbb 0x5ef0af 0x5dae53 0x6d7bfe 0x6da2b9 0x6daed1 0x561fcd 0x562508 0x69c8a4 0x69f208 0x6a0c4d 0x6fd4cb 0x7e5dd8 0x7e91dd 0x7e9ff9 0x7eaaf7 0x7f15a9 0x7fef83258c4d
./mongod(_ZN5mongo10abruptQuitEi+0x399) [0x7e5759]
/lib/libc.so.6(+0x33af0) [0x7fef8326daf0]
/lib/libc.so.6(memcpy+0x15b) [0x7fef832c0dbb]
./mongod(_ZN5mongo22fillQueryResultFromObjERNS_10BufBuilderEPNS_12FieldMatcherERNS_7BSONObjEPNS_7DiskLocE+0xbff) [0x5ef0af]
./mongod(_ZN5mongo14processGetMoreEPKcixRNS_5CurOpEiRb+0x393) [0x5dae53]
./mongod(_ZN5mongo15receivedGetMoreERNS_10DbResponseERNS_7MessageERNS_5CurOpE+0x29e) [0x6d7bfe]
./mongod(_ZN5mongo16assembleResponseERNS_7MessageERNS_10DbResponseERKNS_8SockAddrE+0x1309) [0x6da2b9]
./mongod(_ZN5mongo14DBDirectClient4callERNS_7MessageES2_b+0x81) [0x6daed1]
./mongod(_ZN5mongo14DBClientCursor11requestMoreEv+0x2fd) [0x561fcd]
./mongod(_ZN5mongo14DBClientCursor4moreEv+0x58) [0x562508]
./mongod(_ZN5mongo6Cloner4copyEPKcS2_bbbbNS_5QueryE+0x5b4) [0x69c8a4]
./mongod(_ZN5mongo6Cloner2goEPKcRSsRKSsbbbb+0xe88) [0x69f208]
./mongod(_ZN5mongo9cloneFromEPKcRSsRKSsbbbb+0x3d) [0x6a0c4d]
./mongod(_ZN5mongo14repairDatabaseESsRSsbb+0x3eb) [0x6fd4cb]
./mongod(_ZN5mongo11doDBUpgradeERKSsSsPNS_14DataFileHeaderE+0x68) [0x7e5dd8]
./mongod(_ZN5mongo15repairDatabasesEv+0x28d) [0x7e91dd]
./mongod(_ZN5mongo14_initAndListenEiPKc+0x509) [0x7e9ff9]
./mongod(_ZN5mongo13initAndListenEiPKc+0x27) [0x7eaaf7]
./mongod(main+0x6779) [0x7f15a9]
/lib/libc.so.6(__libc_start_main+0xfd) [0x7fef83258c4d]

Tue Jul 27 17:26:41 dbexit:

[initandlisten] Tue Jul 27 17:26:41 shutdown: going to close listening sockets...
[initandlisten] Tue Jul 27 17:26:41 shutdown: going to flush oplog...
[initandlisten] Tue Jul 27 17:26:41 shutdown: going to close sockets...
[initandlisten] Tue Jul 27 17:26:41 shutdown: waiting for fs preallocator...
[initandlisten] Tue Jul 27 17:26:41 shutdown: closing all files...
Tue Jul 27 17:26:41 closeAllFiles() finished

[initandlisten] Tue Jul 27 17:26:41 shutdown: removing fs lock...
Tue Jul 27 17:26:41 dbexit: really exiting now

ERROR: Client::~Client _context should be NULL: initandlisten

Comment by Eliot Horowitz (Inactive) [ 27/Jul/10 ]

Can you attach how you reproduce? Can move to a SUPPORT case if its private.

Comment by Doug Hudson [ 27/Jul/10 ]

With a fresh dbpath, the original error has appeared again. This time on another collection.

[conn456] Tue Jul 27 17:03:20 building new index on

{ journal: 1 }

for pubmed.articles
[conn456] Tue Jul 27 17:03:20 Buildindex pubmed.articles idxNo:1 { ns: "pubmed.articles", name: "journal_1", key:

{ journal: 1 }

}
Tue Jul 27 17:04:00 Got signal: 7 (Bus error).

Tue Jul 27 17:04:00 Backtrace:
0x7e5759 0x7fbc1062eaf0 0x4d0fe7 0x5a7bb0 0x5a954a 0x6f1a51 0x6f303b 0x6f532a 0x6f6d2a 0x6d6b89 0x6da3c2 0x7e7ecb 0x7fa960 0x7fbc111329ca 0x7fbc106e16fd
./mongod(_ZN5mongo10abruptQuitEi+0x399) [0x7e5759]
/lib/libc.so.6(+0x33af0) [0x7fbc1062eaf0]
./mongod(_ZNK5mongo7BSONObj21getFieldDottedOrArrayERPKc+0xb7) [0x4d0fe7]
./mongod(_ZNK5mongo9IndexSpec8_getKeysESt6vectorIPKcSaIS3_EES1_INS_11BSONElementESaIS6_EERKNS_7BSONObjERSt3setIS9_NS_22BSONObjCmpDefaultOrderESaIS9_EE+0x80) [0x5a7bb0]
./mongod(_ZNK5mongo9IndexSpec7getKeysERKNS_7BSONObjERSt3setIS1_NS_22BSONObjCmpDefaultOrderESaIS1_EE+0x2ea) [0x5a954a]
./mongod(_ZN5mongo14fastBuildIndexEPKcPNS_16NamespaceDetailsERNS_12IndexDetailsEi+0x5a1) [0x6f1a51]
./mongod() [0x6f303b]
./mongod(_ZN5mongo11DataFileMgr6insertEPKcPKvibRKNS_11BSONElementEb+0x9da) [0x6f532a]
./mongod(_ZN5mongo11DataFileMgr16insertWithObjModEPKcRNS_7BSONObjEb+0x5a) [0x6f6d2a]
./mongod(_ZN5mongo14receivedInsertERNS_7MessageERNS_5CurOpE+0x319) [0x6d6b89]
./mongod(_ZN5mongo16assembleResponseERNS_7MessageERNS_10DbResponseERKNS_8SockAddrE+0x1412) [0x6da3c2]
./mongod(_ZN5mongo10connThreadEv+0x31b) [0x7e7ecb]
./mongod(thread_proxy+0x80) [0x7fa960]
/lib/libpthread.so.0(+0x69ca) [0x7fbc111329ca]
/lib/libc.so.6(clone+0x6d) [0x7fbc106e16fd]

Tue Jul 27 17:04:00 dbexit:

[conn456] Tue Jul 27 17:04:00 shutdown: going to close listening sockets...
[conn456] Tue Jul 27 17:04:00 going to close listening socket: 5
[conn456] Tue Jul 27 17:04:00 going to close listening socket: 6
[conn456] Tue Jul 27 17:04:00 going to close listening socket: 7
[conn456] Tue Jul 27 17:04:00 going to close listening socket: 8
[conn456] Tue Jul 27 17:04:00 shutdown: going to flush oplog...
[conn456] Tue Jul 27 17:04:00 shutdown: going to close sockets...
[conn456] Tue Jul 27 17:04:00 shutdown: waiting for fs preallocator...
[conn456] Tue Jul 27 17:04:00 shutdown: closing all files...
Tue Jul 27 17:04:02 closeAllFiles() finished

[conn456] Tue Jul 27 17:04:02 shutdown: removing fs lock...
Tue Jul 27 17:04:02 dbexit: really exiting now

ERROR: Client::~Client _context should be NULL: conn

Comment by Doug Hudson [ 27/Jul/10 ]

The socket exceptions seem to be a logging bug, so ignoring those.

As for my problem, I think we'll have to assume it had a mare and left it in a bad state. Not wanting to risk some corruption in a 150GB database I am going to do a fresh reload. Time consuming but I need to sleep safely.

Comment by Eliot Horowitz (Inactive) [ 27/Jul/10 ]

Should be able to repair if you can move files to a machine with more space.

Comment by Doug Hudson [ 27/Jul/10 ]

Server crash, perhaps due to the disk space. Not sure this is the desired effect though.

I think it looks like I need to restart from scratch with this database.

> ./mongod -dbpath ../../mongo-data/ --directoryperdb --slowms 0 --repair
Tue Jul 27 15:36:47 MongoDB starting : pid=17462 port=27017 dbpath=../../mongo-data/ 64-bit

    • NOTE: This is a development version (1.5.6) of MongoDB.
    • Not recommended for production.

Tue Jul 27 15:36:47 db version v1.5.6, pdfile version 4.5
Tue Jul 27 15:36:47 git version: 39cdcd202f6377e95f30685098ce14c579670d45
Tue Jul 27 15:36:47 sys info: Linux domU-12-31-39-06-79-A1 2.6.21.7-2.ec2.v1.2.fc8xen #1 SMP Fri Nov 20 17:48:28 EST 2009 x86_64 BOOST_LIB_VERSION=1_41
[initandlisten] Tue Jul 27 15:36:47 ****
[initandlisten] Tue Jul 27 15:36:47 ****
[initandlisten] Tue Jul 27 15:36:47 need to upgrade database pubmed_web with pdfile version 4.5, new version: 4.5
[initandlisten] Tue Jul 27 15:36:47 starting upgrade
[initandlisten] Tue Jul 27 15:36:47 pubmed_web repairDatabase pubmed_web
Tue Jul 27 15:36:47 allocating new datafile ../../mongo-data/$tmp_repairDatabase_0/pubmed_web/pubmed_web.ns, filling with zeroes...
Tue Jul 27 15:36:47 done allocating datafile ../../mongo-data/$tmp_repairDatabase_0/pubmed_web/pubmed_web.ns, size: 16MB, took 0 secs
Tue Jul 27 15:36:47 allocating new datafile ../../mongo-data/$tmp_repairDatabase_0/pubmed_web/pubmed_web.0, filling with zeroes...
Tue Jul 27 15:36:47 done allocating datafile ../../mongo-data/$tmp_repairDatabase_0/pubmed_web/pubmed_web.0, size: 64MB, took 0.03 secs
Tue Jul 27 15:36:47 allocating new datafile ../../mongo-data/$tmp_repairDatabase_0/pubmed_web/pubmed_web.1, filling with zeroes...
Tue Jul 27 15:36:47 done allocating datafile ../../mongo-data/$tmp_repairDatabase_0/pubmed_web/pubmed_web.1, size: 128MB, took 0 secs
[initandlisten] Tue Jul 27 15:36:47 building new index on

{ _id: 1 }

for pubmed_web.universes
[initandlisten] Tue Jul 27 15:36:47 Buildindex pubmed_web.universes idxNo:0 { name: "id", ns: "pubmed_web.universes", key:

{ _id: 1 }

}
[initandlisten] Tue Jul 27 15:36:47 done for 4 records 0.001secs
[initandlisten] Tue Jul 27 15:36:47 ****
[initandlisten] Tue Jul 27 15:36:47 ****
[initandlisten] Tue Jul 27 15:36:47 need to upgrade database pubmed with pdfile version 4.5, new version: 4.5
[initandlisten] Tue Jul 27 15:36:47 starting upgrade
[initandlisten] Tue Jul 27 15:36:47 pubmed repairDatabase pubmed
[initandlisten] Tue Jul 27 15:36:47 pubmed Cannot repair database pubmed having size: 150201171968 (bytes) because free disk space is: 71721971712 (bytes)
[initandlisten] Tue Jul 27 15:36:47 pubmed Assertion failure doDBUpgrade( dbName , errmsg , h ) db/db.cpp 418
0x528b33 0x53422f 0x7e91f9 0x7e9ff9 0x7eaaf7 0x7f15a9 0x7fe681b0bc4d 0x4c4fb9
./mongod(_ZN5mongo12sayDbContextEPKc+0xb3) [0x528b33]
./mongod(_ZN5mongo8assertedEPKcS1_j+0x10f) [0x53422f]
./mongod(_ZN5mongo15repairDatabasesEv+0x2a9) [0x7e91f9]
./mongod(_ZN5mongo14_initAndListenEiPKc+0x509) [0x7e9ff9]
./mongod(_ZN5mongo13initAndListenEiPKc+0x27) [0x7eaaf7]
./mongod(main+0x6779) [0x7f15a9]
/lib/libc.so.6(__libc_start_main+0xfd) [0x7fe681b0bc4d]
./mongod(__gxx_personality_v0+0x3a9) [0x4c4fb9]
[initandlisten] Tue Jul 27 15:36:47 exception in initAndListen std::exception: assertion db/db.cpp:418, terminating
Tue Jul 27 15:36:47 dbexit:

[initandlisten] Tue Jul 27 15:36:47 shutdown: going to close listening sockets...
[initandlisten] Tue Jul 27 15:36:47 shutdown: going to flush oplog...
[initandlisten] Tue Jul 27 15:36:47 shutdown: going to close sockets...
[initandlisten] Tue Jul 27 15:36:47 shutdown: waiting for fs preallocator...
[initandlisten] Tue Jul 27 15:36:47 shutdown: closing all files...
Tue Jul 27 15:36:47 closeAllFiles() finished

[initandlisten] Tue Jul 27 15:36:47 shutdown: removing fs lock...
Tue Jul 27 15:36:47 dbexit: really exiting now

Comment by Eliot Horowitz (Inactive) [ 27/Jul/10 ]

You should do a --repair with 1.5.6.
1.5.4 probably left things in a bad state.

Comment by Doug Hudson [ 27/Jul/10 ]

Now using ruby driver 1.0.6 and server 1.5.6.

This is now happening during mongoimport, for the same collection as before.

Seeing a lot of these "9001 socket exception" messages.

There should also be a lot more inserts going on. Each file passed to mongoimport has 700k to 1m rows.

Tue Jul 27 15:24:08 MongoDB starting : pid=6181 port=27017 dbpath=../../mongo-data/ 64-bit

    • NOTE: This is a development version (1.5.6) of MongoDB.
    • Not recommended for production.

Tue Jul 27 15:24:08 db version v1.5.6, pdfile version 4.5
Tue Jul 27 15:24:08 git version: 39cdcd202f6377e95f30685098ce14c579670d45
Tue Jul 27 15:24:08 sys info: Linux domU-12-31-39-06-79-A1 2.6.21.7-2.ec2.v1.2.fc8xen #1 SMP Fri Nov 20 17:48:28 EST 2009 x86_64 BOOST_LIB_VERSION=1_41
[initandlisten] Tue Jul 27 15:24:08 waiting for connections on port 27017
[websvr] Tue Jul 27 15:24:08 web admin interface listening on port 28017
[initandlisten] Tue Jul 27 15:24:19 connection accepted from 127.0.0.1:60597 #1
[initandlisten] Tue Jul 27 15:24:19 connection accepted from 127.0.0.1:60598 #2
[conn1] Tue Jul 27 15:24:19 SocketException: 9001 socket exception
[conn1] Tue Jul 27 15:24:19 end connection 127.0.0.1:60597
[conn2] Tue Jul 27 15:24:19 CMD: drop pubmed.author_score
[conn2] Tue Jul 27 15:24:19 query pubmed.$cmd ntoreturn:1 command:

{ drop: "author_score" }

reslen:142 1ms
[conn2] Tue Jul 27 15:24:19 SocketException: 9001 socket exception
[conn2] Tue Jul 27 15:24:19 end connection 127.0.0.1:60598
[initandlisten] Tue Jul 27 15:24:27 connection accepted from 127.0.0.1:60604 #3
[conn3] Tue Jul 27 15:24:27 SocketException: 9001 socket exception
[conn3] Tue Jul 27 15:24:27 end connection 127.0.0.1:60604
[initandlisten] Tue Jul 27 15:24:27 connection accepted from 127.0.0.1:60605 #4
[conn4] Tue Jul 27 15:24:27 building new index on

{ _id: 1 }

for pubmed.author_score
[conn4] Tue Jul 27 15:24:27 Buildindex pubmed.author_score idxNo:0 { name: "id", ns: "pubmed.author_score", key:

{ _id: 1 }

}
[conn4] Tue Jul 27 15:24:27 done for 0 records 0secs
[conn4] Tue Jul 27 15:24:30 insert pubmed.author_score 1ms
[conn4] Tue Jul 27 15:24:31 insert pubmed.author_score 2ms
[conn4] Tue Jul 27 15:25:09 insert pubmed.author_score 5ms
[conn4] Tue Jul 27 15:25:09 insert pubmed.author_score 3ms
[conn4] Tue Jul 27 15:25:09 insert pubmed.author_score 2ms
[conn4] Tue Jul 27 15:25:18 SocketException: 9001 socket exception
[conn4] Tue Jul 27 15:25:18 end connection 127.0.0.1:60605
[initandlisten] Tue Jul 27 15:25:18 connection accepted from 127.0.0.1:60630 #5
[conn5] Tue Jul 27 15:25:18 SocketException: 9001 socket exception
[conn5] Tue Jul 27 15:25:18 end connection 127.0.0.1:60630
[initandlisten] Tue Jul 27 15:25:22 connection accepted from 127.0.0.1:60633 #6
[conn6] Tue Jul 27 15:25:22 SocketException: 9001 socket exception
[conn6] Tue Jul 27 15:25:22 end connection 127.0.0.1:60633
[initandlisten] Tue Jul 27 15:25:22 connection accepted from 127.0.0.1:60634 #7
[conn7] Tue Jul 27 15:25:25 insert pubmed.author_score 2ms
[conn7] Tue Jul 27 15:25:26 insert pubmed.author_score 3ms
[conn7] Tue Jul 27 15:25:30 insert pubmed.author_score 2ms
[conn7] Tue Jul 27 15:25:30 insert pubmed.author_score 1ms
[conn7] Tue Jul 27 15:25:30 insert pubmed.author_score 2ms
[conn7] Tue Jul 27 15:25:31 insert pubmed.author_score 2ms
[conn7] Tue Jul 27 15:25:35 insert pubmed.author_score 4ms
[conn7] Tue Jul 27 15:25:36 insert pubmed.author_score 1ms
[conn7] Tue Jul 27 15:25:40 insert pubmed.author_score 1ms
[conn7] Tue Jul 27 15:25:40 insert pubmed.author_score 2ms
[conn7] Tue Jul 27 15:25:40 insert pubmed.author_score 1ms
[conn7] Tue Jul 27 15:25:40 insert pubmed.author_score 1ms
[conn7] Tue Jul 27 15:25:40 insert pubmed.author_score 1ms
[conn7] Tue Jul 27 15:25:40 insert pubmed.author_score 2ms
[conn7] Tue Jul 27 15:25:40 insert pubmed.author_score 1ms
[conn7] Tue Jul 27 15:25:40 insert pubmed.author_score 1ms
[conn7] Tue Jul 27 15:25:40 insert pubmed.author_score 1ms
[conn7] Tue Jul 27 15:25:40 insert pubmed.author_score 1ms
[conn7] Tue Jul 27 15:25:40 insert pubmed.author_score 1ms
[conn7] Tue Jul 27 15:25:40 insert pubmed.author_score 1ms
[conn7] Tue Jul 27 15:25:40 insert pubmed.author_score 1ms
[conn7] Tue Jul 27 15:25:40 insert pubmed.author_score 1ms
[conn7] Tue Jul 27 15:25:40 insert pubmed.author_score 1ms
[conn7] Tue Jul 27 15:25:40 insert pubmed.author_score 1ms
[conn7] Tue Jul 27 15:25:40 insert pubmed.author_score 1ms
[conn7] Tue Jul 27 15:25:41 insert pubmed.author_score 2ms
[conn7] Tue Jul 27 15:25:41 insert pubmed.author_score 1ms
[conn7] Tue Jul 27 15:25:41 insert pubmed.author_score 1ms
[conn7] Tue Jul 27 15:25:41 insert pubmed.author_score 1ms
[conn7] Tue Jul 27 15:25:41 insert pubmed.author_score 1ms
[conn7] Tue Jul 27 15:25:49 SocketException: 9001 socket exception
[conn7] Tue Jul 27 15:25:49 end connection 127.0.0.1:60634
[initandlisten] Tue Jul 27 15:25:49 connection accepted from 127.0.0.1:60647 #8
[conn8] Tue Jul 27 15:25:49 SocketException: 9001 socket exception
[conn8] Tue Jul 27 15:25:49 end connection 127.0.0.1:60647
[initandlisten] Tue Jul 27 15:25:54 connection accepted from 127.0.0.1:60651 #9
[conn9] Tue Jul 27 15:25:54 SocketException: 9001 socket exception
[conn9] Tue Jul 27 15:25:54 end connection 127.0.0.1:60651
[initandlisten] Tue Jul 27 15:25:54 connection accepted from 127.0.0.1:60652 #10
[conn10] Tue Jul 27 15:25:59 insert pubmed.author_score 4ms
[conn10] Tue Jul 27 15:26:02 insert pubmed.author_score 1ms
[conn10] Tue Jul 27 15:26:02 insert pubmed.author_score 2ms
[conn10] Tue Jul 27 15:26:03 insert pubmed.author_score 1ms
[conn10] Tue Jul 27 15:26:09 insert pubmed.author_score 1ms
[conn10] Tue Jul 27 15:26:09 insert pubmed.author_score 1ms
[conn10] Tue Jul 27 15:26:22 insert pubmed.author_score 4ms
[conn10] Tue Jul 27 15:26:22 insert pubmed.author_score 1ms
[conn10] Tue Jul 27 15:26:22 insert pubmed.author_score 1ms
[conn10] Tue Jul 27 15:26:22 insert pubmed.author_score 1ms
[conn10] Tue Jul 27 15:26:22 insert pubmed.author_score 1ms
[conn10] Tue Jul 27 15:26:33 SocketException: 9001 socket exception
[conn10] Tue Jul 27 15:26:33 end connection 127.0.0.1:60652
[initandlisten] Tue Jul 27 15:26:33 connection accepted from 127.0.0.1:49992 #11
[conn11] Tue Jul 27 15:26:33 SocketException: 9001 socket exception
[conn11] Tue Jul 27 15:26:33 end connection 127.0.0.1:49992
[initandlisten] Tue Jul 27 15:26:36 connection accepted from 127.0.0.1:49995 #12
[conn12] Tue Jul 27 15:26:36 SocketException: 9001 socket exception
[conn12] Tue Jul 27 15:26:36 end connection 127.0.0.1:49995
[initandlisten] Tue Jul 27 15:26:36 connection accepted from 127.0.0.1:49996 #13
[conn13] Tue Jul 27 15:26:37 insert pubmed.author_score 1ms
[conn13] Tue Jul 27 15:26:37 insert pubmed.author_score 1ms
[conn13] Tue Jul 27 15:26:37 insert pubmed.author_score 1ms
[conn13] Tue Jul 27 15:26:37 insert pubmed.author_score 1ms
[conn13] Tue Jul 27 15:26:37 insert pubmed.author_score 1ms
[conn13] Tue Jul 27 15:26:37 insert pubmed.author_score 1ms
[conn13] Tue Jul 27 15:26:38 insert pubmed.author_score 1ms
[conn13] Tue Jul 27 15:26:40 insert pubmed.author_score 1ms
[conn13] Tue Jul 27 15:26:40 insert pubmed.author_score 1ms
[conn13] Tue Jul 27 15:26:45 insert pubmed.author_score 1ms
[conn13] Tue Jul 27 15:26:53 insert pubmed.author_score 2ms
[conn13] Tue Jul 27 15:26:53 insert pubmed.author_score 4ms
Tue Jul 27 15:27:09 Got signal: 7 (Bus error).

Tue Jul 27 15:27:09 Backtrace:
0x7e5759 0x7f0cf443daf0 0x6aabc1 0x6f4e6e 0x611159 0x619c80 0x618b19 0x618f9c 0x618a01 0x618f9c 0x618a01 0x618f9c 0x6ed6f0 0x6f58d2 0x6f6d2a 0x6d6b89 0x6da3c2 0x7e7ecb 0x7fa960 0x7f0cf4f419ca
./mongod(_ZN5mongo10abruptQuitEi+0x399) [0x7e5759]
/lib/libc.so.6(+0x33af0) [0x7f0cf443daf0]
./mongod(_ZN5mongo16NamespaceDetails5allocEPKciRNS_7DiskLocE+0x181) [0x6aabc1]
./mongod(_ZN5mongo11DataFileMgr6insertEPKcPKvibRKNS_11BSONElementEb+0x51e) [0x6f4e6e]
./mongod(_ZN5mongo11BtreeBucket9addBucketERNS_12IndexDetailsE+0x69) [0x611159]
./mongod(_ZN5mongo11BtreeBucket10insertHereENS_7DiskLocEiS1_RKNS_7BSONObjERKNS_8OrderingES1_S1_RNS_12IndexDetailsE+0x4f0) [0x619c80]
./mongod(_ZN5mongo11BtreeBucket7_insertENS_7DiskLocES1_RKNS_7BSONObjERKNS_8OrderingEbS1_S1_RNS_12IndexDetailsE+0x2a9) [0x618b19]
./mongod(_ZN5mongo11BtreeBucket9bt_insertENS_7DiskLocES1_RKNS_7BSONObjERKNS_8OrderingEbRNS_12IndexDetailsEb+0xbc) [0x618f9c]
./mongod(_ZN5mongo11BtreeBucket7_insertENS_7DiskLocES1_RKNS_7BSONObjERKNS_8OrderingEbS1_S1_RNS_12IndexDetailsE+0x191) [0x618a01]
./mongod(_ZN5mongo11BtreeBucket9bt_insertENS_7DiskLocES1_RKNS_7BSONObjERKNS_8OrderingEbRNS_12IndexDetailsEb+0xbc) [0x618f9c]
./mongod(_ZN5mongo11BtreeBucket7_insertENS_7DiskLocES1_RKNS_7BSONObjERKNS_8OrderingEbS1_S1_RNS_12IndexDetailsE+0x191) [0x618a01]
./mongod(_ZN5mongo11BtreeBucket9bt_insertENS_7DiskLocES1_RKNS_7BSONObjERKNS_8OrderingEbRNS_12IndexDetailsEb+0xbc) [0x618f9c]
./mongod() [0x6ed6f0]
./mongod(_ZN5mongo11DataFileMgr6insertEPKcPKvibRKNS_11BSONElementEb+0xf82) [0x6f58d2]
./mongod(_ZN5mongo11DataFileMgr16insertWithObjModEPKcRNS_7BSONObjEb+0x5a) [0x6f6d2a]
./mongod(_ZN5mongo14receivedInsertERNS_7MessageERNS_5CurOpE+0x319) [0x6d6b89]
./mongod(_ZN5mongo16assembleResponseERNS_7MessageERNS_10DbResponseERKNS_8SockAddrE+0x1412) [0x6da3c2]
./mongod(_ZN5mongo10connThreadEv+0x31b) [0x7e7ecb]
./mongod(thread_proxy+0x80) [0x7fa960]
/lib/libpthread.so.0(+0x69ca) [0x7f0cf4f419ca]

Tue Jul 27 15:27:09 dbexit:

[conn13] Tue Jul 27 15:27:09 shutdown: going to close listening sockets...
[conn13] Tue Jul 27 15:27:09 going to close listening socket: 5
[conn13] Tue Jul 27 15:27:09 going to close listening socket: 6
[conn13] Tue Jul 27 15:27:09 going to close listening socket: 7
[conn13] Tue Jul 27 15:27:09 going to close listening socket: 8
[conn13] Tue Jul 27 15:27:09 shutdown: going to flush oplog...
[conn13] Tue Jul 27 15:27:09 shutdown: going to close sockets...
[conn13] Tue Jul 27 15:27:09 shutdown: waiting for fs preallocator...
[conn13] Tue Jul 27 15:27:09 shutdown: closing all files...
Tue Jul 27 15:27:11 closeAllFiles() finished

[conn13] Tue Jul 27 15:27:11 shutdown: removing fs lock...
Tue Jul 27 15:27:11 dbexit: really exiting now

ERROR: Client::~Client _context should be NULL: conn

Comment by Eliot Horowitz (Inactive) [ 27/Jul/10 ]

Can you attach entire log?

I'm fairly sure 1.5.4 had some issues.

Comment by Doug Hudson [ 27/Jul/10 ]

After first failure (second stack above) attempting to recreate the index resulted in:
[conn1] Tue Jul 27 14:46:31 error: have index [pubmed.author_score.$author_1_year_-1] but no NamespaceDetails

Collection was dropped before second attempt.

Comment by Eliot Horowitz (Inactive) [ 27/Jul/10 ]

Can you try 1.5.6?
When using dev branch - should stay on current.

Generated at Thu Feb 08 02:57:12 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.