reproduceable mongodump crash

[quatmax]

Hi Everyone!

I have a reproduceable crash with latest mongodump on windows 8.1.

One special collection cannot be dumped.

I repaired the whole database, I ran db.collection.validate( true ), everything looks ok!

The database is 12GB (Zipped 300MB, could be uploaded for debugging).

How can I find the problem?

best regards,

Max

//////////////////////////////////////////////////////////////////

mongodump output: 

D:\BitFactory\Max\work\Bin\Release\mongodump.exe --host 127.0.0.1:9000 --out "LinzBHS.9000.mongo/backup" --verbose

[...]

Thu Apr 03 11:32:08.841         db.CostCenter to LinzBHS.9000.mongo/backup\db\CostCenter.bson

Thu Apr 03 11:32:08.843                  166 objects

Thu Apr 03 11:32:08.849         Metadata for db.CostCenter to LinzBHS.9000.mongo/backup\db\CostCenter.metadata.json

Thu Apr 03 11:32:08.850         db.DateIndex to LinzBHS.9000.mongo/backup\db\DateIndex.bson

Thu Apr 03 11:32:08.852                  0 objects

Thu Apr 03 11:32:08.852         Metadata for db.DateIndex to LinzBHS.9000.mongo/backup\db\DateIndex.metadata.json

Thu Apr 03 11:32:08.853         db.DateIndexQuery to LinzBHS.9000.mongo/backup\db\DateIndexQuery.bson

Thu Apr 03 11:32:08.855                  0 objects

Thu Apr 03 11:32:08.856         Metadata for db.DateIndexQuery to LinzBHS.9000.mongo/backup\db\DateIndexQuery.metadata.json

Thu Apr 03 11:32:08.857         db.Day to LinzBHS.9000.mongo/backup\db\Day.bson

Thu Apr 03 11:32:11.008                 Collection File Writing Progress: 310300/3791036        8%  (objects)

Thu Apr 03 11:32:14.436                 Collection File Writing Progress: 582000/3791036        15% (objects)

Thu Apr 03 11:32:17.015                 Collection File Writing Progress: 652500/3791036        17% (objects)

Thu Apr 03 11:32:20.230                 Collection File Writing Progress: 889600/3791036        23% (objects)

Thu Apr 03 11:32:22.305 Socket recv() errno:10054 Eine vorhandene Verbindung wurde vom Remotehost geschlossen. 127.0.0.1:9000

Thu Apr 03 11:32:22.469 SocketException: remote: 127.0.0.1:9000 error: 9001 socket exception [RECV_ERROR] server [127.0.0.1:9000]

Thu Apr 03 11:32:22.469 User Assertion: 16465:recv failed while exhausting cursor

assertion: 16465 recv failed while exhausting cursor

[...]

mongod.log:

Thu Apr 03 11:31:45.787 [initandlisten] MongoDB starting : pid=10708 port=9000 dbpath=LinzBHS.9000.mongo\db 64-bit host=Max

Thu Apr 03 11:31:45.787 [initandlisten] db version v2.4.8

Thu Apr 03 11:31:45.787 [initandlisten] git version: a350fc38922fbda2cec8d5dd842237b904eafc14

Thu Apr 03 11:31:45.788 [initandlisten] build info: windows sys.getwindowsversion(major=6, minor=1, build=7601, platform=2, service_pack='Service Pack 1') BOOST_LIB_VERSION=1_49

Thu Apr 03 11:31:45.788 [initandlisten] allocator: system

Thu Apr 03 11:31:45.788 [initandlisten] options: { dbpath: "LinzBHS.9000.mongo\db", logappend: true, logpath: "LinzBHS.9000.mongo\mongod.log", nohttpinterface: true, port: 9000 }

Thu Apr 03 11:31:45.791 [initandlisten] journal dir=LinzBHS.9000.mongo\db\journal

Thu Apr 03 11:31:45.791 [initandlisten] recover : no journal files present, no recovery needed

Thu Apr 03 11:31:45.894 [initandlisten] waiting for connections on port 9000

Thu Apr 03 11:31:46.227 [initandlisten] connection accepted from 127.0.0.1:63106 #1 (1 connection now open)

Thu Apr 03 11:31:46.228 [conn1] end connection 127.0.0.1:63106 (0 connections now open)

Thu Apr 03 11:31:46.228 [initandlisten] connection accepted from 127.0.0.1:63108 #2 (1 connection now open)

Thu Apr 03 11:31:52.844 [initandlisten] connection accepted from 127.0.0.1:63117 #3 (2 connections now open)

Thu Apr 03 11:31:54.717 [conn3] getmore db.ChangeLogEntry query: { query: {}, $snapshot: true } cursorid:32827011251086 ntoreturn:0 exhaust:1 keyUpdates:0 numYields: 109 locks(micros) r:138913 nreturned:15698 reslen:4194372 112ms

Thu Apr 03 11:31:56.137 [conn3] getmore db.ChangeLogEntry query: { query: {}, $snapshot: true } cursorid:32827011251086 ntoreturn:0 exhaust:1 keyUpdates:0 numYields: 77 locks(micros) r:190001 nreturned:15626 reslen:4194417 122ms

