[SERVER-13651] "btree: key+recloc already in index" error when updating text index Created: 18/Apr/14  Updated: 10/Dec/14  Resolved: 18/Aug/14

Status: Closed
Project: Core Server
Component/s: Index Maintenance, Text Search
Affects Version/s: None
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: Mike Robertson Assignee: Unassigned
Resolution: Duplicate Votes: 1
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Duplicate
duplicates SERVER-14738 Updates to documents with text-indexe... Closed
Related
Participants:

 Description   

After running without any problems, we started receiving "exception: btree: key+recloc already in index code:10287" error. The db log is attached. We are using 2.6.0. Some forums indicate that it might be just a debug statement and is harmless. Need confirmation.



 Comments   
Comment by J Rassi [ 18/Aug/14 ]

mikerobe, andreas@idztech.com, cstigler: based on your problem descriptions, we've determined that SERVER-14738 ("Updates to documents with text-indexed fields...") introduced corruption into the text index on your collections, which is the root cause of the failed updates you're seeing. Per the instructions on that ticket, you should correct the issue by upgrading to 2.6.4 (or 2.4.11, which is scheduled to be released shortly) and then dropping / recreating all text indexes on your cluster. Here is a minimal repro of the issue that you are encountering on with server version 2.6.3, which is affected by this issue:

> db.version()
2.6.3
> db.collection.drop()
true
> db.collection.ensureIndex({a: "text", b: "text"})
{
	"createdCollectionAutomatically" : true,
	"numIndexesBefore" : 1,
	"numIndexesAfter" : 2,
	"ok" : 1
}
> db.collection.insert({a: "foo", b: "bar"}) // Two index entries generated: (term="foo", score=1.1) and (term="bar", score=1.1)
WriteResult({ "nInserted" : 1 })
> db.collection.update({}, {$set: {b: "foo"}}) // Due to SERVER-14738, no index changes applied ("bar" index entry should be removed and "foo" should have score reset to 2.2).
WriteResult({ "nMatched" : 1, "nUpserted" : 0, "nModified" : 1 })
> db.collection.update({}, {$unset: {b: 1}}) // Attempts to reset "foo" score in index to 1.1, but fails because score for "foo" is already 1.1.
WriteResult({
	"nMatched" : 0,
	"nUpserted" : 0,
	"nModified" : 0,
	"writeError" : {
		"code" : 10287,
		"errmsg" : "btree: key+recloc already in index"
	}
})
>

I am thus resolving this ticket as a dup of SERVER-14738. Please complete the upgrade followed by the index rebuild(s), and please re-open this ticket if you continue to encounter this issue after doing so.

davidluvit: we believe that the issue that you are reporting is unrelated to SERVER-14738. I've created a new ticket at SERVER-14947 to track its progress separately. Please watch that ticket for further updates.

Comment by Charlie Stigler [ 14/Aug/14 ]

We started receiving this on our 2.6.1 Mongo server (hosted on MongoHQ/Compose) several months after upgrading to 2.6.1. It wasn't present on my local DB, even when copied to match the production database exactly. It only seemed to affect one property on one document, which we were running a simple $set on and was part of a compound text index. The property was "description" and our index looked like this:

db.tourItems.ensureIndex({
name: 'text',
ownerName: 'text',
description: 'text',
tags: 'text'
}, {
weights:

{ name: 5, ownerName: 4, tags: 3, description: 1 }

,
background: true
});

Running db.tourItems.reIndex() has fixed the problem, for now.

Comment by Daniel Pasette (Inactive) [ 25/Jul/14 ]

A quick update on this issue. We are still investigating the data files provided by davidluvit. If any other users with similar problems are able to provide us with either solid reproduction scenarios or data files, that would be a big help.

Comment by Andreas Bernhardsson [ 25/Jun/14 ]

I've also experienced this issue when running 2.6.1.
It happens occasionally when updates are made to a field that have a full text index.

Comment by David Wartell [ 06/Jun/14 ]

Just to clarify I started getting the btree: key+recloc error weeks after upgrading to 2.6 and weeks after rebuilding my indexes.

Regards,
-David

Comment by David Storch [ 04/Jun/14 ]

Hi davidluvit,

When I upgraded from 2.4 to 2.6 I had errors related to indexes and I had to drop all of my indexes and re-create them in 2.6 to make them go away.

Since you rebuilt the indices, I'm not sure how much information I'll be able to glean from the data files. If there was any corruption in the index, it was likely fixed by the rebuild. I can provide instructions via email for sending us the data files, just in case there might be something helpful there.

I did not keep good notes of those errors during upgrade but they may still be in my log files.

If you do have any relevant log files or sections of log, please do pass them along.

I have not to my knowledge had any unclean shutdowns or crashes that would represent a problem in the environment.

This is good to know. The problem does seem more like a logic error in the code than pure corruption due to something like an unclean shutdown.

Thank you very much for your attention and thank you for MongoDB.

No worries, let me know how I can be helpful in continuing to diagnose the problem.

Best,
Dave

Comment by David Wartell [ 03/Jun/14 ]

Thank you Dave.

The db files are about 3.5 GB uncompressed. I can not make them available publicly... If you can give me a secure location to my email I will gladly upload them to a secure server you operate.

The only things not typical about the collection I am having problems on is:

  • I frequently insert records that will cause a duplicate key on a unique index and I expect this as a normal condition.

I have not to my knowledge had any unclean shutdowns or crashes that would represent a problem in the environment.

