Loading...

Type: Bug
Resolution: Duplicate
Priority: Major - P3
Fix Version/s: None
Affects Version/s: 3.0.7
Component/s: Admin
Labels:
None
Environment:
OS X 10.11.0
MongoDB installed via Homebrew (tested both bottled and built from source)

Operating System:
OS X
Steps To Reproduce:
Hide

Backup a collection using 3.0.7.

Attempt to restore the collection to a new database.

I have only tested a few collections, from a single DB, but all have failed. I have tested backups from a 3.0.6 instance and backups from a 3.0.7 instance that was upgraded from 3.0.6.
Show
Backup a collection using 3.0.7. Attempt to restore the collection to a new database. I have only tested a few collections, from a single DB, but all have failed. I have tested backups from a 3.0.6 instance and backups from a 3.0.7 instance that was upgraded from 3.0.6.

I cannot restore collections to 3.0.7 from mongodump files that restore fine to 3.0.6. The server log indicates that it thinks objects with invalid (too large) BSON sizes are being restored.

mongorestore log:

$ mongorestore -vvvvv -d test3 --drop dump/development/interviews.bson
2015-10-14T17:13:38.455-0500	checking options
2015-10-14T17:13:38.455-0500		dumping with object check disabled
2015-10-14T17:13:38.459-0500	connected to node type: standalone
2015-10-14T17:13:38.459-0500	standalone server: setting write concern w to 1
2015-10-14T17:13:38.459-0500	using write concern: w='1', j=false, fsync=false, wtimeout=0
2015-10-14T17:13:38.459-0500	mongorestore target is a file, not a directory
2015-10-14T17:13:38.459-0500	inferred collection 'interviews' from file
2015-10-14T17:13:38.459-0500	setting number of insertions workers to number of parallel collections (4)
2015-10-14T17:13:38.459-0500	checking for collection data in dump/development/interviews.bson
2015-10-14T17:13:38.459-0500	reading collection interviews for database test3 from dump/development/interviews.bson
2015-10-14T17:13:38.459-0500	scanning directory dump/development for metadata file
2015-10-14T17:13:38.459-0500	found metadata for collection at dump/development/interviews.metadata.json
2015-10-14T17:13:38.459-0500	finalizing intent manager with multi-database longest task first prioritizer
2015-10-14T17:13:38.459-0500	restoring up to 4 collections in parallel
2015-10-14T17:13:38.459-0500	starting restore routine with id=3
2015-10-14T17:13:38.459-0500	starting restore routine with id=0
2015-10-14T17:13:38.459-0500	ending restore routine with id=0, no more work to do
2015-10-14T17:13:38.459-0500	starting restore routine with id=1
2015-10-14T17:13:38.459-0500	starting restore routine with id=2
2015-10-14T17:13:38.459-0500	ending restore routine with id=2, no more work to do
2015-10-14T17:13:38.459-0500	ending restore routine with id=1, no more work to do
2015-10-14T17:13:38.460-0500	dropping collection test3.interviews before restoring
2015-10-14T17:13:38.460-0500	reading metadata file from dump/development/interviews.metadata.json
2015-10-14T17:13:38.461-0500	creating collection test3.interviews using options from metadata
2015-10-14T17:13:38.461-0500	restoring test3.interviews from file dump/development/interviews.bson
2015-10-14T17:13:38.461-0500		file dump/development/interviews.bson is 1285186099 bytes
2015-10-14T17:13:38.462-0500	using 4 insertion workers
2015-10-14T17:13:38.805-0500	Failed: restore error: test3.interviews: error restoring from dump/development/interviews.bson: insertion error: EOF

Server log:

