[SERVER-8227] Assertion in mongo log: 10334:Invalid BSONObj size: 1769280243 (0xF3127569) first element: : ?type=100 Created: 18/Jan/13  Updated: 10/Dec/14  Resolved: 04/Apr/14

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

Type: Bug Priority: Major - P3
Reporter: Dmitry Chernikov Assignee: Unassigned
Resolution: Done Votes: 1
Labels: bson, crash
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

CentOS, x86_64,


Issue Links:
Duplicate
is duplicated by SERVER-8236 Assertion in mongo log: 10334:Invalid... Closed
Operating System: Linux
Participants:

 Description   

We have 6 servers in replica set, accessed using C++ and python drivers.
One of servers sometimes throw in logs assertions like this:

mongo.log

Thu Jan 17 11:00:43 [conn103] Assertion: 10334:Invalid BSONObj size: 1769280243 (0xF3127569) first element: : ?type=100
0xaffd31 0xac5eb9 0xac603c 0x572567 0x66f857 0x84c46b 0x84fcdd 0x85145f 0x851543 0x83dcf3 0x841fc1 0x844a27 0x7ade1f 0x7b4284 0x5703f2 0xaedfc1 0x355a607851 0x355a2e811d
/usr/bin/mongod(_ZN5mongo15printStackTraceERSo+0x21) [0xaffd31]
/usr/bin/mongod(_ZN5mongo11msgassertedEiPKc+0x99) [0xac5eb9]
/usr/bin/mongod() [0xac603c]
/usr/bin/mongod(_ZNK5mongo7BSONObj14_assertInvalidEv+0x497) [0x572567]
/usr/bin/mongod(_ZNK5mongo11BSONElement14embeddedObjectEv+0xa7) [0x66f857]

/usr/bin/mongod(_ZNK5mongo3Mod5applyERNS_15BSONBuilderBaseENS_11BSONElementERNS_8ModStateE+0x191b) [0x84c46b]

/usr/bin/mongod(_ZN5mongo11ModSetState17createNewFromModsERKSsRNS_15BSONBuilderBaseERNS_18BSONIteratorSortedERKSt4pairIKSt17_Rb_tree_iteratorIS7_IS1_N5boost10shared_ptrINS_8ModStateEEEEESF_ERKNS_9LexNumCmpE+0x4dd)
[0x84fcdd]

/usr/bin/mongod(_ZN5mongo11ModSetState20createNewObjFromModsERKSsRNS_14BSONObjBuilderERKNS_7BSONObjE+0x7f) [0x85145f]
/usr/bin/mongod(_ZN5mongo11ModSetState17createNewFromModsEv+0x63) [0x851543]
/usr/bin/mongod() [0x83dcf3]

/usr/bin/mongod(_ZN5mongo14_updateObjectsEbPKcRKNS_7BSONObjES4_bbbRNS_7OpDebugEPNS_11RemoveSaverEbRKNS_24QueryPlanSelectionPolicyEb+0x3081) [0x841fc1]

/usr/bin/mongod(_ZN5mongo13updateObjectsEPKcRKNS_7BSONObjES4_bbbRNS_7OpDebugEbRKNS_24QueryPlanSelectionPolicyE+0xb7) [0x844a27]

/usr/bin/mongod(_ZN5mongo14receivedUpdateERNS_7MessageERNS_5CurOpE+0x4cf) [0x7ade1f]

/usr/bin/mongod(_ZN5mongo16assembleResponseERNS_7MessageERNS_10DbResponseERKNS_11HostAndPortE+0xbd4) [0x7b4284]

/usr/bin/mongod(_ZN5mongo16MyMessageHandler7processERNS_7MessageEPNS_21AbstractMessagingPortEPNS_9LastErrorE+0x82) [0x5703f2]
/usr/bin/mongod(_ZN5mongo3pms9threadRunEPNS_13MessagingPortE+0x411) [0xaedfc1]
/lib64/libpthread.so.0() [0x355a607851]
/lib64/libc.so.6(clone+0x6d) [0x355a2e811d]
Thu Jan 17 11:00:43 [conn103] Assertion: 10329:Element too large
0xaffd31 0xac5eb9 0x5745c7 0x572fdb 0x65b17f 0x7b3aeb 0x5703f2 0xaedfc1 0x355a607851 0x355a2e811d
/usr/bin/mongod(_ZN5mongo15printStackTraceERSo+0x21) [0xaffd31]
/usr/bin/mongod(_ZN5mongo11msgassertedEiPKc+0x99) [0xac5eb9]

