[SERVER-12706] mongorestore'ing auth data causes assertion failure + crash Created: 12/Feb/14  Updated: 10/Dec/14  Resolved: 20/Feb/14

Status: Closed
Project: Core Server
Component/s: Security, Tools
Affects Version/s: 2.5.5
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: Michael O'Brien Assignee: Michael O'Brien
Resolution: Done Votes: 0
Labels: 26qa
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Attachments: File dumprestore_auth_repl.js    
Issue Links:
Related
Operating System: ALL
Participants:

 Description   

Procedure:

  • start up a repl set on 2.4 (source)
  • start up a repl set on 2.6 (target)
  • create a bunch of users in the source db
  • run mongodump from the source db
  • run mongorestore (as __system) to restore the data into the target db by using --host (target DB url)

Running mongodump from source database (2.4) using mongodump version: 2.6
2014-02-12T15:48:22.500-0500 shell: started program mongodump-2.6 --host testReplSet/Michaels-MacBook-Pro.local:40000,Michaels-MacBook-Pro.local:40001,Michaels-MacBook-Pro.local:40002 --authenticationDatabase admin --username user --password pwd
sh26322| 2014-02-12T15:48:22.522-0500 starting new replica set monitor for replica set testReplSet with seed of Michaels-MacBook-Pro.local:40000,Michaels-MacBook-Pro.local:40001,Michaels-MacBook-Pro.local:40002
sh26322| 2014-02-12T15:48:22.523-0500 successfully connected to seed Michaels-MacBook-Pro.local:40000 for replica set testReplSet
 m40000| 2014-02-12T15:48:22.523-0500 [initandlisten] connection accepted from 10.4.122.245:58542 #14 (8 connections now open)
sh26322| 2014-02-12T15:48:22.524-0500 changing hosts to { 0: "Michaels-MacBook-Pro.local:40000", 1: "Michaels-MacBook-Pro.local:40002", 2: "Michaels-MacBook-Pro.local:40001" } from testReplSet/
sh26322| 2014-02-12T15:48:22.524-0500 trying to add new host Michaels-MacBook-Pro.local:40000 to replica set testReplSet
 m40000| 2014-02-12T15:48:22.524-0500 [initandlisten] connection accepted from 10.4.122.245:58543 #15 (9 connections now open)
sh26322| 2014-02-12T15:48:22.524-0500 successfully connected to new host Michaels-MacBook-Pro.local:40000 in replica set testReplSet
sh26322| 2014-02-12T15:48:22.524-0500 trying to add new host Michaels-MacBook-Pro.local:40001 to replica set testReplSet
sh26322| 2014-02-12T15:48:22.524-0500 successfully connected to new host Michaels-MacBook-Pro.local:40001 in replica set testReplSet
Running mongorestore to target database (2.6) using mongorestore version: 2.6
 m40001| 2014-02-12T15:48:22.524-0500 [initandlisten] connection accepted from 10.4.122.245:58544 #6 (4 connections now open)
 m40002| 2014-02-12T15:48:22.525-0500 [initandlisten] connection accepted from 10.4.122.245:58545 #6 (4 connections now open)
 m40000| 2014-02-12T15:48:22.525-0500 [conn14] end connection 10.4.122.245:58542 (8 connections now open)
sh26322| 2014-02-12T15:48:22.524-0500 trying to add new host Michaels-MacBook-Pro.local:40002 to replica set testReplSet
sh26322| 2014-02-12T15:48:22.525-0500 successfully connected to new host Michaels-MacBook-Pro.local:40002 in replica set testReplSet
sh26322| 2014-02-12T15:48:22.525-0500 Primary for replica set testReplSet changed to Michaels-MacBook-Pro.local:40000
sh26322| 2014-02-12T15:48:22.525-0500 replica set monitor for replica set testReplSet started, address is testReplSet/Michaels-MacBook-Pro.local:40000,Michaels-MacBook-Pro.local:40001,Michaels-MacBook-Pro.local:40002
sh26322| 2014-02-12T15:48:22.525-0500 [ReplicaSetMonitorWatcher] starting
sh26322| connected to: testReplSet/Michaels-MacBook-Pro.local:40000,Michaels-MacBook-Pro.local:40001,Michaels-MacBook-Pro.local:40002
sh26322| 2014-02-12T15:48:22.528-0500 all dbs
sh26322| 2014-02-12T15:48:22.528-0500 DATABASE: admin	 to 	dump/admin
 m40001| 2014-02-12T15:48:22.526-0500 [initandlisten] connection accepted from 10.4.122.245:58547 #7 (5 connections now open)
 m40001| 2014-02-12T15:48:22.527-0500 [conn7]  authenticate db: admin { authenticate: 1, nonce: "xxx", user: "user", key: "xxx" }
 m40001| 2014-02-12T15:48:22.532-0500 [conn7] end connection 10.4.122.245:58547 (4 connections now open)
 m40001| 2014-02-12T15:48:22.532-0500 [conn6] end connection 10.4.122.245:58544 (4 connections now open)
 m40000| 2014-02-12T15:48:22.526-0500 [initandlisten] connection accepted from 10.4.122.245:58546 #16 (9 connections now open)
 m40000| 2014-02-12T15:48:22.526-0500 [conn16]  authenticate db: admin { authenticate: 1, nonce: "xxx", user: "user", key: "xxx" }
 m40000| 2014-02-12T15:48:22.532-0500 [conn15] end connection 10.4.122.245:58543 (8 connections now open)
 m40000| 2014-02-12T15:48:22.532-0500 [conn16] end connection 10.4.122.245:58546 (7 connections now open)
 m40002| 2014-02-12T15:48:22.532-0500 [conn6] end connection 10.4.122.245:58545 (3 connections now open)