2015-10-14T17:13:38.458-0500 I NETWORK  [initandlisten] connection accepted from 127.0.0.1:59878 #15 (1 connection now open)
2015-10-14T17:13:38.458-0500 D COMMAND  [conn15] run command admin.$cmd { getnonce: 1 }
2015-10-14T17:13:38.458-0500 I COMMAND  [conn15] command admin.$cmd command: getnonce { getnonce: 1 } keyUpdates:0 writeConflicts:0 numYields:0 reslen:65 locks:{} 0ms
2015-10-14T17:13:38.458-0500 D COMMAND  [conn15] run command admin.$cmd { ping: 1 }
2015-10-14T17:13:38.458-0500 I COMMAND  [conn15] command admin.$cmd command: ping { ping: 1 } keyUpdates:0 writeConflicts:0 numYields:0 reslen:37 locks:{} 0ms
2015-10-14T17:13:38.458-0500 D COMMAND  [conn15] run command admin.$cmd { ismaster: 1 }
2015-10-14T17:13:38.458-0500 I COMMAND  [conn15] command admin.$cmd command: isMaster { ismaster: 1 } keyUpdates:0 writeConflicts:0 numYields:0 reslen:178 locks:{} 0ms
2015-10-14T17:13:38.459-0500 D COMMAND  [conn15] run command admin.$cmd { ping: 1 }
2015-10-14T17:13:38.459-0500 I COMMAND  [conn15] command admin.$cmd command: ping { ping: 1 } keyUpdates:0 writeConflicts:0 numYields:0 reslen:37 locks:{} 0ms
2015-10-14T17:13:38.459-0500 D COMMAND  [conn15] run command admin.$cmd { isMaster: 1 }
2015-10-14T17:13:38.459-0500 I COMMAND  [conn15] command admin.$cmd command: isMaster { isMaster: 1 } keyUpdates:0 writeConflicts:0 numYields:0 reslen:178 locks:{} 0ms
2015-10-14T17:13:38.459-0500 D COMMAND  [conn15] run command admin.$cmd { isMaster: 1 }
2015-10-14T17:13:38.459-0500 I COMMAND  [conn15] command admin.$cmd command: isMaster { isMaster: 1 } keyUpdates:0 writeConflicts:0 numYields:0 reslen:178 locks:{} 0ms
2015-10-14T17:13:38.459-0500 D COMMAND  [conn15] run command test3.$cmd { listCollections: 1, cursor: { batchSize: 0 } }
2015-10-14T17:13:38.460-0500 I COMMAND  [conn15] command test3.$cmd command: listCollections { listCollections: 1, cursor: { batchSize: 0 } } keyUpdates:0 writeConflicts:0 numYields:0 reslen:114 locks:{ Global: { acquireCount: { r: 2 } }, MMAPV1Journal: { acquireCount: { r: 1 } }, Database: { acquireCount: { R: 1 } } } 0ms
2015-10-14T17:13:38.460-0500 I QUERY    [conn15] getmore test3.$cmd.listCollections cursorid:7546192025 ntoreturn:0 keyUpdates:0 writeConflicts:0 numYields:0 nreturned:2 reslen:115 locks:{} 0ms
2015-10-14T17:13:38.460-0500 D COMMAND  [conn15] run command test3.$cmd { drop: "interviews" }
2015-10-14T17:13:38.460-0500 I COMMAND  [conn15] CMD: drop test3.interviews
2015-10-14T17:13:38.460-0500 D STORAGE  [conn15] dropCollection: test3.interviews
2015-10-14T17:13:38.460-0500 D INDEX    [conn15]         dropAllIndexes dropping: { v: 1, key: { _id: 1 }, name: "_id_", ns: "test3.interviews" }
2015-10-14T17:13:38.460-0500 D STORAGE  [conn15] test3.interviews: clearing plan cache - collection info cache reset
2015-10-14T17:13:38.460-0500 D STORAGE  [conn15]         dropIndexes done
2015-10-14T17:13:38.460-0500 D STORAGE  [conn15]    ***** ROLLING BACK 0 disk writes
2015-10-14T17:13:38.460-0500 D STORAGE  [conn15]    ***** ROLLING BACK 0 custom changes
2015-10-14T17:13:38.460-0500 I COMMAND  [conn15] command test3.$cmd command: drop { drop: "interviews" } keyUpdates:0 writeConflicts:0 numYields:0 reslen:79 locks:{ Global: { acquireCount: { r: 1, w: 1 } }, MMAPV1Journal: { acquireCount: { w: 2 } }, Database: { acquireCount: { W: 1 } }, Metadata: { acquireCount: { W: 2 } } } 0ms
2015-10-14T17:13:38.461-0500 D COMMAND  [conn15] run command test3.$cmd { create: "interviews", flags: 1 }
2015-10-14T17:13:38.461-0500 D STORAGE  [conn15] create collection test3.interviews { flags: 1 }
2015-10-14T17:13:38.461-0500 D STORAGE  [conn15] MmapV1ExtentManager::allocateExtent desiredSize:8192 fromFreeList: 1 eloc: 0:5000
2015-10-14T17:13:38.461-0500 D STORAGE  [conn15] test3.interviews: clearing plan cache - collection info cache reset
2015-10-14T17:13:38.461-0500 D STORAGE  [conn15] allocating new extent
2015-10-14T17:13:38.461-0500 D STORAGE  [conn15] MmapV1ExtentManager::allocateExtent desiredSize:131072 fromFreeList: 1 eloc: 0:9000
2015-10-14T17:13:38.461-0500 D STORAGE  [conn15] test3.interviews: clearing plan cache - collection info cache reset
2015-10-14T17:13:38.461-0500 D STORAGE  [conn15]    ***** ROLLING BACK 0 disk writes
2015-10-14T17:13:38.461-0500 D STORAGE  [conn15]    ***** ROLLING BACK 0 custom changes
2015-10-14T17:13:38.461-0500 I COMMAND  [conn15] command test3.$cmd command: create { create: "interviews", flags: 1 } keyUpdates:0 writeConflicts:0 numYields:0 reslen:37 locks:{ Global: { acquireCount: { r: 1, w: 1 } }, MMAPV1Journal: { acquireCount: { w: 2 } }, Database: { acquireCount: { W: 1 } }, Metadata: { acquireCount: { W: 2 } } } 0ms
2015-10-14T17:13:38.556-0500 I NETWORK  [initandlisten] connection accepted from 127.0.0.1:59879 #16 (2 connections now open)
2015-10-14T17:13:38.556-0500 D COMMAND  [conn16] run command admin.$cmd { getnonce: 1 }
2015-10-14T17:13:38.556-0500 I COMMAND  [conn16] command admin.$cmd command: getnonce { getnonce: 1 } keyUpdates:0 writeConflicts:0 numYields:0 reslen:65 locks:{} 0ms
2015-10-14T17:13:38.560-0500 I NETWORK  [initandlisten] connection accepted from 127.0.0.1:59880 #17 (3 connections now open)
2015-10-14T17:13:38.560-0500 D COMMAND  [conn17] run command admin.$cmd { getnonce: 1 }
2015-10-14T17:13:38.560-0500 I COMMAND  [conn17] command admin.$cmd command: getnonce { getnonce: 1 } keyUpdates:0 writeConflicts:0 numYields:0 reslen:64 locks:{} 0ms
2015-10-14T17:13:38.570-0500 I NETWORK  [initandlisten] connection accepted from 127.0.0.1:59881 #18 (4 connections now open)
2015-10-14T17:13:38.570-0500 D COMMAND  [conn18] run command admin.$cmd { getnonce: 1 }
2015-10-14T17:13:38.570-0500 I COMMAND  [conn18] command admin.$cmd command: getnonce { getnonce: 1 } keyUpdates:0 writeConflicts:0 numYields:0 reslen:65 locks:{} 0ms
2015-10-14T17:13:38.650-0500 D JOURNAL  [journal writer] lsn set 166014
2015-10-14T17:13:38.798-0500 I -        [conn18] Assertion: 10334:BSONObj size: 33541467 (0x1FFCD5B) is invalid. Size must be between 0 and 16793600(16MB) First element: insert: "interviews"
2015-10-14T17:13:38.804-0500 I CONTROL  [conn18]
 0x105eca5b9 0x105e772ae 0x105e64852 0x105e646fa 0x105763109 0x10594483f 0x1057a36fd 0x105a0a6be 0x1057432ce 0x105e87421 0x105efff69 0x7fff8f13a9b1 0x7fff8f13a92e 0x7fff8f138385
