[SERVER-8319] Server crashes when trying to append arrays (driver: rmongodb) Created: 24/Jan/13  Updated: 19/Feb/13  Resolved: 19/Feb/13

Status: Closed
Project: Core Server
Component/s: Stability
Affects Version/s: 2.2.2
Fix Version/s: None

Type: Bug Priority: Critical - P2
Reporter: Janko Thyson Assignee: Stennie Steneker (Inactive)
Resolution: Done Votes: 0
Labels: Windows, crash, driver, rmongodb, update
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

OS: Windows 7 (64 Bit)
R 2.15.1
rmongodb 1.0.5


Attachments: Text File mongodblog_approach1_20130129235213.txt     Text File mongodblog_approach2_20130130003711.txt     Text File mongodblog_approach3_20130130004721.txt     Text File mongodblog_approach4_20130130005044.txt     Text File mongodblog_approach5_20130130011419.txt     Text File mongodblog_approach6_20130130011956.txt     File push.R    
Operating System: Windows
Steps To Reproduce:

See this Stackoverflow post for a reproducible example:
http://stackoverflow.com/questions/14489612/appending-bson-arrays-in-mongodb-rmongodb/14508417#14508417

Participants:

 Description   

// DESCRIPTION //

Suppose there is a simple document with an 'tags' array:

_id : 7 51005201f8ab44f1690f9526
tags : 4
1 : 2 a
2 : 2 b
3 : 2 c

The server crashes when I try to append this array either via the '$push' or the '$addToSet' operator.

// LOGFILE OUTPUT //

