Assertion: 10320:BSONElement: bad type 101

[Allan Beaufour]

We've just starting seeing these on one of our slaves:

[[

Wed Mar 23 16:00:44 [replslave] Assertion: 10320:BSONElement: bad type 101

0x540c7e 0x4e7685 0x4e7a3e 0x617ea8 0x61f3a5 0x622b6c 0x6bfbf6 0x6482bb 0x658d99 0x65ccdb 0x65e3dc 0x65e6a8 0x65ee11 0x65f59a 0x83a4b0 0x7f08daa6b9ca 0x7f08da01a70d 

 /usr/bin/mongod(_ZN5mongo11msgassertedEiPKc+0x1de) [0x540c7e]

 /usr/bin/mongod(_ZNK5mongo11BSONElement4sizeEi+0x295) [0x4e7685]

 /usr/bin/mongod(_ZN5mongo15BSONObjIterator4nextEb+0x6e) [0x4e7a3e]

 /usr/bin/mongod(_ZN5mongo11checkNoModsENS_7BSONObjE+0x38) [0x617ea8]

 /usr/bin/mongod(_ZN5mongo14_updateObjectsEbPKcRKNS_7BSONObjES2_bbbRNS_7OpDebugEPNS_11RemoveSaverE+0xad5) [0x61f3a5]

 /usr/bin/mongod(_ZN5mongo13updateObjectsEPKcRKNS_7BSONObjES2_bbbRNS_7OpDebugE+0x11c) [0x622b6c]

 /usr/bin/mongod(_ZN5mongo21applyOperation_inlockERKNS_7BSONObjE+0x856) [0x6bfbf6]

 /usr/bin/mongod(_ZN5mongo10ReplSource14applyOperationERKNS_7BSONObjE+0x1b) [0x6482bb]

 /usr/bin/mongod(_ZN5mongo10ReplSource29sync_pullOpLog_applyOperationERNS_7BSONObjEPNS_6OpTimeE+0x379) [0x658d99]

 /usr/bin/mongod(_ZN5mongo10ReplSource14sync_pullOpLogERi+0x2ceb) [0x65ccdb]

 /usr/bin/mongod(_ZN5mongo10ReplSource4syncERi+0x4cc) [0x65e3dc]

 /usr/bin/mongod(_ZN5mongo9_replMainERSt6vectorIN5boost10shared_ptrINS_10ReplSourceEEESaIS4_EERi+0x218) [0x65e6a8]

 /usr/bin/mongod(_ZN5mongo8replMainEv+0xd1) [0x65ee11]

 /usr/bin/mongod(_ZN5mongo15replSlaveThreadEv+0x21a) [0x65f59a]

 /usr/bin/mongod(thread_proxy+0x80) [0x83a4b0]

 /lib/libpthread.so.0(+0x69ca) [0x7f08daa6b9ca]

 /lib/libc.so.6(clone+0x6d) [0x7f08da01a70d]

]]

We run one master and one slave in this setup. Same versions on both master and slave:

[[

Tue Dec 14 15:42:11 MongoDB starting : pid=20648 port=27017 dbpath=/mongoreplica/slavedb slave=1 64-bit 

Tue Dec 14 15:42:11 db version v1.6.5, pdfile version 4.5

Tue Dec 14 15:42:11 git version: 0eb017e9b2828155a67c5612183337b89e12e291

Tue Dec 14 15:42:11 sys info: Linux d #1 SMP Fri Nov 20 17:48:28 EST 200

9 x86_64 BOOST_LIB_VERSION=1_41

]]

Any clues?

... Allan

[Kyle Banker]

This usually indicates some kind of corruption on the master node. Any
chance you've had any unclean shutdowns of the master node?

> --
> You received this message because you are subscribed to the Google Groups
> "mongodb-user" group.
> To post to this group, send email to mongod...@googlegroups.com.
> To unsubscribe from this group, send email to
> mongodb-user...@googlegroups.com.
> For more options, visit this group at
> http://groups.google.com/group/mongodb-user?hl=en.
>

[Allan Beaufour]

No, the master has been running happily for a long time.

The thing that changed today was the addition of a new binary field to some document, and an index on same.

[Kyle Banker]

Any chance that the length of this field is greater than 800 bytes?
There was bug related to this.

[Allan Beaufour]

No, it's a small field.

I just realize that we have two different assertions. This is the other one:

[[

Wed Mar 23 18:02:56 [replslave] processing op: Assertion: 10320:BSONElement: bad type -85

0x540c7e 0x4e7685 0x4e8d4c 0x4e9429 0x4e8e28 0x4e9429 0x4e8e28 0x56b4e3 0x4e402a 0x658a8f 0x65ccdb 0x65e3dc 0x65e6a8 0x65ee11 0x65f59a 0x83a4b0 0x7f25ec6d89ca 0x7f25ebc8770d 

 /usr/bin/mongod(_ZN5mongo11msgassertedEiPKc+0x1de) [0x540c7e]

 /usr/bin/mongod(_ZNK5mongo11BSONElement4sizeEi+0x295) [0x4e7685]

 /usr/bin/mongod(_ZNK5mongo7BSONObj8toStringERNS_13StringBuilderEbb+0xfc) [0x4e8d4c]

 /usr/bin/mongod(_ZNK5mongo11BSONElement8toStringERNS_13StringBuilderEbb+0x429) [0x4e9429]

 /usr/bin/mongod(_ZNK5mongo7BSONObj8toStringERNS_13StringBuilderEbb+0x1d8) [0x4e8e28]

 /usr/bin/mongod(_ZNK5mongo11BSONElement8toStringERNS_13StringBuilderEbb+0x429) [0x4e9429]

 /usr/bin/mongod(_ZNK5mongo7BSONObj8toStringERNS_13StringBuilderEbb+0x1d8) [0x4e8e28]

 /usr/bin/mongod(_ZNK5mongo14LazyStringImplINS_7BSONObjEE3valEv+0x63) [0x56b4e3]

 /usr/bin/mongod(_ZN5mongo9LogstreamlsERKNS_10LazyStringE+0x1a) [0x4e402a]

 /usr/bin/mongod(_ZN5mongo10ReplSource29sync_pullOpLog_applyOperationERNS_7BSONObjEPNS_6OpTimeE+0x6f) [0x658a8f]

 /usr/bin/mongod(_ZN5mongo10ReplSource14sync_pullOpLogERi+0x2ceb) [0x65ccdb]

 /usr/bin/mongod(_ZN5mongo10ReplSource4syncERi+0x4cc) [0x65e3dc]

 /usr/bin/mongod(_ZN5mongo9_replMainERSt6vectorIN5boost10shared_ptrINS_10ReplSourceEEESaIS4_EERi+0x218) [0x65e6a8]

 /usr/bin/mongod(_ZN5mongo8replMainEv+0xd1) [0x65ee11]

 /usr/bin/mongod(_ZN5mongo15replSlaveThreadEv+0x21a) [0x65f59a]

 /usr/bin/mongod(thread_proxy+0x80) [0x83a4b0]

 /lib/libpthread.so.0(+0x69ca) [0x7f25ec6d89ca]

 /lib/libc.so.6(clone+0x6d) [0x7f25ebc8770d]

]]

[Allan Beaufour]

Just tried to read the entry that the slave seems to be choking on directly from the master's oplog:

[[

db.oplog.$main.find({ts: {$gte: new Timestamp(1300910403000,79)}}).addOption(8).limit(1).skip(1)

Wed Mar 23 18:11:47 Assertion: 10320:BSONElement: bad type 101

0x4d9c29 0x484e96 0x524b12 0x5ee775 0x5ee352 0x5efab2 0x5cfa6a 0x5bfd06 0x57ceff 0x57ce48 0x57cd31 0x52ff6d 0x47cae9 0x47dcc6 0x7f5077c43c4d 0x476d79 

 ./mongo(_ZN5mongo11msgassertedEiPKc+0x129) [0x4d9c29]

 ./mongo(_ZNK5mongo11BSONElement4sizeEi+0x296) [0x484e96]

 ./mongo(_ZN5mongo16resolveBSONFieldEP9JSContextP8JSObjectljPS3_+0x302) [0x524b12]

 ./mongo(js_LookupPropertyWithFlags+0x421) [0x5ee775]

 ./mongo(js_LookupProperty+0x49) [0x5ee352]

 ./mongo(js_GetProperty+0xff) [0x5efab2]

 ./mongo(js_Interpret+0xed54) [0x5cfa6a]

 ./mongo(js_Execute+0x418) [0x5bfd06]

 ./mongo(JS_EvaluateUCScriptForPrincipals+0xb5) [0x57ceff]

 ./mongo(JS_EvaluateUCScript+0x5a) [0x57ce48]

 ./mongo(JS_EvaluateScript+0x80) [0x57cd31]

 ./mongo(_ZN5mongo7SMScope4execERKNS_10StringDataERKSsbbbi+0x10d) [0x52ff6d]

 ./mongo(_Z5_mainiPPc+0x21b9) [0x47cae9]

 ./mongo(main+0x26) [0x47dcc6]

 /lib/libc.so.6(__libc_start_main+0xfd) [0x7f5077c43c4d]

 ./mongo(_ZNSt15basic_streambufIcSt11char_traitsIcEE6xsputnEPKcl+0x49) [0x476d79]

error:BSONElement: bad type 101

]]

So I assume our oplog is corrupted?

This happened to us, on a totally different system, on an older version of Mongo a couple of weeks ago.... The way we got around that was to remove the oplog entirely from the master and start the slave from scratch. Do we really need to do this again?

... Allan

[Kyle Banker]

On which other version of MongoDB did you see this issue? It's
possible that you're hitting a bug that existed in 1.6.5. The best way
to fix this error is to first upgrade to 1.8, then to run a repair on
the master, and then to resync from the slave.

Before you do that, which driver are you using?

[Allan Beaufour]

We used to run 1.4.5 on the other boxes we saw the issue on. We run 1.9 python drivers on these. Repair is not really feasible for us, as we have fairly large data sizes and we run on EBS.

I've unfortunately had to resort to skipping past the entries in the oplog for the slave, to get it replicating again -- with some missing data.

I've would love to figure out why this is happening though, as it is the second time it has happened to us now, within the course of a month.

[Allan Beaufour]

Kyle, any tips to how we can debug what went wrong here? Any particular bugs you think could cause this?

[Kyle Banker]

I know for a fact that there was a bug that could cause this on 1.6.5,
and possibly in earlier versions as well. I think you should upgrade
to 1.8.1. Once you upgrade, you should repair the existing databases.

[Allan Beaufour]

Do you happen to have a reference to the bug?

Upgrading, yes, that would be good, but I'm not super keen on upgrading my production environment to things 8 days after they are released tbh :)

Allan

[Kyle Banker]

Unfortunately, I'm pretty sure that no JIRA case was created when this
bug was fixed.