sh26322| 2014-02-12T15:48:22.528-0500 	admin.system.indexes to dump/admin/system.indexes.bson
sh26322| 2014-02-12T15:48:22.528-0500 		 3 objects
sh26322| 2014-02-12T15:48:22.529-0500 	admin.system.version to dump/admin/system.version.bson
sh26322| 2014-02-12T15:48:22.529-0500 		 1 objects
sh26322| 2014-02-12T15:48:22.529-0500 	Metadata for admin.system.version to dump/admin/system.version.metadata.json
sh26322| 2014-02-12T15:48:22.529-0500 	admin.system.users to dump/admin/system.users.bson
sh26322| 2014-02-12T15:48:22.529-0500 		 10 objects
sh26322| 2014-02-12T15:48:22.529-0500 	Metadata for admin.system.users to dump/admin/system.users.metadata.json
2014-02-12T15:48:22.557-0500 shell: started program mongorestore-2.6 --host testReplSet/Michaels-MacBook-Pro.local:50000,Michaels-MacBook-Pro.local:50001,Michaels-MacBook-Pro.local:50002 --username __system --password abcdefghijklmnopqrstuvwxyz --authenticationDatabase local
sh26323| 2014-02-12T15:48:22.578-0500 starting new replica set monitor for replica set testReplSet with seed of Michaels-MacBook-Pro.local:50000,Michaels-MacBook-Pro.local:50001,Michaels-MacBook-Pro.local:50002
 m50000| 2014-02-12T15:48:22.579-0500 [initandlisten] connection accepted from 10.4.122.245:58548 #14 (8 connections now open)
sh26323| 2014-02-12T15:48:22.579-0500 successfully connected to seed Michaels-MacBook-Pro.local:50000 for replica set testReplSet
sh26323| 2014-02-12T15:48:22.579-0500 changing hosts to { 0: "Michaels-MacBook-Pro.local:50000", 1: "Michaels-MacBook-Pro.local:50002", 2: "Michaels-MacBook-Pro.local:50001" } from testReplSet/
sh26323| 2014-02-12T15:48:22.579-0500 trying to add new host Michaels-MacBook-Pro.local:50000 to replica set testReplSet
 m50000| 2014-02-12T15:48:22.580-0500 [initandlisten] connection accepted from 10.4.122.245:58549 #15 (9 connections now open)
sh26323| 2014-02-12T15:48:22.580-0500 successfully connected to new host Michaels-MacBook-Pro.local:50000 in replica set testReplSet
sh26323| 2014-02-12T15:48:22.580-0500 trying to add new host Michaels-MacBook-Pro.local:50001 to replica set testReplSet
sh26323| 2014-02-12T15:48:22.580-0500 successfully connected to new host Michaels-MacBook-Pro.local:50001 in replica set testReplSet
 m50001| 2014-02-12T15:48:22.580-0500 [initandlisten] connection accepted from 10.4.122.245:58550 #5 (4 connections now open)
sh26323| 2014-02-12T15:48:22.580-0500 trying to add new host Michaels-MacBook-Pro.local:50002 to replica set testReplSet
sh26323| 2014-02-12T15:48:22.581-0500 successfully connected to new host Michaels-MacBook-Pro.local:50002 in replica set testReplSet
 m50002| 2014-02-12T15:48:22.581-0500 [initandlisten] connection accepted from 10.4.122.245:58551 #4 (4 connections now open)
 m50000| 2014-02-12T15:48:22.581-0500 [conn14] end connection 10.4.122.245:58548 (8 connections now open)
sh26323| 2014-02-12T15:48:22.581-0500 Primary for replica set testReplSet changed to Michaels-MacBook-Pro.local:50000
sh26323| 2014-02-12T15:48:22.581-0500 replica set monitor for replica set testReplSet started, address is testReplSet/Michaels-MacBook-Pro.local:50000,Michaels-MacBook-Pro.local:50001,Michaels-MacBook-Pro.local:50002
sh26323| 2014-02-12T15:48:22.581-0500 [ReplicaSetMonitorWatcher] starting
sh26323| connected to: testReplSet/Michaels-MacBook-Pro.local:50000,Michaels-MacBook-Pro.local:50001,Michaels-MacBook-Pro.local:50002
 m50000| 2014-02-12T15:48:22.581-0500 [initandlisten] connection accepted from 10.4.122.245:58552 #16 (9 connections now open)
 m50000| 2014-02-12T15:48:22.582-0500 [conn16]  authenticate db: local { authenticate: 1, nonce: "xxx", user: "__system", key: "xxx" }
 m50001| 2014-02-12T15:48:22.582-0500 [initandlisten] connection accepted from 10.4.122.245:58553 #6 (5 connections now open)
 m50001| 2014-02-12T15:48:22.582-0500 [conn6]  authenticate db: local { authenticate: 1, nonce: "xxx", user: "__system", key: "xxx" }