When I upgraded from 2.4 to 2.6 I had errors related to indexes and I had to drop all of my indexes and re-create them in 2.6 to make them go away. I did not keep good notes of those errors during upgrade but they may still be in my log files.

Thank you very much for your attention and thank you for MongoDB.

Regards,
-David

Comment by David Storch [ 02/Jun/14 ]

Hi davidluvit,

Is there any chance that you would be able to provide copies of your data files for the database on which the failed inserts occurred? If the values are too large to attach here, I can provide instructions for scp'ing them to one of our file servers. Also, if you discover any more details about how to reproduce this problem, please do share them.

The error in the logs appears to be a symptom of corruption that happened due to some earlier event. While inserting a new index key, the btree implementation checks whether the new key will be the last in its bucket. While handling the special case of inserting a new last key, it does some invariant checking (see the code here). Specifically, the right child of what used to be the final index key in the bucket should be the left child of the newly inserted index key. The contents of the btree bucket, however, do not satisfy this condition (perhaps one of the child pointers got accidentally modified somewhere?) causing the insert to fail.

I'm also looping in one of our support engineers, bruce.lucas@10gen.com, as he has lots of experience diagnosing data corruption problems.

Best,
Dave

Comment by David Storch [ 02/Jun/14 ]

Hi davidluvit,

Thanks very much for the additional info. The log shows that an insert raised an error due to a failing internal invariant in the btree implementation. This likely indicates that the index has been corrupted. I'll update you with my findings as I investigate further.

Best,
Dave

Comment by David Wartell [ 30/May/14 ]

I am also having this issue all of a sudden. I could reproduce it consistently for several minutes... and after I gathered the requested information by the other reporter in this bug.

It seems this is related to a duplicate key on a unique index being inserted. However later after gathering all the information below and trying to test myh assumption I can no longer reproduce the issue.

2014-05-30 14:29:47.334 [BatchExecutor: ActivityPostViewedBatchOperation-thread-2] [ERROR] net.luvit.core.activity.ActivityPostViewedBatchOperationRunnable - Error processing ActivityPostViewed batch
net.luvit.jmongo.OMException: Mongo error code '10,287' message: '{ "serverUsed" : "mongo:270" , "ok" : 1 , "n" : 0 , "err" : "insertDocument :: caused by :: 10287 btree: key+recloc already in index" , "code" : 10287}'
        at net.luvit.jmongo.facade.MongoOMFacade.insert(MongoOMFacade.java:182)

Offending query:

insert luvit.Activity query: { _id: ObjectId('53878af8e4b07cce4c18998e'), userId: ObjectId('521bca84e4b03eef4046666f'), date: new Date(1401391864036), disabled: false, type: 1, userHidden: false, userActivity: false, postId: 1853, postActivity: true, postActivityNonComment: true, postActivityViewed: { viewedByUserId: ObjectId('525cb9a3e4b0bd2be59c0ab7'), httpReferer: "http://www.dw.luvit.net/david.wartell.39/Wt-4", userAgent: "Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/34.0.1847.137 Safari/537.36", remoteAddr: "76.30.122.90", privacyViewType: "USER_ID", periodId: "01" }, version: 0 }

> db.serverBuildInfo()

{
        "version" : "2.6.0",
        "gitVersion" : "1c1c76aeca21c5983dc178920f5052c298db616c",
        "OpenSSLVersion" : "",
        "sysInfo" : "Linux build14.nj1.10gen.cc 2.6.32-431.3.1.el6.x86_64 #1 SMP Fri Jan 3 21:39:27 UTC 2014 x86_64 BOOST_LIB_VERSION=1_49",
        "loaderFlags" : "-fPIC -pthread -Wl,-z,now -rdynamic",
        "compilerFlags" : "-Wnon-virtual-dtor -Woverloaded-virtual -fPIC -fno-strict-aliasing -ggdb -pthread -Wall -Wsign-compare -Wno-unknown-pragmas -Winvalid-pch -Werror -pipe -O3 -Wno-unused-function -Wno-deprecated-declarations -fno-builtin-memcmp",
        "allocator" : "tcmalloc",
        "versionArray" : [
                2,
                6,
                0,
                0
        ],
        "javascriptEngine" : "V8",
        "bits" : 64,
        "debug" : false,
        "maxBsonObjectSize" : 16777216,
        "ok" : 1
}

> db.Activity.getIndexes()

