[SERVER-12565] Cannot run mongodump from 2.4 datafiles Created: 31/Jan/14  Updated: 11/Jul/16  Resolved: 07/Feb/14

Status: Closed
Project: Core Server
Component/s: Tools
Affects Version/s: None
Fix Version/s: 2.6.0-rc0

Type: Bug Priority: Major - P3
Reporter: Shaun Verch Assignee: Eliot Horowitz (Inactive)
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Depends
Operating System: ALL
Steps To Reproduce:

Run a 2.4 mongod and shut down (after inserting data shown below):

$ ./mongod-2.4
./mongod-2.4 --help for help and startup options
Fri Jan 31 15:58:53.328 [initandlisten] MongoDB starting : pid=16173 port=27017 dbpath=/data/db/ 64-bit host=sv.local
Fri Jan 31 15:58:53.328 [initandlisten] db version v2.4.8
Fri Jan 31 15:58:53.328 [initandlisten] git version: a350fc38922fbda2cec8d5dd842237b904eafc14
Fri Jan 31 15:58:53.328 [initandlisten] build info: Darwin bs-osx-106-x86-64-2.10gen.cc 10.8.0 Darwin Kernel Version 10.8.0: Tue Jun  7 16:32:41 PDT 2011; root:xnu-1504.15.3~1/RELEASE_X86_64 x86_64 BOOST_LIB_VERSION=1_49
Fri Jan 31 15:58:53.328 [initandlisten] allocator: system
Fri Jan 31 15:58:53.328 [initandlisten] options: {}
Fri Jan 31 15:58:53.331 [initandlisten] journal dir=/data/db/journal
Fri Jan 31 15:58:53.331 [initandlisten] recover : no journal files present, no recovery needed
Fri Jan 31 15:58:53.355 [websvr] admin web console waiting for connections on port 28017
Fri Jan 31 15:58:53.355 [initandlisten] waiting for connections on port 27017
Fri Jan 31 15:58:56.672 [initandlisten] connection accepted from 127.0.0.1:61236 #1 (1 connection now open)
Fri Jan 31 15:59:02.205 [FileAllocator] allocating new datafile /data/db/test.ns, filling with zeroes...
Fri Jan 31 15:59:02.205 [FileAllocator] creating directory /data/db/_tmp
Fri Jan 31 15:59:02.236 [FileAllocator] done allocating datafile /data/db/test.ns, size: 16MB,  took 0.031 secs
Fri Jan 31 15:59:02.259 [FileAllocator] allocating new datafile /data/db/test.0, filling with zeroes...
Fri Jan 31 15:59:02.420 [FileAllocator] done allocating datafile /data/db/test.0, size: 64MB,  took 0.16 secs
Fri Jan 31 15:59:02.445 [FileAllocator] allocating new datafile /data/db/test.1, filling with zeroes...
Fri Jan 31 15:59:02.447 [conn1] build index test.test { _id: 1 }
Fri Jan 31 15:59:02.455 [conn1] build index done.  scanned 0 total records. 0.008 secs
Fri Jan 31 15:59:02.455 [conn1] insert test.test ninserted:1 keyUpdates:0 locks(micros) w:251137 251ms
Fri Jan 31 15:59:02.819 [FileAllocator] done allocating datafile /data/db/test.1, size: 128MB,  took 0.373 secs
Fri Jan 31 15:59:03.858 [conn1] end connection 127.0.0.1:61236 (0 connections now open)
^CFri Jan 31 15:59:05.476 [signalProcessingThread] got signal 2 (Interrupt: 2), will terminate after current cmd ends
Fri Jan 31 15:59:05.476 [signalProcessingThread] now exiting
Fri Jan 31 15:59:05.476 dbexit:
Fri Jan 31 15:59:05.476 [signalProcessingThread] shutdown: going to close listening sockets...
Fri Jan 31 15:59:05.476 [signalProcessingThread] closing listening socket: 9
Fri Jan 31 15:59:05.476 [signalProcessingThread] closing listening socket: 10
Fri Jan 31 15:59:05.476 [signalProcessingThread] closing listening socket: 11
Fri Jan 31 15:59:05.476 [signalProcessingThread] removing socket file: /tmp/mongodb-27017.sock
Fri Jan 31 15:59:05.476 [signalProcessingThread] shutdown: going to flush diaglog...
Fri Jan 31 15:59:05.476 [signalProcessingThread] shutdown: going to close sockets...
Fri Jan 31 15:59:05.476 [signalProcessingThread] shutdown: waiting for fs preallocator...
Fri Jan 31 15:59:05.476 [signalProcessingThread] shutdown: lock for final commit...
Fri Jan 31 15:59:05.476 [signalProcessingThread] shutdown: final commit...
Fri Jan 31 15:59:05.492 [signalProcessingThread] shutdown: closing all files...
Fri Jan 31 15:59:05.492 [signalProcessingThread] closeAllFiles() finished
Fri Jan 31 15:59:05.492 [signalProcessingThread] journalCleanup...
Fri Jan 31 15:59:05.492 [signalProcessingThread] removeJournalFiles
Fri Jan 31 15:59:05.493 [signalProcessingThread] shutdown: removing fs lock...
Fri Jan 31 15:59:05.493 dbexit: really exiting now