----- BEGIN BACKTRACE -----
{"backtrace":[{"b":"10573C000","o":"78E5B9"},{"b":"10573C000","o":"73B2AE"},{"b":"10573C000","o":"728852"},{"b":"10573C000","o":"7286FA"},{"b":"10573C000","o":"27109"},{"b":"10573C000","o":"20883F"},{"b":"10573C000","o":"676FD"},{"b":"10573C000","o":"2CE6BE"},{"b":"10573C000","o":"72CE"},{"b":"10573C000","o":"74B421"},{"b":"10573C000","o":"7C3F69"},{"b":"7FFF8F137000","o":"39B1"},{"b":"7FFF8F137000","o":"392E"},{"b":"7FFF8F137000","o":"1385"}],"processInfo":{ "mongodbVersion" : "3.0.7", "gitVersion" : "nogitversion", "uname" : { "sysname" : "Darwin", "release" : "15.0.0", "version" : "Darwin Kernel Version 15.0.0: Wed Aug 26 16:57:32 PDT 2015; root:xnu-3247.1.106~1/RELEASE_X86_64", "machine" : "x86_64" }, "somap" : [ { "path" : "/usr/local/opt/mongodb/bin/mongod", "machType" : 2, "b" : "10573C000", "buildId" : "461E0283714B3126B5B04D4EB8808F43" }, { "path" : "/usr/lib/libSystem.B.dylib", "machType" : 6, "b" : "7FFF8E274000", "buildId" : "E48AAE3F370E34AEAECA4CA28F211479" }, { "path" : "/usr/lib/libc++.1.dylib", "machType" : 6, "b" : "7FFF9817B000", "buildId" : "54190E1BEE493D6DAC292813D7380BA5" }, { "path" : "/usr/lib/system/libcache.dylib", "machType" : 6, "b" : "7FFF8A46D000", "buildId" : "4948E2C8867F3E9DAAE72F30F0B345C6" }, { "path" : "/usr/lib/system/libcommonCrypto.dylib", "machType" : 6, "b" : "7FFF947CF000", "buildId" : "BD1DCF1983533F6AAFFAEBBA29A302A8" }, { "path" : "/usr/lib/system/libcompiler_rt.dylib", "machType" : 6, "b" : "7FFF8F247000", "buildId" : "253B36E5572D377DAE99A02CE32590E5" }, { "path" : "/usr/lib/system/libcopyfile.dylib", "machType" : 6, "b" : "7FFF878B1000", "buildId" : "CA2602ABE8B73CD8A0C5D86E35FDA09F" }, { "path" : "/usr/lib/system/libcorecrypto.dylib", "machType" : 6, "b" : "7FFF8747A000", "buildId" : "4E1B969F84493B21988051AD58E25AA6" }, { "path" : "/usr/lib/system/libdispatch.dylib", "machType" : 6, "b" : "7FFF94642000", "buildId" : "6B38497E944834339D6B6223F2A99431" }, { "path" : "/usr/lib/system/libdyld.dylib", "machType" : 6, "b" : "7FFF9657A000", "buildId" : "F9D64D8C4C333D06B7F8697F13292894" }, { "path" : "/usr/lib/system/libkeymgr.dylib", "machType" : 6, "b" : "7FFF8BF96000", "buildId" : "470802808B573D758A209E100864DE27" }, { "path" : "/usr/lib/system/liblaunch.dylib", "machType" : 6, "b" : "7FFF8A551000", "buildId" : "7EC0F29743CC3D11B46B7E72E372648A" }, { "path" : "/usr/lib/system/libmacho.dylib", "machType" : 6, "b" : "7FFF8A8EB000", "buildId" : "A9EC23EC11A03B4FA8ACB990C8267A6E" }, { "path" : "/usr/lib/system/libquarantine.dylib", "machType" : 6, "b" : "7FFF90671000", "buildId" : "1693C5FEEA0A312285EB7950ECC7435A" }, { "path" : "/usr/lib/system/libremovefile.dylib", "machType" : 6, "b" : "7FFF96E81000", "buildId" : "C7CFF5F2AFFB3C8DBDB4D66D50E657C0" }, { "path" : "/usr/lib/system/libsystem_asl.dylib", "machType" : 6, "b" : "7FFF982B1000", "buildId" : "97D794DA8CE53676AC5E364F6D172BDA" }, { "path" : "/usr/lib/system/libsystem_blocks.dylib", "machType" : 6, "b" : "7FFF89B71000", "buildId" : "1B4F1F10823E378181626884D14DF0D6" }, { "path" : "/usr/lib/system/libsystem_c.dylib", "machType" : 6, "b" : "7FFF8A1B6000", "buildId" : "A60CE86D1FF332ADA672C7597F884529" }, { "path" : "/usr/lib/system/libsystem_configuration.dylib", "machType" : 6, "b" : "7FFF97AA5000", "buildId" : "EB55C3D8048D350EBF240CBD4479D51C" }, { "path" : "/usr/lib/system/libsystem_coreservices.dylib", "machType" : 6, "b" : "7FFF90665000", "buildId" : "692631A0192332CA9BD5044B1382FFDE" }, { "path" : "/usr/lib/system/libsystem_coretls.dylib", "machType" : 6, "b" : "7FFF93DD2000", "buildId" : "21EDACF1D9B33086982160EB75E7F965" }, { "path" : "/usr/lib/system/libsystem_dnssd.dylib", "machType" : 6, "b" : "7FFF96D6B000", "buildId" : "DB6AB2064AD8369DBF571D246AD60582" }, { "path" : "/usr/lib/system/libsystem_info.dylib", "machType" : 6, "b" : "7FFF8756D000", "buildId" : "65D0643AC8AE3E8D9F6EE4AD823F16B2" }, { "path" : "/usr/lib/system/libsystem_kernel.dylib", "machType" : 6, "b" : "7FFF93A94000", "buildId" : "7DD242A1E2BF39D18787B174046E4F15" }, { "path" : "/usr/lib/system/libsystem_m.dylib", "machType" : 6, "b" : "7FFF8FB5D000", "buildId" : "07D5037230ED3B039FA00662BF8F0098" }, { "path" : "/usr/lib/system/libsystem_malloc.dylib", "machType" : 6, "b" : "7FFF899F2000", "buildId" : "1B57A6143D603F87876F7DB4AF38120F" }, { "path" : "/usr/lib/system/libsystem_network.dylib", "machType" : 6, "b" : "7FFF9A8F8000", "buildId" : "14ECA259D4713E47A843FF0990577893" }, { "path" : "/usr/lib/system/libsystem_networkextension.dylib", "machType" : 6, "b" : "7FFF9A8AC000", "buildId" : "4736FCC59DBA31F4AAC8CD0A177CF502" }, { "path" : "/usr/lib/system/libsystem_notify.dylib", "machType" : 6, "b" : "7FFF96E41000", "buildId" : "56ABC155CB9930A8A8B1C204B5615092" }, { "path" : "/usr/lib/system/libsystem_platform.dylib", "machType" : 6, "b" : "7FFF92A09000", "buildId" : "3F4D2390E3DE3C24A51595DFAC8671C4" }, { "path" : "/usr/lib/system/libsystem_pthread.dylib", "machType" : 6, "b" : "7FFF8F137000", "buildId" : "1373D0F1C6CA364EA6BA8BDBD0D34670" }, { "path" : "/usr/lib/system/libsystem_sandbox.dylib", "machType" : 6, "b" : "7FFF9B01B000", "buildId" : "2F36D536482C39ECBAFD72297728F0A4" }, { "path" : "/usr/lib/system/libsystem_secinit.dylib", "machType" : 6, "b" : "7FFF90897000", "buildId" : "932ED582E80F39DAB0FAF1BC5F1AD2F8" }, { "path" : "/usr/lib/system/libsystem_trace.dylib", "machType" : 6, "b" : "7FFF8B30A000", "buildId" : "E26A91EAAD673FA2A3B679A93DCC716E" }, { "path" : "/usr/lib/system/libunc.dylib", "machType" : 6, "b" : "7FFF9692D000", "buildId" : "D9B0C7B186483AAC931CE7CD362FAA8A" }, { "path" : "/usr/lib/system/libunwind.dylib", "machType" : 6, "b" : "7FFF990F4000", "buildId" : "FDA18078A7753BAFA5A68A7B75D6AA99" }, { "path" : "/usr/lib/system/libxpc.dylib", "machType" : 6, "b" : "7FFF98C42000", "buildId" : "3E09C275A33B357AB0ABA2DDF88EC9D5" }, { "path" : "/usr/lib/libobjc.A.dylib", "machType" : 6, "b" : "7FFF8C396000", "buildId" : "CE3C3C78A7BB3147837555424032FF5E" }, { "path" : "/usr/lib/libauto.dylib", "machType" : 6, "b" : "7FFF8A817000", "buildId" : "460B0167C89B37EC823C52F684B31C26" }, { "path" : "/usr/lib/libc++abi.dylib", "machType" : 6, "b" : "7FFF8A43E000", "buildId" : "F5027B461801344DBD512E6D188C8900" }, { "path" : "/usr/lib/libDiagnosticMessagesClient.dylib", "machType" : 6, "b" : "7FFF8A8E9000", "buildId" : "F2D8CFCCA00A36759C01EF0C663F2445" } ] }}
 mongod(_ZN5mongo15printStackTraceERNSt3__113basic_ostreamIcNS0_11char_traitsIcEEEE+0x39) [0x105eca5b9]
 mongod(_ZN5mongo10logContextEPKc+0x10E) [0x105e772ae]
 mongod(_ZN5mongo11msgassertedEiPKc+0x152) [0x105e64852]
 mongod(_ZN5mongo11msgassertedEiRKNSt3__112basic_stringIcNS0_11char_traitsIcEENS0_9allocatorIcEEEE+0x1A) [0x105e646fa]
 mongod(_ZNK5mongo7BSONObj14_assertInvalidEv+0x4B9) [0x105763109]
 mongod(_ZN5mongo9DbMessage9nextJsObjEv+0x9F) [0x10594483f]
 mongod(_ZN5mongo12QueryMessageC2ERNS_9DbMessageE+0x5D) [0x1057a36fd]
 mongod(_ZN5mongo16assembleResponseEPNS_16OperationContextERNS_7MessageERNS_10DbResponseERKNS_11HostAndPortE+0x44E) [0x105a0a6be]
 mongod(_ZN5mongo16MyMessageHandler7processERNS_7MessageEPNS_21AbstractMessagingPortEPNS_9LastErrorE+0xDE) [0x1057432ce]
 mongod(_ZN5mongo17PortMessageServer17handleIncomingMsgEPv+0x291) [0x105e87421]
 mongod(_ZN5boost12_GLOBAL__N_112thread_proxyEPv+0xA9) [0x105efff69]
 libsystem_pthread.dylib(_pthread_body+0x83) [0x7fff8f13a9b1]
 libsystem_pthread.dylib(_pthread_body+0x0) [0x7fff8f13a92e]
 libsystem_pthread.dylib(thread_start+0xD) [0x7fff8f138385]