sh26323| 2014-02-12T15:48:22.582-0500 dump/admin/system.users.bson
sh26323| 2014-02-12T15:48:22.582-0500 	going into namespace [admin.system.users]
sh26323| 10 objects found
sh26323| 2014-02-12T15:48:22.583-0500 	Creating index: { unique: true, key: { user: 1, db: 1 }, name: "user_1_db_1", ns: "admin.system.users" }
 m50000| 2014-02-12T15:48:22.584-0500 [conn16] uh oh: 0
 m50000| 2014-02-12T15:48:22.584-0500 [conn16] admin.system.users Assertion failure n >= 0 && n < static_cast<int>(_files.size()) src/mongo/db/storage/extent_manager.cpp 112
 m50000| 2014-02-12T15:48:22.588-0500 [conn16] admin.system.users 0x10061e23b 0x1005d7652 0x1005c8222 0x100478041 0x100479050 0x1002cd663 0x1002cde2a 0x10049a05f 0x10049a7c1 0x100496c47 0x100497cd5 0x1001abb27 0x1001ab483 0x100275cba 0x100276637 0x10027cd67 0x100007134 0x1005e4811 0x1006526a5 0x7fff8cd00899
 m50000|  0   mongod                              0x000000010061e23b _ZN5mongo15printStackTraceERSo + 43
 m50000|  1   mongod                              0x00000001005d7652 _ZN5mongo10logContextEPKc + 114
 m50000|  2   mongod                              0x00000001005c8222 _ZN5mongo12verifyFailedEPKcS1_j + 274
 m50000|  3   mongod                              0x0000000100478041 _ZNK5mongo13ExtentManager12_getOpenFileEi + 253
 m50000|  4   mongod                              0x0000000100479050 _ZNK5mongo13ExtentManager9recordForERKNS_7DiskLocE + 24
 m50000|  5   mongod                              0x00000001002cd663 _ZN5mongo16NamespaceDetails10__stdAllocEib + 687
 m50000|  6   mongod                              0x00000001002cde2a _ZN5mongo16NamespaceDetails5allocERKNS_10StringDataEi + 64
 m50000|  7   mongod                              0x000000010049a05f _ZN5mongo11RecordStore11allocRecordEii + 93
 m50000|  8   mongod                              0x000000010049a7c1 _ZN5mongo11RecordStore12insertRecordEPKcii + 75
 m50000|  9   mongod                              0x0000000100496c47 _ZN5mongo10Collection15_insertDocumentERKNS_7BSONObjEb + 77
 m50000|  10  mongod                              0x0000000100497cd5 _ZN5mongo10Collection14insertDocumentERKNS_7BSONObjEb + 279
 m50000|  11  mongod                              0x00000001001abb27 _ZN5mongo8Database22_addNamespaceToCatalogERKNS_10StringDataEPKNS_7BSONObjE + 931
 m50000|  12  mongod                              0x00000001001ab483 _ZN5mongo8Database16createCollectionERKNS_10StringDataEbPKNS_7BSONObjEb + 449
 m50000|  13  mongod                              0x0000000100275cba _ZN5mongo14checkAndInsertERNS_6Client7ContextEPKcRNS_7BSONObjE + 1370
 m50000|  14  mongod                              0x0000000100276637 _ZN5mongo14receivedInsertERNS_7MessageERNS_5CurOpE + 1511
 m50000|  15  mongod                              0x000000010027cd67 _ZN5mongo16assembleResponseERNS_7MessageERNS_10DbResponseERKNS_11HostAndPortE + 7479
 m50000|  16  mongod                              0x0000000100007134 _ZN5mongo16MyMessageHandler7processERNS_7MessageEPNS_21AbstractMessagingPortEPNS_9LastErrorE + 308
 m50000|  17  mongod                              0x00000001005e4811 _ZN5mongo17PortMessageServer17handleIncomingMsgEPv + 1681
 m50000|  18  mongod                              0x00000001006526a5 thread_proxy + 229
 m50000|  19  libsystem_pthread.dylib             0x00007fff8cd00899 _pthread_body + 138
 m50000| 2014-02-12T15:48:22.588-0500 [conn16] insert admin.system.users keyUpdates:0 exception: assertion src/mongo/db/storage/extent_manager.cpp:112  5ms
 m50000| 2014-02-12T15:48:22.590-0500 [conn16] build index on: admin.system.users properties: { v: 1, unique: true, key: { user: 1, db: 1 }, name: "user_1_db_1", ns: "admin.system.users" }
 m50000| 2014-02-12T15:48:22.590-0500 [conn16] build index done.  scanned 9 total records. 0 secs
 m50001| 2014-02-12T15:48:22.590-0500 [repl writer worker 1] uh oh: 0
