Loading...

Type: Bug
Resolution: Done
Priority: Blocker - P1
Fix Version/s: 2.3.0
Affects Version/s: None
Component/s: Testing Infrastructure
Labels:
- buildbot
Environment:
Windows build slave

Operating System:
Windows
Confidence Status:
None
Work Order:
0
CAR Domain/s:
None

Aha! Reference:
None
Tracking Level:
None
Risk Status:
None
Exec Notes:
None
Goal Name(s):
None
Goal Link:
None

mongorestore.exe is failing in jstests/tool/dumpfilename1.js when given the command line

mongorestore.exe --dir /data/db/jstests_tool_dumpfilename1_external/ --host 127.0.0.1:31000

Previously, the test looked like this:

MongoDB shell version: 2.3.0-pre-
null
Thu Oct 11 03:32:34 shell: started program mongod.exe --port 31000 --dbpath /data/db/jstests_tool_dumpfilename1/ --nohttpinterface --noprealloc --smallfiles --bind_ip 127.0.0.1
 m31000| note: noprealloc may hurt performance in many applications
 m31000| Thu Oct 11 03:32:34 [initandlisten] MongoDB starting : pid=5432 port=31000 dbpath=/data/db/jstests_tool_dumpfilename1 64-bit host=AMAZONA-J7UBCUV
 m31000| Thu Oct 11 03:32:34 [initandlisten] _DEBUG build (which is slower)
 m31000| Thu Oct 11 03:32:34 [initandlisten] 
 m31000| Thu Oct 11 03:32:34 [initandlisten] ** NOTE: This is a development version (2.3.0-pre-) of MongoDB.
 m31000| Thu Oct 11 03:32:34 [initandlisten] **       Not recommended for production.
 m31000| Thu Oct 11 03:32:34 [initandlisten] 
 m31000| Thu Oct 11 03:32:34 [initandlisten] db version v2.3.0-pre-, pdfile version 4.5
 m31000| Thu Oct 11 03:32:34 [initandlisten] git version: a7c4ae5de9e17fc72f33a34d4e92ccd58c099f62
 m31000| Thu Oct 11 03:32:34 [initandlisten] build info: windows sys.getwindowsversion(major=6, minor=1, build=7601, platform=2, service_pack='Service Pack 1') BOOST_LIB_VERSION=1_49
 m31000| Thu Oct 11 03:32:34 [initandlisten] options: { bind_ip: "127.0.0.1", dbpath: "/data/db/jstests_tool_dumpfilename1/", nohttpinterface: true, noprealloc: true, port: 31000, smallfiles: true }
 m31000| Thu Oct 11 03:32:34 [initandlisten] journal dir=/data/db/jstests_tool_dumpfilename1/journal
 m31000| Thu Oct 11 03:32:34 [initandlisten] recover : no journal files present, no recovery needed
 m31000| Thu Oct 11 03:32:35 [initandlisten] opening db:  local
 m31000| Thu Oct 11 03:32:35 [initandlisten] waiting for connections on port 31000
 m31000| Thu Oct 11 03:32:35 [initandlisten] connection accepted from 127.0.0.1:57998 #1 (1 connection now open)
 m31000| Thu Oct 11 03:32:35 [conn1] opening db:  jstests_tool_dumpfilename1
 m31000| Thu Oct 11 03:32:35 [FileAllocator] allocating new datafile /data/db/jstests_tool_dumpfilename1/jstests_tool_dumpfilename1.ns, filling with zeroes...
 m31000| Thu Oct 11 03:32:35 [FileAllocator] creating directory /data/db/jstests_tool_dumpfilename1/_tmp
 m31000| Thu Oct 11 03:32:35 [FileAllocator] done allocating datafile /data/db/jstests_tool_dumpfilename1/jstests_tool_dumpfilename1.ns, size: 16MB,  took 0.134 secs
 m31000| Thu Oct 11 03:32:35 [FileAllocator] allocating new datafile /data/db/jstests_tool_dumpfilename1/jstests_tool_dumpfilename1.0, filling with zeroes...
 m31000| Thu Oct 11 03:32:35 [FileAllocator] done allocating datafile /data/db/jstests_tool_dumpfilename1/jstests_tool_dumpfilename1.0, size: 16MB,  took 0.132 secs
 m31000| Thu Oct 11 03:32:35 [conn1] datafileheader::init initializing /data/db/jstests_tool_dumpfilename1/jstests_tool_dumpfilename1.0 n:0
 m31000| Thu Oct 11 03:32:35 [conn1] build index jstests_tool_dumpfilename1.df/ { _id: 1 }
 m31000| Thu Oct 11 03:32:35 [conn1] build index done.  scanned 0 total records. 0.001 secs
 m31000| Thu Oct 11 03:32:35 [conn1] insert jstests_tool_dumpfilename1.df/ keyUpdates:0 locks(micros) w:279905 280ms
 m31000| Thu Oct 11 03:32:35 [conn1] build index jstests_tool_dumpfilename1.df { _id: 1 }
 m31000| Thu Oct 11 03:32:35 [conn1] build index done.  scanned 0 total records. 0.01 secs