/usr/bin/mongod(_ZNK5mongo7BSONObj8toStringERNS_17StringBuilderImplINS_16TrivialAllocatorEEEbbi+0x317) [0x5745c7]

/usr/bin/mongod(_ZNK5mongo11BSONElement8toStringERNS_17StringBuilderImplINS_16TrivialAllocatorEEEbbi+0x69b) [0x572fdb]
/usr/bin/mongod(_ZNK5mongo7OpDebug6reportERKNS_5CurOpE+0xaef) [0x65b17f]

/usr/bin/mongod(_ZN5mongo16assembleResponseERNS_7MessageERNS_10DbResponseERKNS_11HostAndPortE+0x43b) [0x7b3aeb]

/usr/bin/mongod(_ZN5mongo16MyMessageHandler7processERNS_7MessageEPNS_21AbstractMessagingPortEPNS_9LastErrorE+0x82) [0x5703f2]
/usr/bin/mongod(_ZN5mongo3pms9threadRunEPNS_13MessagingPortE+0x411) [0xaedfc1]
/lib64/libpthread.so.0() [0x355a607851]
/lib64/libc.so.6(clone+0x6d) [0x355a2e811d]

We tracked down to piece of code which causes this, but it consists of 3 queries within single connections:

schematic code

conn->insert( "collTickets", ticketObj );
conn->getLastError(); // ensure insertion was done
conn->update( "userInfo", BSON( "_id" << userId ), BSON( "$inc" << BSON( "ticketCount" << 1 ) ), false/update mode/ );
conn->update( "ticketAcks", BSON( "_id" << mongo::OID( ackIdStr ) ), BSON( "$set" << BSON( "lastTicket" << ticketOdj[ "_id" ].OID().str() << "accountant" << managerId ) ) );
conn.done();

objects sizes are guaranteed to be much less than 16MB:

Mongo console

truck:PRIMARY> Object.bsonsize( db.userInfo.findOne( { _id:1842412 } ) )
43705
truck:PRIMARY> db.collTickets.find( {userId:1842412} ).forEach( function ( e ) { print(Object.bsonsize(e));} )
255
356
truck:PRIMARY> db.ticketAcks.find( {toUserId:1842412} ).forEach( function ( e ) { print(Object.bsonsize(e));} )
269
6732
6178
6414
6334
6100
truck:PRIMARY> db.version()
2.2.2
 

What can cause this assertion failures?
How we can avoid them?



 Comments   
Comment by kuku [ 28/May/13 ]