-----  END BACKTRACE  -----
2015-10-14T17:13:38.804-0500 I NETWORK  [conn18] AssertionException handling request, closing client connection: 10334 BSONObj size: 33541467 (0x1FFCD5B) is invalid. Size must be between 0 and 16793600(16MB) First element: insert: "interviews"
2015-10-14T17:13:38.849-0500 D NETWORK  [conn16] SocketException: remote: 127.0.0.1:59879 error: 9001 socket exception [CLOSED] server [127.0.0.1:59879]
2015-10-14T17:13:38.849-0500 I NETWORK  [conn16] end connection 127.0.0.1:59879 (2 connections now open)
2015-10-14T17:13:38.849-0500 D NETWORK  [conn15] SocketException: remote: 127.0.0.1:59878 error: 9001 socket exception [CLOSED] server [127.0.0.1:59878]
2015-10-14T17:13:38.849-0500 I NETWORK  [conn15] end connection 127.0.0.1:59878 (1 connection now open)
2015-10-14T17:13:38.851-0500 D NETWORK  [conn17] SocketException: remote: 127.0.0.1:59880 error: 9001 socket exception [CLOSED] server [127.0.0.1:59880]
2015-10-14T17:13:38.851-0500 I NETWORK  [conn17] end connection 127.0.0.1:59880 (0 connections now open)
Waiting for data... (interrupt to abort)

duplicates

TOOLS-939 Error restoring database "insertion error: EOF"

Closed

Details

Description

Attachments

Issue Links

Activity

People

Dates