Thu Apr 03 11:31:57.410 [conn3] getmore db.ChangeLogEntry query: { query: {}, $snapshot: true } cursorid:32827011251086 ntoreturn:0 exhaust:1 keyUpdates:0 numYields: 89 locks(micros) r:157119 nreturned:15576 reslen:4194540 149ms

Thu Apr 03 11:31:57.804 [conn3] getmore db.ChangeLogEntry query: { query: {}, $snapshot: true } cursorid:32827011251086 ntoreturn:0 exhaust:1 keyUpdates:0 numYields: 104 locks(micros) r:498535 nreturned:15653 reslen:4194373 390ms

Thu Apr 03 11:31:58.752 [conn3] getmore db.ChangeLogEntry query: { query: {}, $snapshot: true } cursorid:32827011251086 ntoreturn:0 exhaust:1 keyUpdates:0 numYields: 85 locks(micros) r:95502 nreturned:15646 reslen:4194493 112ms

Thu Apr 03 11:31:59.013 [conn3] getmore db.ChangeLogEntry query: { query: {}, $snapshot: true } cursorid:32827011251086 ntoreturn:0 exhaust:1 keyUpdates:0 numYields: 97 locks(micros) r:134185 nreturned:15576 reslen:4194484 102ms

Thu Apr 03 11:32:00.211 [conn3] getmore db.ChangeLogEntry query: { query: {}, $snapshot: true } cursorid:32827011251086 ntoreturn:0 exhaust:1 keyUpdates:0 numYields: 82 locks(micros) r:199439 nreturned:15681 reslen:4194388 155ms

Thu Apr 03 11:32:01.920 [conn3] getmore db.ChangeLogEntry query: { query: {}, $snapshot: true } cursorid:32827011251086 ntoreturn:0 exhaust:1 keyUpdates:0 numYields: 65 locks(micros) r:677406 nreturned:15586 reslen:4194512 497ms

Thu Apr 03 11:32:02.887 [conn3] getmore db.ChangeLogEntry query: { query: {}, $snapshot: true } cursorid:32827011251086 ntoreturn:0 exhaust:1 keyUpdates:0 numYields: 115 locks(micros) r:101157 nreturned:15542 reslen:4194423 127ms

Thu Apr 03 11:32:03.345 [conn3] getmore db.ChangeLogEntry query: { query: {}, $snapshot: true } cursorid:32827011251086 ntoreturn:0 exhaust:1 keyUpdates:0 numYields: 77 locks(micros) r:288485 nreturned:15647 reslen:4194360 261ms

Thu Apr 03 11:32:03.534 [conn3] getmore db.ChangeLogEntry query: { query: {}, $snapshot: true } cursorid:32827011251086 ntoreturn:0 exhaust:1 keyUpdates:0 numYields: 80 locks(micros) r:327982 nreturned:15603 reslen:4194373 185ms

Thu Apr 03 11:32:04.589 [conn3] getmore db.ChangeLogEntry query: { query: {}, $snapshot: true } cursorid:32827011251086 ntoreturn:0 exhaust:1 keyUpdates:0 numYields: 79 locks(micros) r:214564 nreturned:15765 reslen:4194492 137ms

Thu Apr 03 11:32:05.917 [conn3] getmore db.ChangeLogEntry query: { query: {}, $snapshot: true } cursorid:32827011251086 ntoreturn:0 exhaust:1 keyUpdates:0 numYields: 95 locks(micros) r:198718 nreturned:15475 reslen:4194555 137ms

Thu Apr 03 11:32:07.301 [conn3] getmore db.ChangeLogEntry query: { query: {}, $snapshot: true } cursorid:32827011251086 ntoreturn:0 exhaust:1 keyUpdates:0 numYields: 106 locks(micros) r:258262 nreturned:15678 reslen:4194460 191ms

Thu Apr 03 11:32:08.272 [conn3] getmore db.ChangeLogEntry query: { query: {}, $snapshot: true } cursorid:32827011251086 ntoreturn:0 exhaust:1 keyUpdates:0 numYields: 87 locks(micros) r:134689 nreturned:15367 reslen:4194556 111ms

Thu Apr 03 11:32:08.702 [conn3] getmore db.ChangeLogEntry query: { query: {}, $snapshot: true } cursorid:32827011251086 ntoreturn:0 keyUpdates:0 numYields: 57 locks(micros) r:233894 nreturned:10526 reslen:2812952 171ms

Thu Apr 03 11:32:10.051 [conn3] getmore db.Day query: { query: {}, $snapshot: true } cursorid:96521395508380 ntoreturn:0 exhaust:1 keyUpdates:0 numYields: 7 locks(micros) r:219962 nreturned:3778 reslen:4194490 110ms

Thu Apr 03 11:32:10.265 [conn3] getmore db.Day query: { query: {}, $snapshot: true } cursorid:96521395508380 ntoreturn:0 exhaust:1 keyUpdates:0 numYields: 17 locks(micros) r:397013 nreturned:3711 reslen:4195201 211ms