sh26323| 2014-02-12T15:48:22.590-0500 	Creating index: { key: { _id: 1 }, name: "_id_", ns: "admin.system.users" }
 m50001| 2014-02-12T15:48:22.590-0500 [repl writer worker 1] admin.system.users Assertion failure n >= 0 && n < static_cast<int>(_files.size()) src/mongo/db/storage/extent_manager.cpp 112
 m50000| 2014-02-12T15:48:22.590-0500 [conn16] build index on: admin.system.users properties: { v: 1, key: { _id: 1 }, name: "_id_", ns: "admin.system.users" }
 m50000| 2014-02-12T15:48:22.590-0500 [conn16] build index done.  scanned 9 total records. 0 secs
sh26323| 2014-02-12T15:48:22.590-0500 dump/admin/system.version.bson
sh26323| 2014-02-12T15:48:22.590-0500 	going into namespace [admin.system.version]
sh26323| Restoring to admin.system.version without dropping. Restored data will be inserted without raising errors; check your server log
2014-02-12T15:48:22.601-0500  m50002| 2014-02-12T15:48:22.591-0500 [repl writer worker 1] uh oh: 0
DBClientCursor::init call() failed
 m50001| 2014-02-12T15:48:22.594-0500 [conn6] end connection 10.4.122.245:58553 (4 connections now open)
 m50001| 2014-02-12T15:48:22.594-0500 [conn5] end connection 10.4.122.245:58550 (3 connections now open)
 m50000| 2014-02-12T15:48:22.594-0500 [conn15] end connection 10.4.122.245:58549 (8 connections now open)
 m50001| 2014-02-12T15:48:22.596-0500 [repl writer worker 1] admin.system.users 0x10061e23b 0x1005d7652 0x1005c8222 0x100478041 0x100479050 0x1002cd663 0x1002cde2a 0x10049a05f 0x10049a7c1 0x100496c47 0x100497cd5 0x1001abb27 0x1001ab483 0x1002f391f 0x1002f47e9 0x10041613d 0x10044cd48 0x100451453 0x1005d06f6 0x1006526a5
 m50001|  0   mongod                              0x000000010061e23b _ZN5mongo15printStackTraceERSo + 43
sh26323| 1 objects found
sh26323| 2014-02-12T15:48:22.591-0500 	Creating index: { key: { _id: 1 }, name: "_id_", ns: "admin.system.version" }
 m50001|  1   mongod                              0x00000001005d7652 _ZN5mongo10logContextEPKc + 114
 m50001|  2   mongod                              0x00000001005c8222 _ZN5mongo12verifyFailedEPKcS1_j + 274
 m50001|  3   mongod                              0x0000000100478041 _ZNK5mongo13ExtentManager12_getOpenFileEi + 253
 m50001|  4   mongod                              0x0000000100479050 _ZNK5mongo13ExtentManager9recordForERKNS_7DiskLocE + 24
 m50001|  5   mongod                              0x00000001002cd663 _ZN5mongo16NamespaceDetails10__stdAllocEib + 687
 m50001|  6   mongod                              0x00000001002cde2a _ZN5mongo16NamespaceDetails5allocERKNS_10StringDataEi + 64
 m50001|  7   mongod                              0x000000010049a05f _ZN5mongo11RecordStore11allocRecordEii + 93
 m50001|  8   mongod                              0x000000010049a7c1 _ZN5mongo11RecordStore12insertRecordEPKcii + 75
 m50000| 2014-02-12T15:48:22.594-0500 [conn16] end connection 10.4.122.245:58552 (7 connections now open)
 m50000| 2014-02-12T15:48:22.601-0500 [conn13] end connection 10.4.122.245:58541 (6 connections now open)
 m50000| 2014-02-12T15:48:22.601-0500 [conn9] end connection 10.4.122.245:58537 (5 connections now open)
 m50000| 2014-02-12T15:48:22.601-0500 [conn8] end connection 10.4.122.245:58535 (4 connections now open)
 m50001|  9   mongod                              0x0000000100496c47 _ZN5mongo10Collection15_insertDocumentERKNS_7BSONObjEb + 77
 m50001|  10  mongod                              0x0000000100497cd5 _ZN5mongo10Collection14insertDocumentERKNS_7BSONObjEb + 279
 m50001|  11  mongod                              0x00000001001abb27 _ZN5mongo8Database22_addNamespaceToCatalogERKNS_10StringDataEPKNS_7BSONObjE + 931
 m50001|  12  mongod                              0x00000001001ab483 _ZN5mongo8Database16createCollectionERKNS_10StringDataEbPKNS_7BSONObjEb + 449
 m50001|  13  mongod                              0x00000001002f391f _ZN5mongo6updateERKNS_13UpdateRequestEPNS_7OpDebugEPNS_12UpdateDriverE + 9039
 m50001|  14  mongod                              0x00000001002f47e9 _ZN5mongo6updateERKNS_13UpdateRequestEPNS_7OpDebugE + 249
 m50000| 2014-02-12T15:48:22.601-0500 [conn4] end connection 10.4.122.245:58531 (3 connections now open)
 m50001|  15  mongod                              0x000000010041613d _ZN5mongo21applyOperation_inlockERKNS_7BSONObjEbb + 3885
 m50001|  16  mongod                              0x000000010044cd48 _ZN5mongo7replset8SyncTail9syncApplyERKNS_7BSONObjEb + 712
 m50001|  17  mongod                              0x0000000100451453 _ZN5mongo7replset14multiSyncApplyERKSt6vectorINS_7BSONObjESaIS2_EEPNS0_8SyncTailE + 83
 m50001|  18  mongod                              0x00000001005d06f6 _ZN5mongo10threadpool6Worker4loopEv + 152
 m50001|  19  mongod                              0x00000001006526a5 thread_proxy + 229
 m50001| 2014-02-12T15:48:22.597-0500 [repl writer worker 1] ERROR: writer worker caught exception:  :: caused by :: 0 assertion src/mongo/db/storage/extent_manager.cpp:112 on: { ts: Timestamp 1392238102000|1, h: -9026973464560402415, v: 2, op: "i", ns: "admin.system.users", o: { _id: "admin.user1", user: "user1", db: "admin", credentials: { MONGODB-CR: "b11396a6a4ce9f875e45dffb387ffa08" }, roles: [ { role: "read", db: "admin" } ] } }
 m50001| 2014-02-12T15:48:22.597-0500 [repl writer worker 1] Fatal Assertion 16360
 m50001| 2014-02-12T15:48:22.597-0500 [repl writer worker 1]
 m50001|
 m50001| ***aborting after fassert() failure
 m50001|
 m50001|
 m50002| 2014-02-12T15:48:22.591-0500 [repl writer worker 1] admin.system.users Assertion failure n >= 0 && n < static_cast<int>(_files.size()) src/mongo/db/storage/extent_manager.cpp 112
 m50002| 2014-02-12T15:48:22.594-0500 [conn4] end connection 10.4.122.245:58551 (3 connections now open)