Thu Oct 11 03:32:35 shell: started program mongodump.exe --out /data/db/jstests_tool_dumpfilename1_external/ --host 127.0.0.1:31000
sh2964| connected to: 127.0.0.1:31000
 m31000| Thu Oct 11 03:32:35 [initandlisten] connection accepted from 127.0.0.1:57999 #2 (2 connections now open)
sh2964| Thu Oct 11 03:32:35 all dbs
sh2964| Thu Oct 11 03:32:35 DATABASE: jstests_tool_dumpfilename1	 to 	/data/db/jstests_tool_dumpfilename1_external/jstests_tool_dumpfilename1
sh2964| Thu Oct 11 03:32:35 ERROR: Cannot dump jstests_tool_dumpfilename1.df/. Collection has '/' or null in the collection name.
sh2964| Thu Oct 11 03:32:35 	jstests_tool_dumpfilename1.df to /data/db/jstests_tool_dumpfilename1_external/jstests_tool_dumpfilename1/df.bson
sh2964| Thu Oct 11 03:32:35 doing snapshot query
sh2964| Thu Oct 11 03:32:35 		 1 objects
sh2964| Thu Oct 11 03:32:35 	Metadata for jstests_tool_dumpfilename1.df to /data/db/jstests_tool_dumpfilename1_external/jstests_tool_dumpfilename1/df.metadata.json
 m31000| Thu Oct 11 03:32:35 [conn2] end connection 127.0.0.1:57999 (1 connection now open)
 m31000| Thu Oct 11 03:32:35 [conn2] thread conn2 stack usage was 19968 bytes,  which is the most so far
 m31000| Thu Oct 11 03:32:35 [conn1] CMD: drop jstests_tool_dumpfilename1.df/
 m31000| Thu Oct 11 03:32:35 [conn1] CMD: drop jstests_tool_dumpfilename1.df
Thu Oct 11 03:32:35 shell: started program mongorestore.exe --dir /data/db/jstests_tool_dumpfilename1_external/ --host 127.0.0.1:31000
sh1508| connected to: 127.0.0.1:31000
 m31000| Thu Oct 11 03:32:35 [initandlisten] connection accepted from 127.0.0.1:58000 #3 (2 connections now open)
sh1508| Thu Oct 11 03:32:35 /data/db/jstests_tool_dumpfilename1_external/jstests_tool_dumpfilename1/df.bson
sh1508| Thu Oct 11 03:32:35 	going into namespace [jstests_tool_dumpfilename1.df]
sh1508| 1 objects found
 m31000| Thu Oct 11 03:32:35 [conn3] build index jstests_tool_dumpfilename1.df { _id: 1 }
 m31000| Thu Oct 11 03:32:35 [conn3] build index done.  scanned 0 total records. 0.001 secs