Thu Jan 24 16:42:44 [conn1]  __test.test Assertion failure x == _nfields src\mongo\db\jsobj.cpp 1250
Thu Jan 24 16:42:44 [conn1] mongod.exe    ...\src\mongo\util\stacktrace.cpp(161)                           mongo::printStackTrace+0x3e
Thu Jan 24 16:42:44 [conn1] mongod.exe    ...\src\mongo\util\assert_util.cpp(109)                          mongo::verifyFailed+0xdc
Thu Jan 24 16:42:44 [conn1] mongod.exe    ...\src\mongo\db\jsobj.cpp(1250)                                 mongo::BSONIteratorSorted::BSONIteratorSorted+0xf3
Thu Jan 24 16:42:44 [conn1] mongod.exe    ...\src\mongo\db\ops\update_internal.cpp(906)                    mongo::ModSetState::createNewFromMods+0xa3
Thu Jan 24 16:42:44 [conn1] mongod.exe    ...\src\mongo\db\ops\update.cpp(370)                             mongo::_updateObjects+0x15a2
Thu Jan 24 16:42:44 [conn1] mongod.exe    ...\src\mongo\db\instance.cpp(573)                               mongo::receivedUpdate+0x60d
Thu Jan 24 16:42:44 [conn1] mongod.exe    ...\src\mongo\db\instance.cpp(437)                               mongo::assembleResponse+0x626
Thu Jan 24 16:42:44 [conn1] mongod.exe    ...\src\mongo\db\db.cpp(192)                                     mongo::MyMessageHandler::process+0xf5
Thu Jan 24 16:42:44 [conn1] mongod.exe    ...\src\mongo\util\net\message_server_port.cpp(86)               mongo::pms::threadRun+0x59a
Thu Jan 24 16:42:44 [conn1] mongod.exe    ...\src\third_party\boost\libs\thread\src\win32\thread.cpp(180)  boost::`anonymous namespace'::thread_start_function+0x21
Thu Jan 24 16:42:44 [conn1] mongod.exe    f:\dd\vctools\crt_bld\self_64_amd64\crt\src\threadex.c(314)      _callthreadstartex+0x17
Thu Jan 24 16:42:44 [conn1] mongod.exe    f:\dd\vctools\crt_bld\self_64_amd64\crt\src\threadex.c(292)      _threadstartex+0x7f
Thu Jan 24 16:42:44 [conn1] kernel32.dll                                                                   BaseThreadInitThunk+0xd
Thu Jan 24 16:42:44 [conn1] update __test.test query: { tags: "a" } update: { $push: { tags: "d" } } nscanned:1 keyUpdates:0 exception: assertion src\mongo\db\jsobj.cpp:1250 locks(micros) w:398335 399ms
Thu Jan 24 16:42:48 CTRL_CLOSE_EVENT signal
Thu Jan 24 16:42:48 [consoleTerminate] got CTRL_CLOSE_EVENT, will terminate after current cmd ends
Thu Jan 24 16:42:48 [consoleTerminate] now exiting
Thu Jan 24 16:42:48 dbexit: 
Thu Jan 24 16:42:48 [consoleTerminate] shutdown: going to close listening sockets...
Thu Jan 24 16:42:48 [consoleTerminate] closing listening socket: 496
Thu Jan 24 16:42:48 [consoleTerminate] closing listening socket: 516
Thu Jan 24 16:42:48 [consoleTerminate] shutdown: going to flush diaglog...
Thu Jan 24 16:42:48 [consoleTerminate] shutdown: going to close sockets...
Thu Jan 24 16:42:48 [consoleTerminate] shutdown: waiting for fs preallocator...
Thu Jan 24 16:42:48 [consoleTerminate] shutdown: lock for final commit...
Thu Jan 24 16:42:48 [consoleTerminate] shutdown: final commit...
Thu Jan 24 16:42:48 [conn1] end connection 127.0.0.1:52419 (0 connections now open)
Thu Jan 24 16:42:48 [consoleTerminate] shutdown: closing all files...
Thu Jan 24 16:42:48 [consoleTerminate] closeAllFiles() finished
Thu Jan 24 16:42:48 [consoleTerminate] journalCleanup...
Thu Jan 24 16:42:48 [consoleTerminate] removeJournalFiles
Thu Jan 24 16:42:48 [consoleTerminate] shutdown: removing fs lock...
Thu Jan 24 16:42:48 dbexit: really exiting now 



 Comments   
Comment by Janko Thyson [ 18/Feb/13 ]

Hi everyone,
with the help of Gerald Lindsly, I was able to make some major progress in figuring out where the bad BSON structure comes from. It's definitely caused by the driver for either C and/or R (rmongodb), not the server. AFIU, it was caused due to multiple calls of a "finish BSON buffer object" which corrupted the actual BSON structure but made everything still look OK in my application. IIRC, Gerald will try to implement options to validate BSON structures client-side before passing everything to the server and running the risk that it rejects it.

Not sure what the "ticket procedure" is at this point. It's probably OK to call it a "case closed"? Thanks a lot for everyone that was involved in helping me make progress on this!

Comment by Janko Thyson [ 30/Jan/13 ]

Added a couple files that might shed some light onto this:

File 'push.R' contains test code (language R) that tests 6 different approaches in order to resolve the issue experienced.

For each of the approaches you'll also find the associated MongoDB server logfile.

Approaches tested:

  • driver version (re-installed rmongo 1.0.5)
    server versions (2.2.2 32 bit and 2.2.2 64 bit)
  • R versions (2.15.1 (portable = launched from a USB drive) and 2.15.2 (portable and local = installed to 'C:/R/R-2.15.2')
  • OS versions (Windows 7 64 bit and Windows 8 64 bit)
Comment by Janko Thyson [ 29/Jan/13 ]

Hi Tad,

I tested your suggestions and updated my SO post accordingly. Indeed, my doc doesn't pass the validity check: http://stackoverflow.com/questions/14489612/appending-bson-arrays-in-mongodb-rmongodb.

And: you were right with respect to my code not crashing the server: it's still running after trying to insert/perform the desired CRUD-operation.

// LOGFILE //

Thu Jan 24 16:42:27 [initandlisten] MongoDB starting : pid=6260 port=27017 dbpath=\data\db\ 64-bit host=ASHB-109C-02
Thu Jan 24 16:42:27 [initandlisten] db version v2.2.2, pdfile version 4.5
Thu Jan 24 16:42:27 [initandlisten] git version: d1b43b61a5308c4ad0679d34b262c5af9d664267
Thu Jan 24 16:42:27 [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 Jan 24 16:42:27 [initandlisten] options: { logpath: "log_1.txt" }
Thu Jan 24 16:42:27 [initandlisten] journal dir=/data/db/journal
Thu Jan 24 16:42:27 [initandlisten] recover : no journal files present, no recovery needed
Thu Jan 24 16:42:27 [initandlisten] waiting for connections on port 27017
Thu Jan 24 16:42:27 [websvr] admin web console waiting for connections on port 28017
Thu Jan 24 16:42:36 [initandlisten] connection accepted from 127.0.0.1:52419 #1 (1 connection now open)
Thu Jan 24 16:42:44 [conn1]  __test.test Assertion failure x == _nfields src\mongo\db\jsobj.cpp 1250
Thu Jan 24 16:42:44 [conn1] mongod.exe    ...\src\mongo\util\stacktrace.cpp(161)                           mongo::printStackTrace+0x3e
Thu Jan 24 16:42:44 [conn1] mongod.exe    ...\src\mongo\util\assert_util.cpp(109)                          mongo::verifyFailed+0xdc
Thu Jan 24 16:42:44 [conn1] mongod.exe    ...\src\mongo\db\jsobj.cpp(1250)                                 mongo::BSONIteratorSorted::BSONIteratorSorted+0xf3
Thu Jan 24 16:42:44 [conn1] mongod.exe    ...\src\mongo\db\ops\update_internal.cpp(906)                    mongo::ModSetState::createNewFromMods+0xa3
Thu Jan 24 16:42:44 [conn1] mongod.exe    ...\src\mongo\db\ops\update.cpp(370)                             mongo::_updateObjects+0x15a2
Thu Jan 24 16:42:44 [conn1] mongod.exe    ...\src\mongo\db\instance.cpp(573)                               mongo::receivedUpdate+0x60d
Thu Jan 24 16:42:44 [conn1] mongod.exe    ...\src\mongo\db\instance.cpp(437)                               mongo::assembleResponse+0x626
Thu Jan 24 16:42:44 [conn1] mongod.exe    ...\src\mongo\db\db.cpp(192)                                     mongo::MyMessageHandler::process+0xf5
Thu Jan 24 16:42:44 [conn1] mongod.exe    ...\src\mongo\util\net\message_server_port.cpp(86)               mongo::pms::threadRun+0x59a
Thu Jan 24 16:42:44 [conn1] mongod.exe    ...\src\third_party\boost\libs\thread\src\win32\thread.cpp(180)  boost::`anonymous namespace'::thread_start_function+0x21
Thu Jan 24 16:42:44 [conn1] mongod.exe    f:\dd\vctools\crt_bld\self_64_amd64\crt\src\threadex.c(314)      _callthreadstartex+0x17
Thu Jan 24 16:42:44 [conn1] mongod.exe    f:\dd\vctools\crt_bld\self_64_amd64\crt\src\threadex.c(292)      _threadstartex+0x7f
Thu Jan 24 16:42:44 [conn1] kernel32.dll                                                                   BaseThreadInitThunk+0xd
Thu Jan 24 16:42:44 [conn1] update __test.test query: { tags: "a" } update: { $push: { tags: "d" } } nscanned:1 keyUpdates:0 exception: assertion src\mongo\db\jsobj.cpp:1250 locks(micros) w:398335 399ms
Thu Jan 24 16:42:48 CTRL_CLOSE_EVENT signal
Thu Jan 24 16:42:48 [consoleTerminate] got CTRL_CLOSE_EVENT, will terminate after current cmd ends
Thu Jan 24 16:42:48 [consoleTerminate] now exiting
Thu Jan 24 16:42:48 dbexit: 
Thu Jan 24 16:42:48 [consoleTerminate] shutdown: going to close listening sockets...
Thu Jan 24 16:42:48 [consoleTerminate] closing listening socket: 496
Thu Jan 24 16:42:48 [consoleTerminate] closing listening socket: 516
Thu Jan 24 16:42:48 [consoleTerminate] shutdown: going to flush diaglog...
Thu Jan 24 16:42:48 [consoleTerminate] shutdown: going to close sockets...
Thu Jan 24 16:42:48 [consoleTerminate] shutdown: waiting for fs preallocator...
Thu Jan 24 16:42:48 [consoleTerminate] shutdown: lock for final commit...
Thu Jan 24 16:42:48 [consoleTerminate] shutdown: final commit...
Thu Jan 24 16:42:48 [conn1] end connection 127.0.0.1:52419 (0 connections now open)
Thu Jan 24 16:42:48 [consoleTerminate] shutdown: closing all files...
Thu Jan 24 16:42:48 [consoleTerminate] closeAllFiles() finished
Thu Jan 24 16:42:48 [consoleTerminate] journalCleanup...
Thu Jan 24 16:42:48 [consoleTerminate] removeJournalFiles
Thu Jan 24 16:42:48 [consoleTerminate] shutdown: removing fs lock...
Thu Jan 24 16:42:48 dbexit: really exiting now

Comment by Janko Thyson [ 29/Jan/13 ]

Hi Tad,

thanks for looking into this! I'll double check if the server actually crashed and test for corrupted BSON docs.

Best regards,
J

Comment by Tad Marshall [ 29/Jan/13 ]

Hi Janko,

Thanks for the report.

The assertion failure does look like a real problem because it is testing a condition that is supposed to be true, and that's why it prints the stack trace. But this does not look like a crash; the CTRL_CLOSE_EVENT message is printed when the console window is closed while mongod.exe is still running, so it looks like the window was closed deliberately.

If this is not the case, please correct me.

The assertion failure is definitely a bug somewhere, but it may be in the R driver.

Can you run your test with --objcheck on the mongod.exe command line to see if the R driver is sending corrupted BSON?

Thanks!

Tad

Comment by Janko Thyson [ 28/Jan/13 ]

I'm not really familiar with how to place bug reports here yet. I think I can't update my bug report. Yet I think this bug actually is a blocker. So it'd be great if someone of you could go ahead and change its priority to "Blocker - P1". Thanks!

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