ReplSetTest Could not call ismaster on node 1: Error: error doing query: failed
 m50002| 2014-02-12T15:48:22.596-0500 [repl writer worker 1] admin.system.users 0x10061e23b 0x1005d7652 0x1005c8222 0x100478041 0x100479050 0x1002cd663 0x1002cde2a 0x10049a05f 0x10049a7c1 0x100496c47 0x100497cd5 0x1001abb27 0x1001ab483 0x1002f391f 0x1002f47e9 0x10041613d 0x10044cd48 0x100451453 0x1005d06f6 0x1006526a5
 m50002|  0   mongod                              0x000000010061e23b _ZN5mongo15printStackTraceERSo + 43
 m50002|  1   mongod                              0x00000001005d7652 _ZN5mongo10logContextEPKc + 114
 m50002|  2   mongod                              0x00000001005c8222 _ZN5mongo12verifyFailedEPKcS1_j + 274
 m50002|  3   mongod                              0x0000000100478041 _ZNK5mongo13ExtentManager12_getOpenFileEi + 253
 m50002|  4   mongod                              0x0000000100479050 _ZNK5mongo13ExtentManager9recordForERKNS_7DiskLocE + 24
 m50002|  5   mongod                              0x00000001002cd663 _ZN5mongo16NamespaceDetails10__stdAllocEib + 687
 m50002|  6   mongod                              0x00000001002cde2a _ZN5mongo16NamespaceDetails5allocERKNS_10StringDataEi + 64
 m50002|  7   mongod                              0x000000010049a05f _ZN5mongo11RecordStore11allocRecordEii + 93
 m50002|  8   mongod                              0x000000010049a7c1 _ZN5mongo11RecordStore12insertRecordEPKcii + 75
 m50002|  9   mongod                              0x0000000100496c47 _ZN5mongo10Collection15_insertDocumentERKNS_7BSONObjEb + 77
 m50002|  10  mongod                              0x0000000100497cd5 _ZN5mongo10Collection14insertDocumentERKNS_7BSONObjEb + 279
 m50002|  11  mongod                              0x00000001001abb27 _ZN5mongo8Database22_addNamespaceToCatalogERKNS_10StringDataEPKNS_7BSONObjE + 931
 m50002|  12  mongod                              0x00000001001ab483 _ZN5mongo8Database16createCollectionERKNS_10StringDataEbPKNS_7BSONObjEb + 449
 m50002|  13  mongod                              0x00000001002f391f _ZN5mongo6updateERKNS_13UpdateRequestEPNS_7OpDebugEPNS_12UpdateDriverE + 9039
 m50002|  14  mongod                              0x00000001002f47e9 _ZN5mongo6updateERKNS_13UpdateRequestEPNS_7OpDebugE + 249
 m50002|  15  mongod                              0x000000010041613d _ZN5mongo21applyOperation_inlockERKNS_7BSONObjEbb + 3885
 m50002|  16  mongod                              0x000000010044cd48 _ZN5mongo7replset8SyncTail9syncApplyERKNS_7BSONObjEb + 712
 m50002|  17  mongod                              0x0000000100451453 _ZN5mongo7replset14multiSyncApplyERKSt6vectorINS_7BSONObjESaIS2_EEPNS0_8SyncTailE + 83
 m50002|  18  mongod                              0x00000001005d06f6 _ZN5mongo10threadpool6Worker4loopEv + 152
 m50002|  19  mongod                              0x00000001006526a5 thread_proxy + 229