[
        {
                "v" : 1,
                "key" : {
                        "_id" : 1
                },
                "ns" : "luvit.Activity",
                "name" : "_id_"
        },
        {
                "v" : 1,
                "key" : {
                        "_id" : "hashed"
                },
                "ns" : "luvit.Activity",
                "name" : "hash",
                "background" : true
        },
        {
                "v" : 1,
                "key" : {
                        "postId" : 1,
                        "postActivityViewed.viewedByUserId" : 1,
                        "date" : -1
                },
                "ns" : "luvit.Activity",
                "name" : "findByPostIdAndPostView_viewedByUserId",
                "background" : true,
                "dropdups" : false,
                "sparse" : false
        },
        {
                "v" : 1,
                "key" : {
                        "postActivityViewed.periodId" : 1
                },
                "unique" : true,
                "ns" : "luvit.Activity",
                "name" : "uniquePostView_postId_viewedByUserId_periodId",
                "background" : true,
                "dropdups" : false,
                "sparse" : true
        },
        {
                "v" : 1,
                "key" : {
                        "postId" : 1,
                        "postActivityComment.fbCommentId" : 1
                },
                "ns" : "luvit.Activity",
                "name" : "findByPostCommentFacebookCommentId",
                "background" : true,
                "dropdups" : false,
                "sparse" : false
        },
        {
                "v" : 1,
                "key" : {
                        "userId" : 1,
                        "userHidden" : 1,
                        "disabled" : 1,
                        "date" : -1,
                        "_id" : -1
                },
                "name" : "findByUserId",
                "ns" : "luvit.Activity",
                "background" : true,
                "dropdups" : false,
                "sparse" : false
        },
        {
                "v" : 1,
                "key" : {
                        "userId" : 1,
                        "userHidden" : 1,
                        "disabled" : 1,
                        "type" : 1,
                        "date" : -1,
                        "_id" : -1
                },
                "name" : "findByUserIdAndType",
                "ns" : "luvit.Activity",
                "background" : true,
                "dropdups" : false,
                "sparse" : false
        },
        {
                "v" : 1,
                "key" : {
                        "userId" : 1,
                        "userHidden" : 1,
                        "disabled" : 1,
                        "userActivity" : 1,
                        "date" : -1,
                        "_id" : -1
                },
                "name" : "findByUserIdUserActivitiesOnly",
                "ns" : "luvit.Activity",
                "background" : true,
                "dropdups" : false,
                "sparse" : false
        },
        {
                "v" : 1,
                "key" : {
                        "postId" : 1,
                        "userHidden" : 1,
                        "disabled" : 1,
                        "date" : -1,
                        "_id" : -1
                },
                "name" : "findByPostId",
                "ns" : "luvit.Activity",
                "background" : true,
                "dropdups" : false,
                "sparse" : false
        },
        {
                "v" : 1,
                "key" : {
                        "postId" : 1,
                        "type" : 1,
                        "userHidden" : 1,
                        "disabled" : 1,
                        "date" : -1,
                        "_id" : -1
                },
                "name" : "findByPostIdAndType",
                "ns" : "luvit.Activity",
                "background" : true,
                "dropdups" : false,
                "sparse" : false
        },
        {
                "v" : 1,
                "key" : {
                        "postId" : 1,
                        "postActivityNonComment" : 1,
                        "userHidden" : 1,
                        "disabled" : 1,
                        "date" : -1,
                        "_id" : -1
                },
                "name" : "findByPostIdAndNotComment",
                "ns" : "luvit.Activity",
                "background" : true,
                "dropdups" : false,
                "sparse" : false
        }
]

> db.stats()

{
        "db" : "luvit",
        "collections" : 18,
        "objects" : 6353,
        "avgObjSize" : 5594.595309302692,
        "dataSize" : 35542464,
        "storageSize" : 50589696,
        "numExtents" : 42,
        "indexes" : 72,
        "indexSize" : 4733904,
        "fileSize" : 201326592,
        "nsSizeMB" : 16,
        "dataFileVersion" : {
                "major" : 4,
                "minor" : 6
        },
        "extentFreeList" : {
                "num" : 17,
                "totalSize" : 626688
        },
        "ok" : 1
}

> db.Activity.stats()

{
        "ns" : "luvit.Activity",
        "count" : 394,
        "size" : 189376,
        "avgObjSize" : 480,
        "storageSize" : 516096,
        "numExtents" : 3,
        "nindexes" : 11,
        "lastExtentSize" : 393216,
        "paddingFactor" : 1,
        "systemFlags" : 0,
        "userFlags" : 0,
        "totalIndexSize" : 408800,
        "indexSizes" : {
                "_id_" : 73584,
                "hash" : 24528,
                "findByPostIdAndPostView_viewedByUserId" : 32704,
                "uniquePostView_postId_viewedByUserId_periodId" : 8176,
                "findByPostCommentFacebookCommentId" : 24528,
                "findByUserId" : 40880,
                "findByUserIdAndType" : 40880,
                "findByUserIdUserActivitiesOnly" : 40880,
                "findByPostId" : 40880,
                "findByPostIdAndType" : 40880,
                "findByPostIdAndNotComment" : 40880
        },
        "ok" : 1
}

> db.Activity.find().limit(10).pretty()

