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 | 2 years ago
  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 | 2 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 | 2 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