2014-02-12T15:48:22.624-0500  m50002| 2014-02-12T15:48:22.597-0500 [repl writer worker 1] ERROR: writer worker caught exception:  :: caused by :: 0 assertion src/mongo/db/storage/extent_manager.cpp:112 on: { ts: Timestamp 1392238102000|1, h: -9026973464560402415, v: 2, op: "i", ns: "admin.system.users", o: { _id: "admin.user1", user: "user1", db: "admin", credentials: { MONGODB-CR: "b11396a6a4ce9f875e45dffb387ffa08" }, roles: [ { role: "read", db: "admin" } ] } }
DBClientCursor::init call() failed
 m50002| 2014-02-12T15:48:22.597-0500 [repl writer worker 1] Fatal Assertion 16360
 m50002| 2014-02-12T15:48:22.597-0500 [repl writer worker 1]
 m50002|
 m50002| ***aborting after fassert() failure
 m50002|
 m50002|
ReplSetTest Could not call ismaster on node 2: Error: error doing query: failed
 m50000| 2014-02-12T15:48:22.625-0500 [conn1]  authenticate db: admin { authenticate: 1, nonce: "xxx", user: "user", key: "xxx" }
 m50000| 2014-02-12T15:48:22.625-0500 [conn1] Failed to authenticate user@admin with mechanism MONGODB-CR: AuthenticationFailed UserNotFound Could not find user user@admin
Error: 18 { ok: 0.0, errmsg: "auth failed", code: 18 }
2014-02-12T15:48:22.627-0500 trying reconnect to 127.0.0.1:50001
2014-02-12T15:48:22.627-0500 warning: Failed to connect to 127.0.0.1:50001, reason: errno:61 Connection refused
2014-02-12T15:48:22.627-0500 reconnect 127.0.0.1:50001 failed couldn't connect to server 127.0.0.1:50001
ReplSetTest Could not call ismaster on node 1: Error: socket exception [CONNECT_ERROR] for 127.0.0.1:50001
2014-02-12T15:48:22.629-0500 trying reconnect to 127.0.0.1:50002
2014-02-12T15:48:22.629-0500 warning: Failed to connect to 127.0.0.1:50002, reason: errno:61 Connection refused
2014-02-12T15:48:22.629-0500 reconnect 127.0.0.1:50002 failed couldn't connect to server 127.0.0.1:50002
ReplSetTest Could not call ismaster on node 2: Error: socket exception [CONNECT_ERROR] for 127.0.0.1:50002

Repro script:

users = [
  {user:"user1", roles: ["read"], pwd:"pwd"},
  {user:"user2", roles: ["readWrite"], pwd:"pwd"},
  {user:"user3", roles: ["dbAdmin"], pwd:"pwd"},
  {user:"user4", roles: ["userAdmin"], pwd:"pwd"},
  {user:"user5", roles: ["clusterAdmin"], pwd:"pwd"},
  {user:"user6", roles: ["readAnyDatabase"], pwd:"pwd"},
  {user:"user7", roles: ["readWriteAnyDatabase"], pwd:"pwd"},
  {user:"user8", roles: ["userAdminAnyDatabase"], pwd:"pwd"},
  {user:"user9", roles: ["dbAdminAnyDatabase"], pwd:"pwd"},
]
 
sourceVersion = "2.4"
targetVersion = "2.6"
 
dumpVersion = "2.6"
restoreVersion = "2.6"
 
source = new ReplSetTest({nodes:3, binVersion:sourceVersion, auth:"", keyFile:"testKeyFile", startPort:40000})
target = new ReplSetTest({nodes:3, binVersion:targetVersion, auth:"", keyFile:"testKeyFile", startPort:50000})
source.startSet()
source.initiate()
target.startSet()
target.initiate()
 
//Set up the all-powerful user we will run the dump/restore programs as.
//Need to pick command to use (createUser vs. addUser) based on version, since createUser doesn't exist in 2.4.x.
print("Creating users in source database (" + sourceVersion + ")")
if(sourceVersion != "2.4"){
  source.getPrimary().getDB("admin").createUser({user:"user", roles:["userAdminAnyDatabase", "readWriteAnyDatabase", "clusterAdmin"], pwd:"pwd"})
}else{
  source.getPrimary().getDB("admin").addUser({user:"user", roles:["userAdminAnyDatabase", "readWriteAnyDatabase", "clusterAdmin"], pwd:"pwd"})
}
source.getPrimary().getDB("admin").auth("user", "pwd")
 
