Duplicate Key Error in BlockchainWriter onCreateBatchSuccess

[lautarodragan]

I'm finding this a lot in the QA environment logs.

{  
   "msg":"Anchor request failure",
   "module":"BlockchainWriter",
   "file":"Router",
   "method":"onCreateBatchSuccess",
   "error":{  
      "driver":true,
      "name":"MongoError",
      "index":0,
      "code":11000,
      "errmsg":"E11000 duplicate key error collection: regtest.blockchainWriter index: ipfsDirectoryHash_1 dup key: { : \"QmbuvwFrxRu54uLkF12Ch3LiBZyA8vRTiQ2rfPenM3jxX7\" }",
      "stack":[  
         "MongoError: E11000 duplicate key error collection: regtest.blockchainWriter index: ipfsDirectoryHash_1 dup key: { : \"QmbuvwFrxRu54uLkF12Ch3LiBZyA8vRTiQ2rfPenM3jxX7\" }",
         "    at Function.create (/usr/src/app/node_modules/mongodb-core/lib/error.js:43:12)",
         "    at toError (/usr/src/app/node_modules/mongodb/lib/utils.js:149:22)",
         "    at coll.s.topology.insert (/usr/src/app/node_modules/mongodb/lib/operations/collection_ops.js:844:39)",
         "    at handler (/usr/src/app/node_modules/mongodb-core/lib/topologies/replset.js:1195:22)",
         "    at /usr/src/app/node_modules/mongodb-core/lib/connection/pool.js:532:18",
         "    at process._tickCallback (internal/process/next_tick.js:61:11)"
      ],
      "message":"E11000 duplicate key error collection: regtest.blockchainWriter index: ipfsDirectoryHash_1 dup key: { : \"QmbuvwFrxRu54uLkF12Ch3LiBZyA8vRTiQ2rfPenM3jxX7\" }",
      "type":"MongoError"
   },
   "ipfsDirectoryHash":"QmbuvwFrxRu54uLkF12Ch3LiBZyA8vRTiQ2rfPenM3jxX7",
   "v":1
}

I think there is one for each POST request.

[geoffturk]

Reassigning to @krobi64.

[krobi64]

Kris Robison [11:51 AM]
in our qa environment, do multiple node instances share the same RMQ and mongo instance?

Warren Vosper [12:09 PM]
hello! yes, that would be the case in any env unless MONGODB_DATABASE and EXCHANGE_PREFIX are set to unique values for each node instance.

So here’s what I believe is happening… there is a race condition between multiple node instances picking up the same event and attempting to do an insert. If we modify the hard insert, then I think that error message will go away

I’ll try to create a test that does that locally

[geoffturk]

@warrenv Is this related to #328?

[warrenv]

yes, this is probably a subset of the issue in #328

[lautarodragan]

Discussed this with Kris on the side, leaving a comment here for reference.

This is most likely not an issue related to #328, since the QA node instances don't share the same db, and there's only one instance of the node for each (one mainnet, one testnet).

[geoffturk]

OK, so even with a freshly reset DB (regtest DB in QA), this error pops up for the very first work being written into the DB:

> @po.et/node@1.0.3 start /usr/src/app
> node dist/babel/src

Running Po.et Node

Loading Configuration...
Switching to Structured Logging
Logging Level: error

(node:26) DeprecationWarning: current URL string parser is deprecated, and will be removed in a future version. To use the new parser, pass option { useNewUrlParser: true } to MongoClient.connect.
Fri, 07 Dec 2018 10:20:01 GMT koa deprecated Support for generators will be removed in v3. See the documentation for examples of how to convert old middleware https://github.com/koajs/koa/blob/master/docs/migration.md at dist/babel/src/API/Router.js:108:18
(node:26) DeprecationWarning: collection.find option [fields] is deprecated and will be removed in a later version.
{"level":50,"time":1544181002026,"msg":"Anchor request failure","pid":26,"hostname":"node-regtest-poet-node-57d569b6b8-djst8","module":"BlockchainWriter","file":"Router","method":"onCreateBatchSuccess","error":{"driver":true,"name":"MongoError","index":0,"code":11000,"errmsg":"E11000 duplicate key error collection: regtest.blockchainWriter index: ipfsDirectoryHash_1 dup key: { : \"QmdjuqK3GQnDnB9KfoKHApXpTR7DUb4haMfVcK1kjT2jCo\" }","stack":["MongoError: E11000 duplicate key error collection: regtest.blockchainWriter index: ipfsDirectoryHash_1 dup key: { : \"QmdjuqK3GQnDnB9KfoKHApXpTR7DUb4haMfVcK1kjT2jCo\" }","    at Function.create (/usr/src/app/node_modules/mongodb-core/lib/error.js:43:12)","    at toError (/usr/src/app/node_modules/mongodb/lib/utils.js:149:22)","    at coll.s.topology.insert (/usr/src/app/node_modules/mongodb/lib/operations/collection_ops.js:844:39)","    at handler (/usr/src/app/node_modules/mongodb-core/lib/topologies/replset.js:1195:22)","    at /usr/src/app/node_modules/mongodb-core/lib/connection/pool.js:532:18","    at process._tickCallback (internal/process/next_tick.js:61:11)"],"message":"E11000 duplicate key error collection: regtest.blockchainWriter index: ipfsDirectoryHash_1 dup key: { : \"QmdjuqK3GQnDnB9KfoKHApXpTR7DUb4haMfVcK1kjT2jCo\" }","type":"MongoError"},"ipfsDirectoryHash":"QmdjuqK3GQnDnB9KfoKHApXpTR7DUb4haMfVcK1kjT2jCo","v":1}

[krobi64]

@WesleyCharlesBlake Are we seeing this error in production or only QA? I tried looking for it in Logz, but the only error messages I see are Access Denied.

I have yet to figure out how to replicate it locally.

[geoffturk]

@WesleyCharlesBlake ^^^^^^^^^^^^^^^^

[geoffturk]

@krobi64 We're getting them in prod as well as QA.

[geoffturk]

Also, found this other variant on an IPFS directory:

t error.errmsg |   | E11000 duplicate key error collection: mainnet.ipfsDirectoryHashInfo index: ipofsDirectoryHash_1 dup key: { : null }
? error.index |   | 0
t error.message |   | E11000 duplicate key error collection: mainnet.ipfsDirectoryHashInfo index: ipofsDirectoryHash_1 dup key: { : null }
t error.name |   | MongoError
t error.stack |   | MongoError: E11000 duplicate key error collection: mainnet.ipfsDirectoryHashInfo index: ipofsDirectoryHash_1 dup key: { : null },     at Function.create (/usr/src/app/node_modules/mongodb-core/lib/error.js:43:12),     at toError (/usr/src/app/node_modules/mongodb/lib/utils.js:149:22),     at coll.s.topology.update (/usr/src/app/node_modules/mongodb/lib/operations/collection_ops.js:1399:39),     at handler (/usr/src/app/node_modules/mongodb-core/lib/topologies/replset.js:1195:22),     at /usr/src/app/node_modules/mongodb-core/lib/connection/pool.js:532:18,     at process._tickCallback (internal/process/next_tick.js:61:11)

[WesleyCharlesBlake]

yep getting it in both QA and PROD