[SERVER-34840] Initial sync of a hidden node (buildIndex: False) triggers Index alreadyExists Created: 04/May/18  Updated: 06/Dec/22

Status: Backlog
Project: Core Server
Component/s: Replication
Affects Version/s: 3.6.3
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: Dugast Fabien Assignee: Backlog - Replication Team
Resolution: Unresolved Votes: 0
Labels: former-quick-wins
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Attachments: File dummy_db.tar.gz    
Issue Links:
Related
related to SERVER-34414 Creating a role with buildsIndexes:fa... Closed
is related to SERVER-40767 Create JS testing on replica sets wit... Backlog
Assigned Teams:
Replication
Operating System: ALL
Steps To Reproduce:

Create a replica set with 2 nodes,

One hidden: 
node =

{'host': 'test-mongo-hid.dummy.eu:27018', 'buildIndexes': false, 'hidden': true, 'priority': 0, 'votes': 0}

The other PRIMARY.

Mongorestore the dummy database:

mongorestore --dir dummy --db dummy --drop

Stop the hidden node

sudo systemctl stop mongod@my-repl

Delete all data on the hidden node

rm -rf /srv/path/to/data/my-repl/*

 

Start the node

 sudo systemctl start mongod@my-repl

 Enjoy the stacktrace.

 

A dummy database is in attachment. This database as more than 1 index.

Sprint: Repl 2018-06-04
Participants:

 Description   

Hello,

When I try to sync a hidden node (BuildIndex: false) from scratch, the process crash with the above stacktrace. The hidden node try to sync databases with more than 1 index.

From scratch mean I perform a:

 

rm rf /srv/mongodb/my-repl/*
sudo systemctl start mongod@my-repl

 

 

May 04 08:35:54 test-mongo-hid.test.dummy.eu mongod.27017[5093]: [replication-1] Starting initial sync (attempt 10 of 10)
May 04 08:35:54 test-mongo-hid.test.dummy.eu mongod.27017[5093]: [replication-1] Finishing collection drop for local.temp_oplog_buffer (no UUID).
May 04 08:35:54 test-mongo-hid.test.dummy.eu mongod.27017[5093]: [replication-1] createCollection: local.temp_oplog_buffer with no UUID.
May 04 08:35:54 test-mongo-hid.test.dummy.eu mongod.27017[5093]: [replication-1] sync source candidate: test-mongo-re1.test.dummy.eu:27017
May 04 08:35:54 test-mongo-hid.test.dummy.eu mongod.27017[5093]: [replication-1] dropAllDatabasesExceptLocal 4
May 04 08:35:54 test-mongo-hid.test.dummy.eu mongod.27017[5093]: [replication-0] CollectionCloner::start called, on ns:admin.system.roles
May 04 08:35:54 test-mongo-hid.test.dummy.eu mongod.27017[5093]: [repl writer worker 9] createCollection: admin.system.roles with provided UUID: 002f28c7-b0df-4f98-a9f0-101dbeeeb195
May 04 08:35:54 test-mongo-hid.test.dummy.eu mongod.27017[5093]: [repl writer worker 9] build index on: admin.system.roles properties: { v: 2, key: { _id: 1 }, name: "_id_", ns: "admin.system.roles" }
May 04 08:35:54 test-mongo-hid.test.dummy.eu mongod.27017[5093]: [repl writer worker 9]          building index using bulk method; build may temporarily use up to 500 megabytes of RAM
May 04 08:35:54 test-mongo-hid.test.dummy.eu mongod.27017[5093]: [repl writer worker 11] CollectionCloner ns:admin.system.roles finished cloning with status: OK
May 04 08:35:54 test-mongo-hid.test.dummy.eu mongod.27017[5093]: [repl writer worker 11] CollectionCloner::start called, on ns:admin.system.users
May 04 08:35:54 test-mongo-hid.test.dummy.eu mongod.27017[5093]: [repl writer worker 13] createCollection: admin.system.users with provided UUID: 1e30d209-454f-474e-898e-77bf2ef7ac58
May 04 08:35:54 test-mongo-hid.test.dummy.eu mongod.27017[5093]: [repl writer worker 13] build index on: admin.system.users properties: { v: 2, key: { _id: 1 }, name: "_id_", ns: "admin.system.users" }
May 04 08:35:54 test-mongo-hid.test.dummy.eu mongod.27017[5093]: [repl writer worker 13]          building index using bulk method; build may temporarily use up to 500 megabytes of RAM
May 04 08:35:54 test-mongo-hid.test.dummy.eu mongod.27017[5093]: [repl writer worker 15] CollectionCloner ns:admin.system.users finished cloning with status: OK
May 04 08:35:54 test-mongo-hid.test.dummy.eu mongod.27017[5093]: [repl writer worker 15] CollectionCloner::start called, on ns:admin.system.version
May 04 08:35:54 test-mongo-hid.test.dummy.eu mongod.27017[5093]: [repl writer worker 7] createCollection: admin.system.version with provided UUID: 1de6ed2e-0d67-4e6b-b615-20762c7ff84a
May 04 08:35:54 test-mongo-hid.test.dummy.eu mongod.27017[5093]: [repl writer worker 7] build index on: admin.system.version properties: { v: 2, key: { _id: 1 }, name: "_id_", ns: "admin.system.version" }
May 04 08:35:54 test-mongo-hid.test.dummy.eu mongod.27017[5093]: [repl writer worker 7]          building index using bulk method; build may temporarily use up to 500 megabytes of RAM
May 04 08:35:54 test-mongo-hid.test.dummy.eu mongod.27017[5093]: [repl writer worker 5] setting featureCompatibilityVersion to 3.6
May 04 08:35:54 test-mongo-hid.test.dummy.eu mongod.27017[5093]: [repl writer worker 5] Skip closing connection for connection # 3
May 04 08:35:54 test-mongo-hid.test.dummy.eu mongod.27017[5093]: [repl writer worker 5] Skip closing connection for connection # 2
May 04 08:35:54 test-mongo-hid.test.dummy.eu mongod.27017[5093]: [repl writer worker 5] Skip closing connection for connection # 1
May 04 08:35:54 test-mongo-hid.test.dummy.eu mongod.27017[5093]: [repl writer worker 5] CollectionCloner ns:admin.system.version finished cloning with status: OK
May 04 08:35:54 test-mongo-hid.test.dummy.eu mongod.27017[5093]: [repl writer worker 5] CollectionCloner::start called, on ns:admin.system.keys
May 04 08:35:54 test-mongo-hid.test.dummy.eu mongod.27017[5093]: [repl writer worker 3] createCollection: admin.system.keys with provided UUID: 1830a91b-c4f7-48ad-bf99-d69ff10066e7
May 04 08:35:54 test-mongo-hid.test.dummy.eu mongod.27017[5093]: [repl writer worker 3] build index on: admin.system.keys properties: { v: 2, key: { _id: 1 }, name: "_id_", ns: "admin.system.keys" }
May 04 08:35:54 test-mongo-hid.test.dummy.eu mongod.27017[5093]: [repl writer worker 3]          building index using bulk method; build may temporarily use up to 500 megabytes of RAM
May 04 08:35:54 test-mongo-hid.test.dummy.eu mongod.27017[5093]: [repl writer worker 2] CollectionCloner ns:admin.system.keys finished cloning with status: OK
May 04 08:35:54 test-mongo-hid.test.dummy.eu mongod.27017[5093]: [replication-0] CollectionCloner::start called, on ns:config.system.sessions
May 04 08:35:54 test-mongo-hid.test.dummy.eu mongod.27017[5093]: [repl writer worker 0] createCollection: config.system.sessions with provided UUID: a2741332-f793-497a-829d-e7abc4d4f785
May 04 08:35:54 test-mongo-hid.test.dummy.eu mongod.27017[5093]: [repl writer worker 0] build index on: config.system.sessions properties: { v: 2, key: { _id: 1 }, name: "_id_", ns: "config.system.sessions" }
May 04 08:35:54 test-mongo-hid.test.dummy.eu mongod.27017[5093]: [repl writer worker 0]          building index using bulk method; build may temporarily use up to 500 megabytes of RAM
May 04 08:35:54 test-mongo-hid.test.dummy.eu mongod.27017[5093]: [repl writer worker 10] _insertDocumentsCallback, but no documents to insert for ns:config.system.sessions
May 04 08:35:54 test-mongo-hid.test.dummy.eu mongod.27017[5093]: [repl writer worker 10] CollectionCloner ns:config.system.sessions finished cloning with status: OK
May 04 08:35:54 test-mongo-hid.test.dummy.eu mongod.27017[5093]: [repl writer worker 10] CollectionCloner::start called, on ns:config.transactions
May 04 08:35:54 test-mongo-hid.test.dummy.eu mongod.27017[5093]: [NetworkInterfaceASIO-RS-0] Connecting to test-mongo-re1.test.dummy.eu:27017
May 04 08:35:54 test-mongo-hid.test.dummy.eu mongod.27017[5093]: [repl writer worker 8] createCollection: config.transactions with provided UUID: 338bda00-b652-44ce-90fd-e3902995e63c
May 04 08:35:54 test-mongo-hid.test.dummy.eu mongod.27017[5093]: [repl writer worker 8] build index on: config.transactions properties: { v: 2, key: { _id: 1 }, name: "_id_", ns: "config.transactions" }
May 04 08:35:54 test-mongo-hid.test.dummy.eu mongod.27017[5093]: [repl writer worker 8]          building index using bulk method; build may temporarily use up to 500 megabytes of RAM
May 04 08:35:54 test-mongo-hid.test.dummy.eu mongod.27017[5093]: [repl writer worker 14] _insertDocumentsCallback, but no documents to insert for ns:config.transactions
May 04 08:35:54 test-mongo-hid.test.dummy.eu mongod.27017[5093]: [repl writer worker 14] CollectionCloner ns:config.transactions finished cloning with status: OK
May 04 08:35:54 test-mongo-hid.test.dummy.eu mongod.27017[5093]: [replication-1] CollectionCloner::start called, on ns:dummy.prometheus_exporter
May 04 08:35:54 test-mongo-hid.test.dummy.eu mongod.27017[5093]: [repl writer worker 12] createCollection: dummy.prometheus_exporter with provided UUID: 1a6a1775-5291-4d1e-94ad-2b2739fac25c
May 04 08:35:54 test-mongo-hid.test.dummy.eu mongod.27017[5093]: [NetworkInterfaceASIO-RS-0] Successfully connected to test-mongo-re1.test.dummy.eu:27017, took 30ms (3 connections now open to test-mongo-re1.test.dummy.eu:27017)
May 04 08:35:54 test-mongo-hid.test.dummy.eu mongod.27017[5093]: [repl writer worker 6] CollectionCloner ns:dummy.prometheus_exporter finished cloning with status: OK
May 04 08:35:54 test-mongo-hid.test.dummy.eu mongod.27017[5093]: [repl writer worker 6] CollectionCloner::start called, on ns:dummy.mongo_exporter.chunks
May 04 08:35:54 test-mongo-hid.test.dummy.eu mongod.27017[5093]: [repl writer worker 4] createCollection: dummy.mongo_exporter.chunks with provided UUID: ca1c7156-3f29-486e-a0a1-de6493bfbf61
May 04 08:35:54 test-mongo-hid.test.dummy.eu mongod.27017[5093]: [repl writer worker 4] CollectionCloner ns:dummy.mongo_exporter.chunks finished cloning with status: IndexAlreadyExists: no indexes per repl
May 04 08:35:54 test-mongo-hid.test.dummy.eu mongod.27017[5093]: [repl writer worker 4] collection clone for 'dummy.mongo_exporter.chunks' failed due to IndexAlreadyExists: While cloning collection 'dummy.mongo_exporter.chunks' there was an error 'no indexes per repl'
May 04 08:35:54 test-mongo-hid.test.dummy.eu mongod.27017[5093]: [repl writer worker 4] CollectionCloner::start called, on ns:dummy.mongo_exporter.files
May 04 08:35:54 test-mongo-hid.test.dummy.eu mongod.27017[5093]: [repl writer worker 1] createCollection: dummy.mongo_exporter.files with provided UUID: e36b38de-0a72-47bc-952c-dd41409e8090
May 04 08:35:54 test-mongo-hid.test.dummy.eu mongod.27017[5093]: [repl writer worker 1] CollectionCloner ns:dummy.mongo_exporter.files finished cloning with status: IndexAlreadyExists: no indexes per repl
May 04 08:35:54 test-mongo-hid.test.dummy.eu mongod.27017[5093]: [repl writer worker 1] collection clone for 'dummy.mongo_exporter.files' failed due to IndexAlreadyExists: While cloning collection 'dummy.mongo_exporter.files' there was an error 'no indexes per repl'
May 04 08:35:54 test-mongo-hid.test.dummy.eu mongod.27017[5093]: [repl writer worker 1] database 'dummy' (3 of 3) clone failed due to InitialSyncFailure: Failed to clone 2 collection(s) in 'dummy' from test-mongo-re1.test.dummy.eu:27017
May 04 08:35:54 test-mongo-hid.test.dummy.eu mongod.27017[5093]: [repl writer worker 1] Finished cloning data: InitialSyncFailure: Failed to clone 2 collection(s) in 'dummy' from test-mongo-re1.test.dummy.eu:27017. Beginning oplog replay.
May 04 08:35:54 test-mongo-hid.test.dummy.eu systemd[1]: mongod@aptest-rs1.service: Main process exited, code=exited, status=14/n/a
May 04 08:35:54 test-mongo-hid.test.dummy.eu systemd[1]: mongod@aptest-rs1.service: Unit entered failed state.
May 04 08:35:54 test-mongo-hid.test.dummy.eu systemd[1]: mongod@aptest-rs1.service: Failed with result 'exit-code'.

 

It seems that in the code, if buildIndexes is false and we are not on the _id index, you return a Status with the message on the stacktrace

https://github.com/mongodb/mongo/blob/b1cc960cb5de30861b00bf72057c5dfa0733c1fb/src/mongo/db/catalog/index_catalog_impl.cpp



 Comments   
Comment by Matthew Russotto [ 07/May/18 ]

It appears it would not; while both are related to no-index nodes they have different causes.

Comment by Kelsey Schubert [ 04/May/18 ]

matthew.russotto, would this be corrected by the work in SERVER-34414?

Generated at Thu Feb 08 04:38:02 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.