//Create a bunch of users in our source database.
for(var i=0;i<users.length;i++){
  var func = source.getPrimary().getDB("admin").addUser
  if(sourceVersion != "2.4"){
    source.getPrimary().getDB("admin").createUser(users[i])
  }else{
    source.getPrimary().getDB("admin").addUser(users[i])
  }
}
print("Done adding users")
 
//Dump the data from the source server.
print("Running mongodump from source database (" + sourceVersion + ") using mongodump version: " + dumpVersion)
MongoRunner.runMongoTool("mongodump-" + dumpVersion, {host:source.getURL(), authenticationDatabase: "admin", username:"user", password:"pwd" })
//Restore the data into the target server.
print("Running mongorestore to target database (" + targetVersion + ") using mongorestore version: " + restoreVersion)
MongoRunner.runMongoTool("mongorestore-" + restoreVersion, {host:target.getURL() , username:"__system", password:"abcdefghijklmnopqrstuvwxyz", authenticationDatabase:"local"})
 
target.getPrimary().getDB("admin").auth("user", "pwd")
 
printjson(target.getPrimary().getDB("admin").system.users.find().toArray())



 Comments   
Comment by Spencer Brody (Inactive) [ 13/Feb/14 ]

Attaching a simpler repro script

Comment by Spencer Brody (Inactive) [ 13/Feb/14 ]

The storage layer is failing a verify() at src/mongo/db/storage/extent_manager.cpp 109. It looks like its trying to access the first data file before its finished being allocated?

2014-02-13T14:34:16.218-0500 shell: started program /media/ssd/mongo3/mongorestore --host ubuntu:50000
sh20065| connected to: ubuntu:50000
 m50000| 2014-02-13T14:34:16.257-0500 [initandlisten] connection accepted from 127.0.0.1:50497 #14 (8 connections now open)
sh20065| 2014-02-13T14:34:16.258-0500   going into namespace [admin.system.version]
sh20065| 1 objects found
 m50000| 2014-02-13T14:34:16.265-0500 [conn14] uh oh: 0
 m50000| 2014-02-13T14:34:16.265-0500 [conn14] admin.system.version Assertion failure n >= 0 && n < static_cast<int>(_files.size()) src/mongo/db/storage/extent_manager.cpp 109