ue May 28 18:09:31 [conn396] Assertion: 10334:Invalid BSONObj size: -286331391 (0x01EEEEEE) first element: : ?type=112
0xaffd31 0xac5eb9 0xac603c 0x572567 0x796c1d 0x86fc24 0x6587c4 0x80fd77 0x810068 0x85cc3e 0x7b955f 0x7b9ea0 0x7b40f8 0x5703f2 0xaedfc1 0x3402c0673d 0x34020d44bd
/mongodb-linux-x86_64-2.2.2/bin/mongod(_ZN5mongo15printStackTraceERSo+0x21) [0xaffd31]
/mongodb-linux-x86_64-2.2.2/bin/mongod(_ZN5mongo11msgassertedEiPKc+0x99) [0xac5eb9]
/mongodb-linux-x86_64-2.2.2/bin/mongod [0xac603c]
/mongodb-linux-x86_64-2.2.2/bin/mongod(_ZNK5mongo7BSONObj14_assertInvalidEv+0x497) [0x572567]
/mongodb-linux-x86_64-2.2.2/bin/mongod(_ZN5mongo13unindexRecordEPNS_16NamespaceDetailsEPNS_6RecordERKNS_7DiskLocEb+0x11d) [0x796c1d]
/mongodb-linux-x86_64-2.2.2/bin/mongod(_ZN5mongo11DataFileMgr12deleteRecordEPKcPNS_6RecordERKNS_7DiskLocEbbb+0x204) [0x86fc24]
/mongodb-linux-x86_64-2.2.2/bin/mongod(_ZN5mongo16NamespaceDetails11cappedAllocEPKci+0x4b4) [0x6587c4]
/mongodb-linux-x86_64-2.2.2/bin/mongod(_ZN5mongo16NamespaceDetails6_allocEPKci+0x27) [0x80fd77]
/mongodb-linux-x86_64-2.2.2/bin/mongod(_ZN5mongo16NamespaceDetails5allocEPKciRNS_7DiskLocE+0x38) [0x810068]
/mongodb-linux-x86_64-2.2.2/bin/mongod(_ZN5mongo11DataFileMgr17fast_oplog_insertEPNS_16NamespaceDetailsEPKci+0x6e) [0x85cc3e]
/mongodb-linux-x86_64-2.2.2/bin/mongod [0x7b955f]
/mongodb-linux-x86_64-2.2.2/bin/mongod(_ZN5mongo7profileERKNS_6ClientEiRNS_5CurOpE+0x290) [0x7b9ea0]
/mongodb-linux-x86_64-2.2.2/bin/mongod(_ZN5mongo16assembleResponseERNS_7MessageERNS_10DbResponseERKNS_11HostAndPortE+0xa48) [0x7b40f8]
/mongodb-linux-x86_64-2.2.2/bin/mongod(_ZN5mongo16MyMessageHandler7processERNS_7MessageEPNS_21AbstractMessagingPortEPNS_9LastErrorE+0x82) [0x5703f2]
/mongodb-linux-x86_64-2.2.2/bin/mongod(_ZN5mongo3pms9threadRunEPNS_13MessagingPortE+0x411) [0xaedfc1]
/lib64/libpthread.so.0 [0x3402c0673d]
/lib64/libc.so.6(clone+0x6d) [0x34020d44bd]
Tue May 28 18:09:31 [conn396] warning: Caught Assertion while trying to profile getmore against local.oplog.rs: 10334 Invalid BSONObj size: -286331391 (0x01EEEEEE) first element: : ?type=112
Tue May 28 18:09:31 [initandlisten] connection accepted from 192.168.100.238:38062 #556307 (640 connections now open)
Tue May 28 18:09:32 [initandlisten] connection accepted from 192.168.100.238:38068 #556308 (641 connections now open)
Tue May 28 18:09:32 [initandlisten] connection accepted from 192.168.100.238:38069 #556309 (642 connections now open)
Tue May 28 18:09:32 [initandlisten] connection accepted from 192.168.100.238:38072 #556310 (643 connections now open)

Ask for help, every day, Thinks!

Comment by James Wahlin [ 07/Mar/13 ]

Hi Alexander,

From the log trace above it looks like the BSON object itself is invalid. The "first element:" trace shows "?type=100" where 100 is not a valid BSON type. MongoDB code prepends a ? when an unknown type is encountered in this path. You can find the code here:
https://github.com/mongodb/mongo/blob/v2.2/src/mongo/bson/bson-inl.h#L779

My first question to you is what version of the C++ driver are you running? If older than 2.2.2 I would suggest upgrading. If you are running the 2.2.2 client then we will need to dive deeper. The path above appears to be triggered by an update so at this point it is not clear whether the driver is generating invalid BSON or whether the update path is generating.

Thanks,
James

Comment by Alexander Borodetsky [ 18/Jan/13 ]

Also we have MMS account associated with my JIRA account. This issue occured on repset "wop"

Comment by Alexander Borodetsky [ 18/Jan/13 ]

Also i want to underline - this is not SERVER-7206. Because we didn't use profiler and we have NO system.profiler collection

Comment by Alexander Borodetsky [ 18/Jan/13 ]

Please change "Affects Version/s" to 2.2.2 as well. Because actually it is happens on 2.2.2 NOT on 2.2.0

Comment by Dmitry Chernikov [ 18/Jan/13 ]

forgot to mention that we use a version of mongod 2.2.2,
profiling is not used (and weren't used before),
objects in db contain some utf8-encoded strings of 2-4 kb in size...
all objects in db that should be accessed by this query set accesible and can be read w/o problems - i.e. db stayed consistent...

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