sh1508| Thu Oct 11 03:32:35 	Creating index: { key: { _id: 1 }, ns: "jstests_tool_dumpfilename1.df", name: "_id_" }
 m31000| Thu Oct 11 03:32:35 [conn3] end connection 127.0.0.1:58000 (1 connection now open)
 m31000| Thu Oct 11 03:32:35 [conn3] thread conn3 stack usage was 25320 bytes,  which is the most so far
 m31000| Thu Oct 11 03:32:35 [initandlisten] connection accepted from 127.0.0.1:58001 #4 (2 connections now open)
 m31000| Thu Oct 11 03:32:35 [conn4] terminating, shutdown command received
 m31000| Thu Oct 11 03:32:35 dbexit: shutdown called
 m31000| Thu Oct 11 03:32:35 [conn4] shutdown: going to close listening sockets...
 m31000| Thu Oct 11 03:32:35 [conn4] closing listening socket: 416
 m31000| Thu Oct 11 03:32:35 [conn4] shutdown: going to flush diaglog...
 m31000| Thu Oct 11 03:32:35 [conn4] shutdown: going to close sockets...
 m31000| Thu Oct 11 03:32:35 [conn4] shutdown: waiting for fs preallocator...
 m31000| Thu Oct 11 03:32:35 [conn4] shutdown: lock for final commit...
Thu Oct 11 03:32:35 DBClientCursor::init call() failed
 m31000| Thu Oct 11 03:32:35 [conn4] shutdown: final commit...
 m31000| Thu Oct 11 03:32:35 [conn1] end connection 127.0.0.1:57998 (1 connection now open)
 m31000| Thu Oct 11 03:32:35 [conn1] thread conn1 stack usage was 27016 bytes,  which is the most so far
 m31000| Thu Oct 11 03:32:36 [conn4] shutdown: closing all files...
 m31000| Thu Oct 11 03:32:36 [conn4] closeAllFiles() finished
 m31000| Thu Oct 11 03:32:36 [conn4] journalCleanup...
 m31000| Thu Oct 11 03:32:36 [conn4] removeJournalFiles
 m31000| Thu Oct 11 03:32:36 [conn4] shutdown: removing fs lock...
 m31000| Thu Oct 11 03:32:36 dbexit: really exiting now
 m31000| Thu Oct 11 03:32:36 [conn4] thread conn4 stack usage was 30264 bytes,  which is the most so far
Thu Oct 11 03:32:36 shell: stopped mongo program on port 31000
*** dumpfilename1 completed successfully ***

It now looks like this:

Fri Oct 12 03:32:40 [conn5] end connection 127.0.0.1:63621 (0 connections now open)
Fri Oct 12 03:33:48 [initandlisten] connection accepted from 127.0.0.1:63641 #6 (1 connection now open)
MongoDB shell version: 2.3.0-pre-
null
Fri Oct 12 03:33:49 shell: started program mongod.exe --port 31000 --dbpath /data/db/jstests_tool_dumpfilename1/ --nohttpinterface --noprealloc --smallfiles --bind_ip 127.0.0.1
 m31000| note: noprealloc may hurt performance in many applications
 m31000| Fri Oct 12 03:33:49 [initandlisten] MongoDB starting : pid=3540 port=31000 dbpath=/data/db/jstests_tool_dumpfilename1 64-bit host=AMAZONA-J7UBCUV
 m31000| Fri Oct 12 03:33:49 [initandlisten] _DEBUG build (which is slower)
 m31000| Fri Oct 12 03:33:49 [initandlisten] 
 m31000| Fri Oct 12 03:33:49 [initandlisten] ** NOTE: This is a development version (2.3.0-pre-) of MongoDB.
 m31000| Fri Oct 12 03:33:49 [initandlisten] **       Not recommended for production.
 m31000| Fri Oct 12 03:33:49 [initandlisten] 
 m31000| Fri Oct 12 03:33:49 [initandlisten] db version v2.3.0-pre-, pdfile version 4.5
 m31000| Fri Oct 12 03:33:49 [initandlisten] git version: 46f2d0598cb7c74fc7fd44bd038ecc3599b36f68
 m31000| Fri Oct 12 03:33:49 [initandlisten] build info: windows sys.getwindowsversion(major=6, minor=1, build=7601, platform=2, service_pack='Service Pack 1') BOOST_LIB_VERSION=1_49
 m31000| Fri Oct 12 03:33:49 [initandlisten] options: { bind_ip: "127.0.0.1", dbpath: "/data/db/jstests_tool_dumpfilename1/", nohttpinterface: true, noprealloc: true, port: 31000, smallfiles: true }
 m31000| Fri Oct 12 03:33:49 [initandlisten] journal dir=/data/db/jstests_tool_dumpfilename1\journal
 m31000| Fri Oct 12 03:33:49 [initandlisten] recover : no journal files present, no recovery needed
 m31000| Fri Oct 12 03:33:49 [initandlisten] opening db:  local
 m31000| Fri Oct 12 03:33:49 [initandlisten] waiting for connections on port 31000
 m31000| Fri Oct 12 03:33:49 [initandlisten] connection accepted from 127.0.0.1:63650 #1 (1 connection now open)
 m31000| Fri Oct 12 03:33:49 [conn1] opening db:  jstests_tool_dumpfilename1
 m31000| Fri Oct 12 03:33:49 [FileAllocator] allocating new datafile /data/db/jstests_tool_dumpfilename1\jstests_tool_dumpfilename1.ns, filling with zeroes...
 m31000| Fri Oct 12 03:33:49 [FileAllocator] creating directory /data/db/jstests_tool_dumpfilename1\_tmp
 m31000| Fri Oct 12 03:33:49 [FileAllocator] done allocating datafile /data/db/jstests_tool_dumpfilename1\jstests_tool_dumpfilename1.ns, size: 16MB,  took 0.133 secs
 m31000| Fri Oct 12 03:33:49 [FileAllocator] allocating new datafile /data/db/jstests_tool_dumpfilename1\jstests_tool_dumpfilename1.0, filling with zeroes...
 m31000| Fri Oct 12 03:33:49 [FileAllocator] done allocating datafile /data/db/jstests_tool_dumpfilename1\jstests_tool_dumpfilename1.0, size: 16MB,  took 0.132 secs
 m31000| Fri Oct 12 03:33:49 [conn1] datafileheader::init initializing /data/db/jstests_tool_dumpfilename1\jstests_tool_dumpfilename1.0 n:0
 m31000| Fri Oct 12 03:33:49 [conn1] build index jstests_tool_dumpfilename1.df/ { _id: 1 }
 m31000| Fri Oct 12 03:33:50 [conn1] build index done.  scanned 0 total records. 0.001 secs
 m31000| Fri Oct 12 03:33:50 [conn1] insert jstests_tool_dumpfilename1.df/ keyUpdates:0 locks(micros) w:280806 280ms
 m31000| Fri Oct 12 03:33:50 [conn1] build index jstests_tool_dumpfilename1.df { _id: 1 }
 m31000| Fri Oct 12 03:33:50 [conn1] build index done.  scanned 0 total records. 0.006 secs
Fri Oct 12 03:33:50 shell: started program mongodump.exe --out /data/db/jstests_tool_dumpfilename1_external/ --host 127.0.0.1:31000
sh2936| connected to: 127.0.0.1:31000
 m31000| Fri Oct 12 03:33:50 [initandlisten] connection accepted from 127.0.0.1:63651 #2 (2 connections now open)