sh20065| 2014-02-13T14:34:16.268-0500   Creating index: { key: { _id: 1 }, name: "_id_", ns: "admin.system.version" }
 m50000| 2014-02-13T14:34:16.281-0500 [conn14] admin.system.version 0x159f7f7 0x15462bd 0x153228c 0x13a58a0 0x13a623e 0x13a9854 0x13a989a 0x13c8d19 0x13c9627 0x13c879e 0x13d5050 0x13d491c 0xf6cb97 0xf6ca36 0xf7de24 0xf7d86b 0x1149830 0x1149df7 0x1146a8c 0xe72072 
 m50000|  /media/ssd/mongo3/mongod(_ZN5mongo15printStackTraceERSo+0x27) [0x159f7f7]
 m50000|  /media/ssd/mongo3/mongod(_ZN5mongo10logContextEPKc+0x71) [0x15462bd]
 m50000|  /media/ssd/mongo3/mongod(_ZN5mongo12verifyFailedEPKcS1_j+0xff) [0x153228c]
 m50000|  /media/ssd/mongo3/mongod(_ZNK5mongo13ExtentManager12_getOpenFileEi+0x140) [0x13a58a0]
 m50000|  /media/ssd/mongo3/mongod(_ZNK5mongo13ExtentManager9recordForERKNS_7DiskLocE+0x38) [0x13a623e]
 m50000|  /media/ssd/mongo3/mongod(_ZNK5mongo7DiskLoc3recEv+0x62) [0x13a9854]
 m50000|  /media/ssd/mongo3/mongod(_ZNK5mongo7DiskLoc4drecEv+0x44) [0x13a989a]
 m50000|  /media/ssd/mongo3/mongod(_ZN5mongo16NamespaceDetails10__stdAllocEib+0x32d) [0x13c8d19]
 m50000|  /media/ssd/mongo3/mongod(_ZN5mongo16NamespaceDetails6_allocEPNS_10CollectionERKNS_10StringDataEi+0x47) [0x13c9627]
 m50000|  /media/ssd/mongo3/mongod(_ZN5mongo16NamespaceDetails5allocEPNS_10CollectionERKNS_10StringDataEi+0xba) [0x13c879e]
 m50000|  /media/ssd/mongo3/mongod(_ZN5mongo19SimpleRecordStoreV111allocRecordEii+0x6e) [0x13d5050]
 m50000|  /media/ssd/mongo3/mongod(_ZN5mongo17RecordStoreV1Base12insertRecordEPKcii+0x74) [0x13d491c]
 m50000|  /media/ssd/mongo3/mongod(_ZN5mongo10Collection15_insertDocumentERKNS_7BSONObjEb+0xa9) [0xf6cb97]
 m50000|  /media/ssd/mongo3/mongod(_ZN5mongo10Collection14insertDocumentERKNS_7BSONObjEb+0x1fa) [0xf6ca36]
 m50000|  /media/ssd/mongo3/mongod(_ZN5mongo8Database22_addNamespaceToCatalogERKNS_10StringDataEPKNS_7BSONObjE+0x28a) [0xf7de24]
 m50000|  /media/ssd/mongo3/mongod(_ZN5mongo8Database16createCollectionERKNS_10StringDataEbPKNS_7BSONObjEb+0x4f9) [0xf7d86b]
 m50000|  /media/ssd/mongo3/mongod(_ZN5mongo14checkAndInsertERNS_6Client7ContextEPKcRNS_7BSONObjE+0x3f6) [0x1149830]
 m50000|  /media/ssd/mongo3/mongod(_ZN5mongo14receivedInsertERNS_7MessageERNS_5CurOpE+0x34a) [0x1149df7]
 m50000|  /media/ssd/mongo3/mongod(_ZN5mongo16assembleResponseERNS_7MessageERNS_10DbResponseERKNS_11HostAndPortE+0x633) [0x1146a8c]
 m50000|  /media/ssd/mongo3/mongod(_ZN5mongo16MyMessageHandler7processERNS_7MessageEPNS_21AbstractMessagingPortEPNS_9LastErrorE+0xf2) [0xe72072]
 m50000| 2014-02-13T14:34:16.281-0500 [conn14] 
 m50000| 
 m50000| ***aborting after verify() failure as this is a debug/test build
 m50000| 
 m50000| 
 m50000| Got signal: 6 (Aborted).
 m50000| Backtrace:
 m50000| 0x159f7f7 0xe69ad7 0x7fb34b9f24a0 0x7fb34b9f2425 0x7fb34b9f5b8b 0x15323af 0x13a58a0 0x13a623e 0x13a9854 0x13a989a 0x13c8d19 0x13c9627 0x13c879e 0x13d5050 0x13d491c 0xf6cb97 0xf6ca36 0xf7de24 0xf7d86b 0x1149830 
 m50000|  /media/ssd/mongo3/mongod(_ZN5mongo15printStackTraceERSo+0x27) [0x159f7f7]
 m50000|  /media/ssd/mongo3/mongod(_ZN5mongo10abruptQuitEi+0x123) [0xe69ad7]
 m50000|  /lib/x86_64-linux-gnu/libc.so.6(+0x364a0) [0x7fb34b9f24a0]
 m50000|  /lib/x86_64-linux-gnu/libc.so.6(gsignal+0x35) [0x7fb34b9f2425]
 m50000|  /lib/x86_64-linux-gnu/libc.so.6(abort+0x17b) [0x7fb34b9f5b8b]
 m50000|  /media/ssd/mongo3/mongod(_ZN5mongo12verifyFailedEPKcS1_j+0x222) [0x15323af]
 m50000|  /media/ssd/mongo3/mongod(_ZNK5mongo13ExtentManager12_getOpenFileEi+0x140) [0x13a58a0]
 m50000|  /media/ssd/mongo3/mongod(_ZNK5mongo13ExtentManager9recordForERKNS_7DiskLocE+0x38) [0x13a623e]
 m50000|  /media/ssd/mongo3/mongod(_ZNK5mongo7DiskLoc3recEv+0x62) [0x13a9854]
 m50000|  /media/ssd/mongo3/mongod(_ZNK5mongo7DiskLoc4drecEv+0x44) [0x13a989a]
 m50000|  /media/ssd/mongo3/mongod(_ZN5mongo16NamespaceDetails10__stdAllocEib+0x32d) [0x13c8d19]
 m50000|  /media/ssd/mongo3/mongod(_ZN5mongo16NamespaceDetails6_allocEPNS_10CollectionERKNS_10StringDataEi+0x47) [0x13c9627]
 m50000|  /media/ssd/mongo3/mongod(_ZN5mongo16NamespaceDetails5allocEPNS_10CollectionERKNS_10StringDataEi+0xba) [0x13c879e]
 m50000|  /media/ssd/mongo3/mongod(_ZN5mongo19SimpleRecordStoreV111allocRecordEii+0x6e) [0x13d5050]
 m50000|  /media/ssd/mongo3/mongod(_ZN5mongo17RecordStoreV1Base12insertRecordEPKcii+0x74) [0x13d491c]
 m50000|  /media/ssd/mongo3/mongod(_ZN5mongo10Collection15_insertDocumentERKNS_7BSONObjEb+0xa9) [0xf6cb97]
 m50000|  /media/ssd/mongo3/mongod(_ZN5mongo10Collection14insertDocumentERKNS_7BSONObjEb+0x1fa) [0xf6ca36]
 m50000|  /media/ssd/mongo3/mongod(_ZN5mongo8Database22_addNamespaceToCatalogERKNS_10StringDataEPKNS_7BSONObjE+0x28a) [0xf7de24]
 m50000|  /media/ssd/mongo3/mongod(_ZN5mongo8Database16createCollectionERKNS_10StringDataEbPKNS_7BSONObjEb+0x4f9) [0xf7d86b]
 m50000|  /media/ssd/mongo3/mongod(_ZN5mongo14checkAndInsertERNS_6Client7ContextEPKcRNS_7BSONObjE+0x3f6) [0x1149830]
 

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