Insert data:

$ ./mongo
MongoDB shell version: 2.5.5-pre-
connecting to: test
> db.test.insert({x:1})
> exit
bye

Dump using 2.5.5 mongodump:

$ ./mongodump --dbpath /data/db
2014-01-31T15:59:09.706-0500 all dbs
2014-01-31T15:59:09.706-0500 [tools] _DEBUG ReadContext db wasn't open, will try to open local.system.namespaces
2014-01-31T15:59:09.706-0500 [tools] opening db:  local
2014-01-31T15:59:09.707-0500 [tools] _DEBUG ReadContext db wasn't open, will try to open test.system.namespaces
2014-01-31T15:59:09.707-0500 [tools] opening db:  test
2014-01-31T15:59:09.708-0500 DATABASE: test	 to 	dump/test
2014-01-31T15:59:09.709-0500 	test.system.indexes to dump/test/system.indexes.bson
2014-01-31T15:59:09.710-0500 		 1 objects
2014-01-31T15:59:09.710-0500 	test.test to dump/test/test.bson
2014-01-31T15:59:09.710-0500 [tools] lock status: r recursive:1 otherCount:-1 otherdb:test
2014-01-31T15:59:09.710-0500 [tools] Assertion: 16105:expected to be write locked for test.$freelist
2014-01-31T15:59:09.725-0500 [tools] 0x100d05975 0x100c639b4 0x100c3efd6 0x100c3f22a 0x10032d745 0x10093f97e 0x10093fae8 0x10093fb51 0x1001c696c 0x1001d3e4f 0x1001ee6eb 0x1001e47c0 0x1001e4e80 0x1001e4f6a 0x1001e648d 0x1001e91fa 0x1001bf879 0x1001c70f6 0x10056b884 0x1004e73fc
 0   mongodump                           0x0000000100d05975 _ZN5mongo15printStackTraceERSo + 37
 1   mongodump                           0x0000000100c639b4 _ZN5mongo10logContextEPKc + 228
 2   mongodump                           0x0000000100c3efd6 _ZN5mongo11msgassertedEiPKc + 390
 3   mongodump                           0x0000000100c3f22a _ZNK5mongo13ExceptionInfo6appendERNS_14BSONObjBuilderEPKcS4_ + 0
 4   mongodump                           0x000000010032d745 _ZN5mongo4Lock17assertWriteLockedERKNS_10StringDataE + 165
 5   mongodump                           0x000000010093f97e _ZN5mongo14NamespaceIndex6add_nsERKNS_9NamespaceEPKNS_16NamespaceDetailsE + 72
 6   mongodump                           0x000000010093fae8 _ZN5mongo14NamespaceIndex6add_nsERKNS_10StringDataEPKNS_16NamespaceDetailsE + 78
 7   mongodump                           0x000000010093fb51 _ZN5mongo14NamespaceIndex6add_nsERKNS_10StringDataERKNS_7DiskLocEb + 95
 8   mongodump                           0x00000001001c696c _ZN5mongo8Database19_initExtentFreeListEv + 238
 9   mongodump                           0x00000001001d3e4f _ZN5mongo8Database14_initForWritesEv + 99
 10  mongodump                           0x00000001001ee6eb _ZN5mongo8Database7getFileEiib + 35
 11  mongodump                           0x00000001001e47c0 _ZN5mongo12IndexCatalog21_shouldOverridePluginERKNS_7BSONObjE + 114
 12  mongodump                           0x00000001001e4e80 _ZN5mongo12IndexCatalog20_getAccessMethodNameERKNS_7BSONObjE + 46
 13  mongodump                           0x00000001001e4f6a _ZN5mongo12IndexCatalog19_createAccessMethodEPKNS_15IndexDescriptorEPNS_17IndexCatalogEntryE + 60
 14  mongodump                           0x00000001001e648d _ZN5mongo12IndexCatalog24_setupInMemoryStructuresEPNS_15IndexDescriptorE + 1231
 15  mongodump                           0x00000001001e91fa _ZN5mongo12IndexCatalog4initEv + 818
 16  mongodump                           0x00000001001bf879 _ZN5mongo10CollectionC1ERKNS_10StringDataEPNS_16NamespaceDetailsEPNS_8DatabaseE + 491
 17  mongodump                           0x00000001001c70f6 _ZN5mongo8Database13getCollectionERKNS_10StringDataE + 1212
 18  mongodump                           0x000000010056b884 _ZN5mongo8runCountERKSsRKNS_7BSONObjERSsRi + 196
 19  mongodump                           0x00000001004e73fc _ZN5mongo14DBDirectClient5countERKSsRKNS_7BSONObjEiii + 516