sh2936| Fri Oct 12 03:33:50 all dbs
sh2936| Fri Oct 12 03:33:50 DATABASE: jstests_tool_dumpfilename1	 to 	/data/db/jstests_tool_dumpfilename1_external/jstests_tool_dumpfilename1
sh2936| Fri Oct 12 03:33:50 ERROR: Cannot dump jstests_tool_dumpfilename1.df/. Collection has '/' or null in the collection name.
sh2936| Fri Oct 12 03:33:50 	jstests_tool_dumpfilename1.df to /data/db/jstests_tool_dumpfilename1_external/jstests_tool_dumpfilename1\df.bson
sh2936| Fri Oct 12 03:33:50 doing snapshot query
sh2936| Fri Oct 12 03:33:50 		 1 objects
sh2936| Fri Oct 12 03:33:50 	Metadata for jstests_tool_dumpfilename1.df to /data/db/jstests_tool_dumpfilename1_external/jstests_tool_dumpfilename1\df.metadata.json
 m31000| Fri Oct 12 03:33:50 [conn2] end connection 127.0.0.1:63651 (1 connection now open)
 m31000| Fri Oct 12 03:33:50 [conn2] thread conn2 stack usage was 19968 bytes,  which is the most so far
 m31000| Fri Oct 12 03:33:50 [conn1] CMD: drop jstests_tool_dumpfilename1.df/
 m31000| Fri Oct 12 03:33:50 [conn1] CMD: drop jstests_tool_dumpfilename1.df
Fri Oct 12 03:33:50 shell: started program mongorestore.exe --dir /data/db/jstests_tool_dumpfilename1_external/ --host 127.0.0.1:31000
sh4220| connected to: 127.0.0.1:31000
 m31000| Fri Oct 12 03:33:50 [initandlisten] connection accepted from 127.0.0.1:63652 #3 (2 connections now open)
sh4220| Fri Oct 12 03:33:50 /data/db/jstests_tool_dumpfilename1_external\jstests_tool_dumpfilename1\df.bson
sh4220| Fri Oct 12 03:33:50 	going into namespace [jstests_tool_dumpfilename1_external\jstests_tool_dumpfilename1.df]
 m31000| Fri Oct 12 03:33:50 [conn3] assertion 16256 Invalid ns [jstests_tool_dumpfilename1_external\jstests_tool_dumpfilename1.system.namespaces] ns:jstests_tool_dumpfilename1_external\jstests_tool_dumpfilename1.system.namespaces query:{ name: "jstests_tool_dumpfilename1_external\jstests_tool_dumpfilename1.df" }
 m31000| Fri Oct 12 03:33:50 [conn3] problem detected during query over jstests_tool_dumpfilename1_external\jstests_tool_dumpfilename1.system.namespaces : { $err: "Invalid ns [jstests_tool_dumpfilename1_external\jstests_tool_dumpfilename1.system.namespaces]", code: 16256 }
sh4220| Fri Oct 12 03:33:50 warning: Restoring to jstests_tool_dumpfilename1_external\jstests_tool_dumpfilename1.df without dropping. Restored data will be inserted without raising errors; check your server log
sh4220| 1 objects found
sh4220| Fri Oct 12 03:33:50 	Creating index: { key: { _id: 1 }, ns: "jstests_tool_dumpfilename1_external\jstests_tool_dumpfilename1.df", name: "_id_" }
 m31000| Fri Oct 12 03:33:50 [conn3] assertion 16256 Invalid ns [jstests_tool_dumpfilename1_external\jstests_tool_dumpfilename1.$cmd] ns:jstests_tool_dumpfilename1_external\jstests_tool_dumpfilename1.$cmd query:{ getlasterror: 1, w: 1 }
 m31000| Fri Oct 12 03:33:50 [conn3]  ntoskip:0 ntoreturn:1
 m31000| Fri Oct 12 03:33:50 [conn3] problem detected during query over jstests_tool_dumpfilename1_external\jstests_tool_dumpfilename1.$cmd : { $err: "Invalid ns [jstests_tool_dumpfilename1_external\jstests_tool_dumpfilename1.$cmd]", code: 16256 }