Thu Apr 03 11:32:10.477 [conn3] getmore db.Day query: { query: {}, $snapshot: true } cursorid:96521395508380 ntoreturn:0 exhaust:1 keyUpdates:0 numYields: 13 locks(micros) r:189106 nreturned:3687 reslen:4194720 106ms

Thu Apr 03 11:32:10.619 [conn3] getmore db.Day query: { query: {}, $snapshot: true } cursorid:96521395508380 ntoreturn:0 exhaust:1 keyUpdates:0 numYields: 3 locks(micros) r:271933 nreturned:2800 reslen:4196811 139ms

Thu Apr 03 11:32:11.466 [conn3] getmore db.Day query: { query: {}, $snapshot: true } cursorid:96521395508380 ntoreturn:0 exhaust:1 keyUpdates:0 numYields: 12 locks(micros) r:362285 nreturned:4261 reslen:4194731 208ms

Thu Apr 03 11:32:12.896 [conn3] getmore db.Day query: { query: {}, $snapshot: true } cursorid:96521395508380 ntoreturn:0 exhaust:1 keyUpdates:0 numYields: 24 locks(micros) r:431200 nreturned:6099 reslen:4195481 286ms

Thu Apr 03 11:32:13.572 [conn3] getmore db.Day query: { query: {}, $snapshot: true } cursorid:96521395508380 ntoreturn:0 exhaust:1 keyUpdates:0 numYields: 35 locks(micros) r:939622 nreturned:4282 reslen:4194378 674ms

Thu Apr 03 11:32:14.424 [conn3] getmore db.Day query: { query: {}, $snapshot: true } cursorid:96521395508380 ntoreturn:0 exhaust:1 keyUpdates:0 numYields: 23 locks(micros) r:741319 nreturned:3506 reslen:4196845 652ms

Thu Apr 03 11:32:15.465 [conn3] getmore db.Day query: { query: {}, $snapshot: true } cursorid:96521395508380 ntoreturn:0 exhaust:1 keyUpdates:0 numYields: 38 locks(micros) r:1509465 nreturned:3495 reslen:4194492 1039ms

Thu Apr 03 11:32:15.932 [conn3] getmore db.Day query: { query: {}, $snapshot: true } cursorid:96521395508380 ntoreturn:0 exhaust:1 keyUpdates:0 numYields: 8 locks(micros) r:487035 nreturned:2108 reslen:4196736 463ms

Thu Apr 03 11:32:18.293 [conn3] getmore db.Day query: { query: {}, $snapshot: true } cursorid:96521395508380 ntoreturn:0 exhaust:1 keyUpdates:0 numYields: 38 locks(micros) r:316429 nreturned:3258 reslen:4194613 220ms

Thu Apr 03 11:32:19.800 [conn3] getmore db.Day query: { query: {}, $snapshot: true } cursorid:96521395508380 ntoreturn:0 exhaust:1 keyUpdates:0 numYields: 40 locks(micros) r:747298 nreturned:4358 reslen:4195425 434ms

Thu Apr 03 11:32:20.218 [conn3] getmore db.Day query: { query: {}, $snapshot: true } cursorid:96521395508380 ntoreturn:0 exhaust:1 keyUpdates:0 numYields: 30 locks(micros) r:608013 nreturned:3468 reslen:4195470 414ms

Thu Apr 03 11:32:20.937 [conn3] getmore db.Day query: { query: {}, $snapshot: true } cursorid:96521395508380 ntoreturn:0 exhaust:1 keyUpdates:0 numYields: 34 locks(micros) r:215598 nreturned:4695 reslen:4194368 135ms

Thu Apr 03 11:32:22.448 [conn3] SocketException handling request, closing client connection: 9001 socket exception [SEND_ERROR] server [127.0.0.1:63117] 

[Matt Kangas]

Hi Max,

I don't see anything unusual in your log output that explains the problem you are seeing. Both sides (mongodump and mongod) both report a networking error, nothing more.

I suggest you open a community support ticket so we have a way to track progress on your issue. A couple of things that would be worth mentioning in the ticket:

1. What version of mongodump are you using? I see the server is v2.4.8.

2. Does it reproduce if you dump only the "Day" collection?

3. If you increase the log level on mongod (-v, -vvvv, etc), is a more specific error message than SEND_ERROR displayed?

4. What is the largest BSON document in db.Day? I'm wondering if there is a really large one.

Let me know when the ticket is created and I will happy to follow up.

--Matt

--
You received this message because you are subscribed to the Google Groups "mongodb-dev" group.
To unsubscribe from this group and stop receiving emails from it, send an email to mongodb-dev...@googlegroups.com.
To post to this group, send email to mongo...@googlegroups.com.
Visit this group at http://groups.google.com/group/mongodb-dev.
For more options, visit https://groups.google.com/d/optout.

[quatmax]

Hi Matt!

Thanks for the answer! I created following issue:

https://jira.mongodb.org/browse/SERVER-13571

BR,

Max