{
        "_id" : ObjectId("524c9355e4b036fd9ca4f201"),
        "userId" : ObjectId("521bca84e4b03eef4046666f"),
        "date" : ISODate("2013-10-02T21:42:45.155Z"),
        "type" : 1,
        "userActivity" : false,
        "userHidden" : false,
        "postId" : 68,
        "postActivity" : true,
        "postActivityPublic" : false,
        "postActivityPrivate" : true,
        "postActivityViewed" : {
                "viewedByUserId" : ObjectId("523f1e2fe4b03ef603f139e5"),
                "userAgent" : "Mozilla/5.0 (Windows NT 6.1; WOW64; rv:24.0) Gecko/20100101 Firefox/24.0",
                "remoteAddr" : "76.30.122.90",
                "privacyViewType" : "USER_ID"
        },
        "version" : 0
}
{
        "_id" : ObjectId("524c9bece4b01911638c6fb8"),
        "userId" : ObjectId("523f1e2fe4b03ef603f139e5"),
        "date" : ISODate("2013-10-02T22:19:24.732Z"),
        "type" : 1,
        "userActivity" : false,
        "userHidden" : false,
        "postId" : 72,
        "postActivity" : true,
        "postActivityPublic" : false,
        "postActivityPrivate" : true,
        "postActivityViewed" : {
                "viewedByUserId" : ObjectId("521bca84e4b03eef4046666f"),
                "userAgent" : "Mozilla/5.0 (iPhone; CPU iPhone OS 6_1_4 like Mac OS X) AppleWebKit/536.26 (KHTML, like Gecko) CriOS/30.0.1599.12 Mobile/10B350 Safari/8536.25",
                "remoteAddr" : "76.30.122.90",
                "privacyViewType" : "USER_ID"
        },
        "version" : 0
}
{
        "_id" : ObjectId("524cec46e4b05d632175b814"),
        "userId" : ObjectId("521bca84e4b03eef4046666f"),
        "date" : ISODate("2013-10-03T04:02:14.746Z"),
        "type" : 1,
        "userActivity" : false,
        "userHidden" : false,
        "postId" : 71,
        "postActivity" : true,
        "postActivityPublic" : false,
        "postActivityPrivate" : true,
        "postActivityViewed" : {
                "viewedByUserId" : ObjectId("523f1e2fe4b03ef603f139e5"),
                "userAgent" : "Mozilla/5.0 (Windows NT 6.1; WOW64; rv:24.0) Gecko/20100101 Firefox/24.0",
                "remoteAddr" : "76.30.122.90",
                "privacyViewType" : "USER_ID"
        },
        "version" : 0
}
{
        "_id" : ObjectId("524e65d7e4b0f8ed806e2d3a"),
        "userId" : ObjectId("523f1e2fe4b03ef603f139e5"),
        "date" : ISODate("2013-10-04T06:53:11.671Z"),
        "type" : 1,
        "userActivity" : false,
        "userHidden" : false,
        "postId" : 85,
        "postActivity" : true,
        "postActivityPublic" : false,
        "postActivityPrivate" : true,
        "postActivityViewed" : {
                "viewedByUserId" : ObjectId("521bca84e4b03eef4046666f"),
                "userAgent" : "Mozilla/5.0 (compatible; MSIE 10.0; Windows NT 6.1; WOW64; Trident/6.0)",
                "remoteAddr" : "76.30.122.90",
                "privacyViewType" : "USER_ID"
        },
        "version" : 0
}
{
        "_id" : ObjectId("524f2145e4b09b28dd9b673e"),
        "userId" : ObjectId("523f1e2fe4b03ef603f139e5"),
        "date" : ISODate("2013-10-04T20:12:53.066Z"),
        "type" : 1,
        "userActivity" : false,
        "userHidden" : false,
        "postId" : 70,
        "postActivity" : true,
        "postActivityPublic" : false,
        "postActivityPrivate" : true,
        "postActivityViewed" : {
                "viewedByUserId" : ObjectId("521bca84e4b03eef4046666f"),
                "userAgent" : "Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/30.0.1599.69 Safari/537.36",
                "remoteAddr" : "76.30.122.90",
                "privacyViewType" : "USER_ID"
        },
        "version" : 0
}
{
        "_id" : ObjectId("525378b7e4b00522551fa5c4"),
        "userId" : ObjectId("521bca84e4b03eef4046666f"),
        "date" : ISODate("2013-10-08T03:15:03.566Z"),
        "type" : 1,
        "userActivity" : false,
        "userHidden" : false,
        "postId" : 75,
        "postActivity" : true,
        "postActivityPublic" : false,
        "postActivityPrivate" : true,
        "postActivityViewed" : {
                "viewedByUserId" : ObjectId("523f1e2fe4b03ef603f139e5"),
                "userAgent" : "Mozilla/5.0 (Windows NT 6.1; WOW64; rv:24.0) Gecko/20100101 Firefox/24.0",
                "remoteAddr" : "76.30.122.90",
                "privacyViewType" : "USER_ID"
        },
        "version" : 0
}
{
        "_id" : ObjectId("52546e36e4b062ff14c57c01"),
        "userId" : ObjectId("521bca84e4b03eef4046666f"),
        "date" : ISODate("2013-10-08T20:42:30.249Z"),
        "type" : 1,
        "userActivity" : false,
        "userHidden" : false,
        "postId" : 87,
        "postActivity" : true,
        "postActivityPublic" : false,
        "postActivityPrivate" : true,
        "postActivityViewed" : {
                "viewedByUserId" : ObjectId("523f1e2fe4b03ef603f139e5"),
                "userAgent" : "Mozilla/5.0 (Windows NT 6.1; WOW64; rv:24.0) Gecko/20100101 Firefox/24.0",
                "remoteAddr" : "76.30.122.90",
                "privacyViewType" : "USER_ID"
        },
        "version" : 0
}
{
        "_id" : ObjectId("525743b5e4b0590c101517cd"),
        "userId" : ObjectId("521bca84e4b03eef4046666f"),
        "date" : ISODate("2013-10-11T00:17:57.314Z"),
        "type" : 1,
        "userActivity" : false,
        "userHidden" : false,
        "postId" : 75,
        "postActivity" : true,
        "postActivityPublic" : false,
        "postActivityPrivate" : true,
        "postActivityViewed" : {
                "viewedByUserId" : ObjectId("523f1e2fe4b03ef603f139e5"),
                "userAgent" : "Mozilla/5.0 (Windows NT 6.1; WOW64; rv:24.0) Gecko/20100101 Firefox/24.0",
                "remoteAddr" : "76.30.122.90",
                "privacyViewType" : "USER_ID"
        },
        "version" : 0
}
{
        "_id" : ObjectId("525b5b98e4b06a623826f012"),
        "userId" : ObjectId("523f1e2fe4b03ef603f139e5"),
        "date" : ISODate("2013-10-14T02:48:56.844Z"),
        "type" : 1,
        "userActivity" : false,
        "userHidden" : false,
        "postId" : 100,
        "postActivity" : true,
        "postActivityPublic" : false,
        "postActivityPrivate" : true,
        "postActivityViewed" : {
                "viewedByUserId" : ObjectId("523cb1a7e4b072b1f3d9997d"),
                "userAgent" : "Mozilla/5.0 (Windows NT 6.1; WOW64; rv:24.0) Gecko/20100101 Firefox/24.0",
                "remoteAddr" : "76.30.122.90",
                "privacyViewType" : "USER_ID"
        },
        "version" : 0
}
{
        "_id" : ObjectId("525b5bcde4b003b74308001b"),
        "userId" : ObjectId("523f1e2fe4b03ef603f139e5"),
        "date" : ISODate("2013-10-14T02:49:49.374Z"),
        "type" : 0,
        "userActivity" : false,
        "userHidden" : false,
        "postId" : 100,
        "postActivity" : true,
        "postActivityPublic" : true,
        "postActivityPrivate" : false,
        "postActivityLuvThis" : {
                "srcPostUserId" : ObjectId("523cb1a7e4b072b1f3d9997d"),
                "srcPostId" : 101
        },
        "version" : 0
}

