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}'

JIRA | J Rassi | 3 years ago
tip
Your exception is missing from the Samebug knowledge base.
Here are the best solutions we found on the Internet.
Click on the to mark the helpful solution and get rewards for you help.
  1. 0

    Creating ticket to track issue reported at [comment from SERVER-13651|https://jira.mongodb.org/browse/SERVER-13651?focusedCommentId=602834&page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel#comment-602834]: [~davidluvit] wrote: {quote} 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. {noformat} 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) {noformat} Offending query: {noformat} 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 } {noformat} > db.serverBuildInfo() {noformat} { "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 } {noformat} > db.Activity.getIndexes() {noformat} [ { "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 } ] {noformat} > db.stats() {noformat} { "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 } {noformat} > db.Activity.stats() {noformat} { "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 } {noformat} > db.Activity.find().limit(10).pretty() {noformat} { "_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 } {noformat} root@mongo:/luvit/working/log# tail -100 mongod.log {noformat} 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 } {noformat} {quote}

    JIRA | 3 years ago | Rassi
    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}'
  2. 0

    Creating ticket to track issue reported at [comment from SERVER-13651|https://jira.mongodb.org/browse/SERVER-13651?focusedCommentId=602834&page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel#comment-602834]: [~davidluvit] wrote: {quote} 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. {noformat} 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) {noformat} Offending query: {noformat} 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 } {noformat} > db.serverBuildInfo() {noformat} { "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 } {noformat} > db.Activity.getIndexes() {noformat} [ { "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 } ] {noformat} > db.stats() {noformat} { "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 } {noformat} > db.Activity.stats() {noformat} { "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 } {noformat} > db.Activity.find().limit(10).pretty() {noformat} { "_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 } {noformat} root@mongo:/luvit/working/log# tail -100 mongod.log {noformat} 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 } {noformat} {quote}

    JIRA | 3 years ago | J Rassi
    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}'

    Root Cause Analysis

    1. 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()
    2. net.luvit.jmongo
      MongoOMFacade.insert
      1. net.luvit.jmongo.facade.MongoOMFacade.insert(MongoOMFacade.java:182)
      1 frame