assertion: 16105 expected to be write locked for test.$freelist
2014-01-31T15:59:09.727-0500 [tools] thread tools stack usage was 32320 bytes,  which is the most so far
dbexit: 2014-01-31T15:59:09.728-0500 [tools] shutdown: going to close listening sockets...
2014-01-31T15:59:09.728-0500 [tools] shutdown: going to flush diaglog...
2014-01-31T15:59:09.728-0500 [tools] shutdown: going to close sockets...
2014-01-31T15:59:09.728-0500 [tools] shutdown: waiting for fs preallocator...
2014-01-31T15:59:09.728-0500 [tools] shutdown: closing all files...
2014-01-31T15:59:09.728-0500 [tools] is it really ok to close a mongommf outside a write lock? file:/data/db/test.0
2014-01-31T15:59:09.728-0500 [tools] is it really ok to close a mongommf outside a write lock? file:/data/db/local.0
2014-01-31T15:59:09.728-0500 [tools] is it really ok to close a mongommf outside a write lock? file:/data/db/test.ns
2014-01-31T15:59:09.728-0500 [tools] is it really ok to close a mongommf outside a write lock? file:/data/db/local.ns
2014-01-31T15:59:09.728-0500 [tools] closeAllFiles() finished
2014-01-31T15:59:09.728-0500 [tools] shutdown: removing fs lock...
dbexit: really exiting now

Confirmation that the data has not been dumped:

$ ls dump/
test
$ ls dump/test/
system.indexes.bson test.bson
$ bsondump dump/test/test.bson
file dump/test/test.bson empty, skipping

Participants:

 Description   

Cannot run a direct mongodump against the data files of a 2.4 database. See steps to reproduce.



 Comments   
Comment by Githook User [ 10/Feb/14 ]

Author:

{u'username': u'erh', u'name': u'Eliot Horowitz', u'email': u'eliot@10gen.com'}

Message: SERVER-12565: remove old extent freelist implementation and replace with new one
Branch: master
https://github.com/mongodb/mongo/commit/b8bc31bdb9ff9cc2510205158bd84edd1f5dfc8a

Comment by Githook User [ 07/Feb/14 ]

Author:

{u'username': u'erh', u'name': u'Eliot Horowitz', u'email': u'eliot@10gen.com'}

Message: SERVER-12565: only create freelist for extents when needed
Branch: master
https://github.com/mongodb/mongo/commit/795353195c696a95a6f18a4deb38dfb5ad588ab9

Comment by Shaun Verch [ 05/Feb/14 ]

It looks like the issue is that when Database::getFile is called it unconditionally initializes the data files for writing: https://github.com/mongodb/mongo/blob/9cbdc4fa38c14a27/src/mongo/db/database.h#L83

In this case, we are trying to run a count command, which retrieves the index catalog for the database. To initialize the index metadata, the index catalog calls into getFile, which attempts to initialize the extent free list as part of initializing for writes. In the 2.4 data files, it seems like we don't have an extent free list, so it tries to create it, which fails because "count" doesn't take a write lock.

A workaround for this is to start a new mongod on the 2.4 datafiles and then shut it down. this seems to properly initialize the data files without problems as subsequent mongodumps are successful.

Comment by Eliot Horowitz (Inactive) [ 31/Jan/14 ]

I would guess the namespace over which you want to count doesn't exist, and someone isn't checking high enough up.

Comment by Andy Schwerin [ 31/Jan/14 ]

eliot, any idea why a tool running a count command using DBDirectClient would end up calling a function that requires a write lock? Looks like initForWrites() is getting called on a Database object deep inside getCollection(). It appears to be that mongodump is trying to open db.$freelist as a collection, and since it doesn't exist, tries to allocate storage.

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