root@mongo:/luvit/working/log# tail -100 mongod.log

2014-05-29T16:52:37.113+0000 [conn716]  authenticate db: luvit { authenticate: 1, user: "luvit", nonce: "xxx", key: "xxx" }
2014-05-29T16:53:43.984+0000 [conn718]  authenticate db: luvit { authenticate: 1, user: "luvit", nonce: "xxx", key: "xxx" }
2014-05-29T16:53:45.849+0000 [conn719]  authenticate db: luvit { authenticate: 1, user: "luvit", nonce: "xxx", key: "xxx" }
2014-05-29T16:56:29.110+0000 [conn721]  authenticate db: luvit { authenticate: 1, user: "luvit", nonce: "xxx", key: "xxx" }
2014-05-29T16:56:30.279+0000 [conn722]  authenticate db: luvit { authenticate: 1, user: "luvit", nonce: "xxx", key: "xxx" }
2014-05-29T17:00:00.143+0000 [conn724]  authenticate db: luvit { authenticate: 1, user: "luvit", nonce: "xxx", key: "xxx" }
2014-05-29T17:00:01.375+0000 [conn725]  authenticate db: luvit { authenticate: 1, user: "luvit", nonce: "xxx", key: "xxx" }
2014-05-29T17:28:13.825+0000 [conn726]  authenticate db: luvit { authenticate: 1, user: "luvit", nonce: "xxx", key: "xxx" }
2014-05-29T17:29:00.886+0000 [conn727]  authenticate db: luvit { authenticate: 1, user: "luvit", nonce: "xxx", key: "xxx" }
2014-05-29T17:34:50.593+0000 [conn725] update luvit.ActivityPostMonthlyStats query: { _id: "2014-05/1425" } update: { $setOnInsert: { postId: 1425, date: new Date(1398902400000), views: { total: 0, daily: [ 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 ] }, luvThis: { total: 0, daily: [ 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 ] }, comments: { total: 0, daily: [ 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 ] }, version: 0 } } nscanned:0 nscannedObjects:0 nMatched:1 nModified:0 upsert:1 keyUpdates:0 numYields:0 locks(micros) w:109390 109ms
2014-05-29T17:34:50.593+0000 [conn725] command luvit.$cmd command: update { $msg: "query not recording (too large)" } keyUpdates:0 numYields:0  reslen:111 110ms
2014-05-29T17:34:50.708+0000 [conn728]  authenticate db: luvit { authenticate: 1, user: "luvit", nonce: "xxx", key: "xxx" }
2014-05-29T18:06:32.756+0000 [conn730]  authenticate db: luvit { authenticate: 1, user: "luvit", nonce: "xxx", key: "xxx" }
2014-05-29T18:06:34.033+0000 [conn731]  authenticate db: luvit { authenticate: 1, user: "luvit", nonce: "xxx", key: "xxx" }
2014-05-29T18:14:00.689+0000 [conn733]  authenticate db: luvit { authenticate: 1, user: "luvit", nonce: "xxx", key: "xxx" }
2014-05-29T18:16:06.099+0000 [conn734]  authenticate db: luvit { authenticate: 1, user: "luvit", nonce: "xxx", key: "xxx" }
2014-05-29T18:20:27.943+0000 [conn736]  authenticate db: luvit { authenticate: 1, user: "luvit", nonce: "xxx", key: "xxx" }
2014-05-29T18:20:47.527+0000 [conn737]  authenticate db: luvit { authenticate: 1, user: "luvit", nonce: "xxx", key: "xxx" }
2014-05-29T18:29:22.435+0000 [conn739]  authenticate db: luvit { authenticate: 1, user: "luvit", nonce: "xxx", key: "xxx" }
2014-05-29T18:31:41.836+0000 [conn741]  authenticate db: luvit { authenticate: 1, user: "luvit", nonce: "xxx", key: "xxx" }
2014-05-29T18:35:26.105+0000 [conn743]  authenticate db: luvit { authenticate: 1, user: "luvit", nonce: "xxx", key: "xxx" }
2014-05-29T18:37:18.634+0000 [conn745]  authenticate db: luvit { authenticate: 1, user: "luvit", nonce: "xxx", key: "xxx" }
2014-05-29T18:45:51.432+0000 [conn747]  authenticate db: luvit { authenticate: 1, user: "luvit", nonce: "xxx", key: "xxx" }
2014-05-29T18:48:17.836+0000 [conn749]  authenticate db: luvit { authenticate: 1, user: "luvit", nonce: "xxx", key: "xxx" }
2014-05-29T18:52:36.853+0000 [conn751]  authenticate db: luvit { authenticate: 1, user: "luvit", nonce: "xxx", key: "xxx" }
2014-05-29T18:53:54.415+0000 [conn753]  authenticate db: luvit { authenticate: 1, user: "luvit", nonce: "xxx", key: "xxx" }
2014-05-29T18:54:09.906+0000 [conn754]  authenticate db: luvit { authenticate: 1, user: "luvit", nonce: "xxx", key: "xxx" }
2014-05-29T18:59:33.806+0000 [conn756]  authenticate db: luvit { authenticate: 1, user: "luvit", nonce: "xxx", key: "xxx" }
2014-05-29T18:59:35.565+0000 [conn757]  authenticate db: luvit { authenticate: 1, user: "luvit", nonce: "xxx", key: "xxx" }
2014-05-29T19:03:34.751+0000 [conn759]  authenticate db: luvit { authenticate: 1, user: "luvit", nonce: "xxx", key: "xxx" }
2014-05-29T19:03:36.576+0000 [conn760]  authenticate db: luvit { authenticate: 1, user: "luvit", nonce: "xxx", key: "xxx" }
2014-05-29T19:08:07.770+0000 [conn762]  authenticate db: luvit { authenticate: 1, user: "luvit", nonce: "xxx", key: "xxx" }
2014-05-29T19:08:09.572+0000 [conn763]  authenticate db: luvit { authenticate: 1, user: "luvit", nonce: "xxx", key: "xxx" }
2014-05-29T19:28:18.325+0000 [conn765]  authenticate db: luvit { authenticate: 1, user: "luvit", nonce: "xxx", key: "xxx" }
2014-05-29T19:28:20.322+0000 [conn766]  authenticate db: luvit { authenticate: 1, user: "luvit", nonce: "xxx", key: "xxx" }
2014-05-29T19:28:25.237+0000 [conn768]  authenticate db: luvit { authenticate: 1, user: "luvit", nonce: "xxx", key: "xxx" }
2014-05-29T19:30:59.207+0000 [conn769] Unauthorized not authorized on luvit to execute command { createIndexes: "LuvitUserLuvsPost", indexes: [ { name: "hashed", ns: "luvit.LuvitUserLuvsPost", background: true, key: { postId: "hashed" } } ] }
2014-05-29T19:31:04.114+0000 [conn769]  authenticate db: luvit { authenticate: 1, user: "luvit", nonce: "xxx", key: "xxx" }
2014-05-29T19:31:04.328+0000 [conn769] ERROR nextChild != lchild
2014-05-29T19:31:04.341+0000 [conn769]   thisLoc: 0:23000 luvit.Activity.$_id_
2014-05-29T19:31:04.341+0000 [conn769]   keyPos: 1 n:2
2014-05-29T19:31:04.341+0000 [conn769]   nextChild: 0:21000 lchild: 0:1f000
2014-05-29T19:31:04.341+0000 [conn769]   recordLoc: 0:2382960 rchild: 0:25000
2014-05-29T19:31:04.341+0000 [conn769]   key: { : ObjectId('5374f8b3e4b0246df3feb8a2') }
2014-05-29T19:31:04.351+0000 [conn769] BUCKET n:2 parent:fffffffe
  1f000
    0 { : ObjectId('52b871f2e4b06e01 Loc:0:31150
  fffffffe
    1 { : ObjectId('5374f8b3e4b0246d Loc:0:2382960
  21000
2014-05-29T19:31:04.352+0000 [conn769] luvit.Activity Assertion failure false src/mongo/db/structure/btree/btree.cpp 1392
2014-05-29T19:31:04.606+0000 [conn769] luvit.Activity 0x11bd301 0x115f819 0x114395e 0xefa5db 0xef8d04 0xef9578 0xefa6b8 0xef8d04 0xefcda0 0xb66298 0xb5fd1d 0x8cb3a7 0x8cf44c 0x8afdc3 0x8b1c5a 0xa0079d 0xa00fe5 0xa0176f 0xa019bd 0xa030bd
 /luvit/deploy/mongodb/bin/mongod(_ZN5mongo15printStackTraceERSo+0x21) [0x11bd301]
 /luvit/deploy/mongodb/bin/mongod(_ZN5mongo10logContextEPKc+0x159) [0x115f819]
 /luvit/deploy/mongodb/bin/mongod(_ZN5mongo12verifyFailedEPKcS1_j+0x17e) [0x114395e]
 /luvit/deploy/mongodb/bin/mongod(_ZNK5mongo11BtreeBucketINS_12BtreeData_V1EE10insertHereEPNS_17IndexCatalogEntryENS_7DiskLocEiS5_RKNS_5KeyV1ES5_S5_+0xb9b) [0xefa5db]
 /luvit/deploy/mongodb/bin/mongod(_ZNK5mongo11BtreeBucketINS_12BtreeData_V1EE7_insertEPNS_17IndexCatalogEntryENS_7DiskLocES5_RKNS_5KeyV1EbS5_S5_+0x624) [0xef8d04]
 /luvit/deploy/mongodb/bin/mongod(_ZN5mongo11BtreeBucketINS_12BtreeData_V1EE5splitEPNS_17IndexCatalogEntryENS_7DiskLocEiS5_RKNS_5KeyV1ES5_S5_+0x578) [0xef9578]
 /luvit/deploy/mongodb/bin/mongod(_ZNK5mongo11BtreeBucketINS_12BtreeData_V1EE10insertHereEPNS_17IndexCatalogEntryENS_7DiskLocEiS5_RKNS_5KeyV1ES5_S5_+0xc78) [0xefa6b8]
 /luvit/deploy/mongodb/bin/mongod(_ZNK5mongo11BtreeBucketINS_12BtreeData_V1EE7_insertEPNS_17IndexCatalogEntryENS_7DiskLocES5_RKNS_5KeyV1EbS5_S5_+0x624) [0xef8d04]
 /luvit/deploy/mongodb/bin/mongod(_ZNK5mongo11BtreeBucketINS_12BtreeData_V1EE9bt_insertEPNS_17IndexCatalogEntryENS_7DiskLocES5_RKNS_7BSONObjEbb+0x110) [0xefcda0]
 /luvit/deploy/mongodb/bin/mongod(_ZN5mongo18BtreeInterfaceImplINS_12BtreeData_V1EE9bt_insertEPNS_17IndexCatalogEntryENS_7DiskLocES5_RKNS_7BSONObjEbb+0x78) [0xb66298]
 /luvit/deploy/mongodb/bin/mongod(_ZN5mongo22BtreeBasedAccessMethod6insertERKNS_7BSONObjERKNS_7DiskLocERKNS_19InsertDeleteOptionsEPlPKNS_23PregeneratedKeysOnIndexE+0x1bd) [0xb5fd1d]
 /luvit/deploy/mongodb/bin/mongod(_ZN5mongo12IndexCatalog12_indexRecordEPNS_17IndexCatalogEntryERKNS_7BSONObjERKNS_7DiskLocEPKNS_23PregeneratedKeysOnIndexE+0xc7) [0x8cb3a7]
 /luvit/deploy/mongodb/bin/mongod(_ZN5mongo12IndexCatalog11indexRecordERKNS_7BSONObjERKNS_7DiskLocEPKNS_16PregeneratedKeysE+0x7c) [0x8cf44c]
 /luvit/deploy/mongodb/bin/mongod(_ZN5mongo10Collection15_insertDocumentERKNS_7BSONObjEbPKNS_16PregeneratedKeysE+0xb3) [0x8afdc3]
 /luvit/deploy/mongodb/bin/mongod(_ZN5mongo10Collection14insertDocumentERKNS_7BSONObjEbPKNS_16PregeneratedKeysE+0x22a) [0x8b1c5a]
 /luvit/deploy/mongodb/bin/mongod() [0xa0079d]
 /luvit/deploy/mongodb/bin/mongod(_ZN5mongo18WriteBatchExecutor13execOneInsertEPNS0_16ExecInsertsStateEPPNS_16WriteErrorDetailE+0x95) [0xa00fe5]
 /luvit/deploy/mongodb/bin/mongod(_ZN5mongo18WriteBatchExecutor11execInsertsERKNS_21BatchedCommandRequestEPSt6vectorIPNS_16WriteErrorDetailESaIS6_EE+0x5af) [0xa0176f]
 /luvit/deploy/mongodb/bin/mongod(_ZN5mongo18WriteBatchExecutor11bulkExecuteERKNS_21BatchedCommandRequestEPSt6vectorIPNS_19BatchedUpsertDetailESaIS6_EEPS4_IPNS_16WriteErrorDetailESaISB_EE+0x3d) [0xa019bd]
 /luvit/deploy/mongodb/bin/mongod(_ZN5mongo18WriteBatchExecutor12executeBatchERKNS_21BatchedCommandRequestEPNS_22BatchedCommandResponseE+0x8cd) [0xa030bd]
2014-05-29T19:31:04.607+0000 [conn769] insert luvit.Activity query: { _id: ObjectId('53878af8e4b07cce4c18998e'), userId: ObjectId('521bca84e4b03eef4046666f'), date: new Date(1401391864036), disabled: false, type: 1, userHidden: false, userActivity: false, postId: 1853, postActivity: true, postActivityNonComment: true, postActivityViewed: { viewedByUserId: ObjectId('525cb9a3e4b0bd2be59c0ab7'), httpReferer: "http://www.dw.luvit.net/david.wartell.39/Wt-4", userAgent: "Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/34.0.1847.137 Safari/537.36", remoteAddr: "76.30.122.90", privacyViewType: "USER_ID", periodId: "01" }, version: 0 } ninserted:0 keyUpdates:0 exception: insertDocument :: caused by :: 0 assertion src/mongo/db/structure/btree/btree.cpp:1392 code:8 numYields:0 locks(micros) w:293613 293ms
2014-05-29T19:31:04.607+0000 [conn769] command luvit.$cmd command: insert { $msg: "query not recording (too large)" } keyUpdates:0 numYields:0  reslen:186 294ms
2014-05-29T19:41:59.965+0000 [conn771]  authenticate db: luvit { authenticate: 1, user: "luvit", nonce: "xxx", key: "xxx" }
2014-05-29T19:42:01.417+0000 [conn772]  authenticate db: luvit { authenticate: 1, user: "luvit", nonce: "xxx", key: "xxx" }
2014-05-29T20:14:27.792+0000 [conn773]  authenticate db: luvit { authenticate: 1, user: "luvit", nonce: "xxx", key: "xxx" }
2014-05-29T20:36:02.309+0000 [conn775]  authenticate db: luvit { authenticate: 1, user: "luvit", nonce: "xxx", key: "xxx" }
2014-05-29T20:36:07.761+0000 [conn776]  authenticate db: luvit { authenticate: 1, user: "luvit", nonce: "xxx", key: "xxx" }
2014-05-29T20:38:44.737+0000 [conn778]  authenticate db: luvit { authenticate: 1, user: "luvit", nonce: "xxx", key: "xxx" }
2014-05-29T20:56:38.624+0000 [conn780]  authenticate db: luvit { authenticate: 1, user: "luvit", nonce: "xxx", key: "xxx" }
2014-05-29T20:56:52.018+0000 [conn781]  authenticate db: luvit { authenticate: 1, user: "luvit", nonce: "xxx", key: "xxx" }
2014-05-29T21:04:31.633+0000 [conn783]  authenticate db: luvit { authenticate: 1, user: "luvit", nonce: "xxx", key: "xxx" }
2014-05-29T21:48:57.280+0000 [conn785]  authenticate db: luvit { authenticate: 1, user: "luvit", nonce: "xxx", key: "xxx" }
2014-05-29T21:49:03.814+0000 [conn786]  authenticate db: luvit { authenticate: 1, user: "luvit", nonce: "xxx", key: "xxx" }
2014-05-30T00:47:07.455+0000 [conn788]  authenticate db: luvit { authenticate: 1, user: "luvit", nonce: "xxx", key: "xxx" }
2014-05-30T00:47:10.188+0000 [conn789]  authenticate db: luvit { authenticate: 1, user: "luvit", nonce: "xxx", key: "xxx" }
2014-05-30T01:14:54.971+0000 [conn791]  authenticate db: luvit { authenticate: 1, user: "luvit", nonce: "xxx", key: "xxx" }
2014-05-30T01:14:56.298+0000 [conn792]  authenticate db: luvit { authenticate: 1, user: "luvit", nonce: "xxx", key: "xxx" }
2014-05-30T01:16:27.959+0000 [conn794]  authenticate db: luvit { authenticate: 1, user: "luvit", nonce: "xxx", key: "xxx" }
2014-05-30T01:16:30.066+0000 [conn795]  authenticate db: luvit { authenticate: 1, user: "luvit", nonce: "xxx", key: "xxx" }
2014-05-30T01:20:29.799+0000 [conn797]  authenticate db: luvit { authenticate: 1, user: "luvit", nonce: "xxx", key: "xxx" }
2014-05-30T01:20:31.245+0000 [conn798]  authenticate db: luvit { authenticate: 1, user: "luvit", nonce: "xxx", key: "xxx" }
2014-05-30T14:25:02.918+0000 [conn800]  authenticate db: luvit { authenticate: 1, user: "luvit", nonce: "xxx", key: "xxx" }
2014-05-30T14:25:04.271+0000 [conn801]  authenticate db: luvit { authenticate: 1, user: "luvit", nonce: "xxx", key: "xxx" }
2014-05-30T14:39:48.188+0000 [conn802]  authenticate db: luvit { authenticate: 1, nonce: "xxx", user: "luvit", key: "xxx" }
2014-05-30T14:39:48.191+0000 [conn802] Unauthorized not authorized on admin to execute command { getLog: "startupWarnings" }
2014-05-30T14:39:48.218+0000 [conn802] Unauthorized not authorized on admin to execute command { replSetGetStatus: 1.0, forShell: 1.0 }
2014-05-30T14:43:35.159+0000 [conn802] command luvit.$cmd command: dbStats { dbstats: 1.0, scale: undefined } keyUpdates:0 numYields:0 locks(micros) r:884817 reslen:293 884ms
2014-05-30T14:44:43.550+0000 [conn802] Unauthorized not authorized on admin to execute command { hostInfo: 1.0 }

Comment by David Storch [ 20/May/14 ]

Hi Mike,

Apologies for the delay in our response. If possible, could you please provide the following additional information in order to help diagnose the problem:

  • Snippets from the mongod logs from the timeframe just before these exceptions started occurring and while they were occurring.
  • A few examples of the update ops that failed with this exception.
  • The output of db.<coll>.getIndexes(), where <coll> is replaced with the name of your collection.
  • The output of db.stats()
  • The output of db.<coll>.stats()
  • The output of db.hostInfo()
  • The output of db.serverBuildInfo()
  • The output of db.<coll>.find().limit(10).pretty()

Do you have any specific steps which I could follow to consistently reproduce the failed updates?

Thanks a lot for your help. Hopefully with some additional information we can figure out what's going on here!

Best,
Dave

Comment by Mike Robertson [ 18/Apr/14 ]

This also happens on Ubuntu. Any repeated updates to the text field of a document that's being full-text indexed in 2.5 or later leads to this error.

Comment by Mike Robertson [ 18/Apr/14 ]

This issue is happening constantly for me on Debian with the 2.6.0 release (that's 2.6.0 – the latest release – not 2.0.6). I have a full text index on the collection being modified and am repeatedly making small text modifications to the indexed field. Strangely, I've never seen this error happen on the mac, but see it within minutes of using the database on Debian.

I also never saw this happening with 2.4 with the full text index

This is most definitely not a harmless debug statement. When this happens, the updates are rejected.

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