sh4220| Fri Oct 12 03:33:50 dev: lastError==0 won't report:nextSafe(): { $err: "Invalid ns [jstests_tool_dumpfilename1_external\jstests_tool_dumpfilename1.$cmd]", code: 16256 }
sh4220| assertion: 13106 nextSafe(): { $err: "Invalid ns [jstests_tool_dumpfilename1_external\jstests_tool_dumpfilename1.$cmd]", code: 16256 }
 m31000| Fri Oct 12 03:33:50 [conn3] end connection 127.0.0.1:63652 (1 connection now open)
 m31000| Fri Oct 12 03:33:50 [conn3] thread conn3 stack usage was 21128 bytes,  which is the most so far
assert: [1] != [0] are not equal : collection 2 does not restore properly
Error("Printing Stack Trace")@:0
()@src/mongo/shell/utils.js:37
("[1] != [0] are not equal : collection 2 does not restore properly")@src/mongo/shell/utils.js:58
(1,0,"collection 2 does not restore properly")@src/mongo/shell/utils.js:88
@D:\slave\Windows_64bit_DEBUG_Nightly\mongo\jstests\tool\dumpfilename1.js:22

Fri Oct 12 03:33:50 uncaught exception: [1] != [0] are not equal : collection 2 does not restore properly
failed to load: D:\slave\Windows_64bit_DEBUG_Nightly\mongo\jstests\tool\dumpfilename1.js
 m31000| Fri Oct 12 03:33:50 [initandlisten] connection accepted from 127.0.0.1:63653 #4 (2 connections now open)
 m31000| Fri Oct 12 03:33:50 [conn4] terminating, shutdown command received
 m31000| Fri Oct 12 03:33:50 dbexit: shutdown called
 m31000| Fri Oct 12 03:33:50 [conn4] shutdown: going to close listening sockets...
 m31000| Fri Oct 12 03:33:50 [conn4] closing listening socket: 412
 m31000| Fri Oct 12 03:33:50 [conn4] shutdown: going to flush diaglog...
 m31000| Fri Oct 12 03:33:50 [conn4] shutdown: going to close sockets...
 m31000| Fri Oct 12 03:33:50 [conn4] shutdown: waiting for fs preallocator...
 m31000| Fri Oct 12 03:33:50 [conn4] shutdown: lock for final commit...
 m31000| Fri Oct 12 03:33:50 [conn4] shutdown: final commit...
Fri Oct 12 03:33:50 DBClientCursor::init call() failed

In the good test, mongorestore displays this:

sh1508| Thu Oct 11 03:32:35 /data/db/jstests_tool_dumpfilename1_external/jstests_tool_dumpfilename1/df.bson
sh1508| Thu Oct 11 03:32:35 	going into namespace [jstests_tool_dumpfilename1.df]

In the bad test, mongorestore displays this:

sh4220| Fri Oct 12 03:33:50 /data/db/jstests_tool_dumpfilename1_external\jstests_tool_dumpfilename1\df.bson
sh4220| Fri Oct 12 03:33:50 	going into namespace [jstests_tool_dumpfilename1_external\jstests_tool_dumpfilename1.df]

The new/bad one is failing to extract the filename portion of the file specification, leaving the path part in it. This is perhaps caused by the change from forward slashes to backslashes in part of the file specification displayed on the first line.

Passing test:
http://buildlogs.mongodb.org/Nightly%20Windows%2064-bit%20DEBUG/builds/91/test/tools/dumpfilename1.js

Failing test:
http://buildlogs.mongodb.org/Nightly%20Windows%2064-bit%20DEBUG/builds/92/test/tools/dumpfilename1.js

depends on

SERVER-7341 Make mongorestore on Windows agnostic about directory separators (slash and backslash)

Closed

Details

Description

Attachments

Issue Links

Activity

People

Dates