[SERVER-76624] Server can falsely report CollectionUUIDMismatch Created: 27/Apr/23  Updated: 01/Feb/24  Resolved: 01/Feb/24

Status: Closed
Project: Core Server
Component/s: None
Affects Version/s: None
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: Michael McClimon Assignee: Jordi Olivares Provencio
Resolution: Won't Fix Votes: 0
Labels: car-qw
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Depends
Problem/Incident
Related
is related to SERVER-79049 Server returns unexpected CollectionU... Open
is related to SERVER-82926 Unexpected CollectionUUIDMismatch Closed
Assigned Teams:
Catalog and Routing
Operating System: ALL
Sprint: Execution NAMR Team 2023-07-10, Sharding EMEA 2023-07-24, Sharding EMEA 2023-08-07, Sharding EMEA 2023-08-21, Sharding EMEA 2023-09-04, Sharding EMEA 2023-09-18, Sharding EMEA 2023-10-02, Sharding EMEA 2023-10-16, Sharding EMEA 2023-10-30, CAR Team 2023-11-13, CAR Team 2023-11-27, CAR Team 2023-12-11, CAR Team 2023-12-25, CAR Team 2024-01-08, CAR Team 2024-02-05
Participants:
Story Points: 2

 Description   

In a mongosync test run, mongod mistakenly reported a collectionUUIDMismatch error. The sequence of events was:

  • mongosync creates a collection, testDB.userWriteBlockColl
  • mongod successfully does so, and gives it the UUID 3ca88158-8e77-49fb-9fcd-1bff14d26f5f
  • mongosync runs the following command, with that UUID, and gets a collectionUUIDMismatch error

 

 {
  "aggregate": "userWriteBlockColl",
  "collectionUUID": { "$uuid": "3ca88158-8e77-49fb-9fcd-1bff14d26f5f" },
  "pipeline": [
    { "$listCatalog": {} },
    { "$addFields": { "collectionUUID": "$md.options.uuid" } },
    { "$addFields": { "ns": "$md.ns" } },
    { "$project": { "md.options.uuid": 0 } },
    { "$addFields": { "options": "$md.options" } }
  ],
  "cursor": {},
  "readConcern": {
    "afterClusterTime": {
      "$timestamp": { "t": 1682347099, "i": 21 }
    }
  },
}

 

The mongod returns this very confusing error, with the same UUID and the same collection name in both expected and actual collection:

{
    db:                 "testDB", 
    collectionUUID:     UUID("3ca88158-8e77-49fb-9fcd-1bff14d26f5f"), 
    expectedCollection: "userWriteBlockColl", 
    actualCollection:   "userWriteBlockColl" 
} 

 

I collected some of the relevant logs in this GitHub gist, but the full mongod logs are available from the Evergreen task page for the failed mongosync tests.



 Comments   
Comment by Jordi Olivares Provencio [ 01/Feb/24 ]

rohan.sharan@mongodb.com I can more or less confirm that if you were to use afterClusterTime to enforce causal consistency this issue would be fixed. Closing this as Won't Fix as there's nothing else on our end to solve.

Comment by Rohan Sharan [ 19/Jul/23 ]

Yeah actually apparently it uses read preference nearest by default on the source cluster, which is where SampleCollection is being run. It doesn't use causal consistency, and it never would be able to run source collection creation and the aggregation in the same session, because the source collection creation is not done by mongosync (mongosync doesn't write to the source cluster).

 

I created a ticket REP-2956 in mongosync to consider any of the following changes:

  • Leave it as is (we retry on actualCollection = expectedCollection 5 times sleeping 1s between retries) 
  • Audit reads on the source cluster and either:
    • Add an afterClusterTime to reads
    • Explicitly make the read preference primary or primary preferred.

 

Do the all of the 3 options mentioned above individually seem like they'll take care of the issue?

 

Also, despite this popping up because mongosync is reading from a secondary, isn't this incorrect server behavior?

Comment by Jordi Serra Torrens [ 19/Jul/23 ]

My reading of the latest logs linked in this comment is the same huayu.ouyang@mongodb.com concluded above. It appears that mongosync targeted an aggregation to a secondary shard node that was in the process of replicating the collection creation (possibly still hadn't, but I can't really tell from the logs), therefore it did not know about the expectedUUID so it threw CollectionUUIDMismatch.

// j1:cl0:s1:n0 replicates the collection creation
[j1:cl0:s1:n0] 22:06:25.390Z | 2023-07-12T22:06:25.389+00:00 I  STORAGE  20320   [ReplWriterWorker-1] "createCollection","attr":{"namespace":"test.regex9","uuidDisposition":"provided","uuid":{"uuid":{"$uuid":"2fc0c120-7ab8-4a0b-8cc9-10985cf67261"}},"options":{"uuid":{"$uuid":"2fc0c120-7ab8-4a0b-8cc9-10985cf67261"}}}
 
// mongos gets a CollectionUUIDMismatch error when trying to establish cursors on shard for an aggregation
[j1:cl0:s] 22:06:25.463Z | 2023-07-12T22:06:25.463+00:00 I  QUERY    4625501 [conn109] "Unable to establish remote cursors","attr":{"error":{"code":361,"codeName":"CollectionUUIDMismatch","errmsg":"Collection UUID does not match that specified","db":"test","collectionUUID":{"$uuid":"2fc0c120-7ab8-4a0b-8cc9-10985cf67261"},"expectedCollection":"regex9","actualCollection":"regex9"},"nRemotes":1}
[MultipleReplicatorFixture:j1:replicator1] 22:06:25.465Z {"level":"fatal","serverID":"79c97d01","mongosyncID":"shard-rs1","stack":[{"func":"(*Mongosync).SampleCollection","line":"465","source":"/data/mci/d1d8c51b07c3cbfab081b19a39a04e3b/src/github.com/10gen/mongosync/internal/mongosync/initialize_sharding.go"},{"func":"(*Mongosync).Presplit","line":"302","source":"/data/mci/d1d8c51b07c3cbfab081b19a39a04e3b/src/github.com/10gen/mongosync/internal/mongosync/initialize_sharding.go"},{"func":"(*Mongosync).ShardCollectionOnDestination","line":"113","source":"/data/mci/d1d8c51b07c3cbfab081b19a39a04e3b/src/github.com/10gen/mongosync/internal/mongosync/initialize_sharding.go"},{"func":"(*Mongosync).InitializeCollectionsAndIndexes","line":"236","source":"/data/mci/d1d8c51b07c3cbfab081b19a39a04e3b/src/github.com/10gen/mongosync/internal/mongosync/initialize_main.go"},{"func":"(*Mongosync).Replicate","line":"1299","source":"/data/mci/d1d8c51b07c3cbfab081b19a39a04e3b/src/github.com/10gen/mongosync/internal/mongosync/mongosync.go"},{"func":"(*Mongosync).launchReplicationThread.func1","line":"1557","source":"/data/mci/d1d8c51b07c3cbfab081b19a39a04e3b/src/github.com/10gen/mongosync/internal/mongosync/mongosync.go"},{"func":"goexit","line":"1594","source":"/opt/golang/go1.19/src/runtime/asm_amd64.s"}],"error":"encountered a problem in the cursor when trying to $sample and $bucketAuto aggregation for source namespace 'test.', UUID 2fc0c120-7ab8-4a0b-8cc9-10985cf67261.: got a collection UUID mismatch error but the actual collection name (regex9) matches the last used name (regex9) - giving up on retries","time":"2023-07-12T22:06:25.465882806Z","message":"Error during replication"}

rohan.sharan@mongodb.com Can you confirm whether mongosync's SampleCollection performs secondary reads? If so, does it use causal consistent sessions? Also, did the source collection creation happen on the same client/session as mongosync is running the aggregate or a different one? Otherwise we'd need mongosync to pass a causal consistency token that is inclusive of the collection creation so that later the aggregation can be guaranteed to see the effects of the collection creation.

Comment by Huayu Ouyang [ 07/Jul/23 ]

I have tried to reproduce this bug but have not been able to. Since this occurred only once back in April, it might be possible that changes to how AutoGetCollection and lock free reads work since then like https://github.com/10gen/mongo/commit/e7b145405e5e076ebe59354a34cb3a74a67e2c5e or https://github.com/10gen/mongo/commit/014850f5f9d0e2cd9490755e94fe7a17570f7a70 have also solved the issue. Additionally, SERVER-77685 was recently merged which also moves the collection uuid mismatch check later in AutoGetCollection constructors, after a consistent snapshot of the catalog is made.

Closing this as Cannot Reproduce, but if this reoccurs feel free to re-open or file a new ticket.

Comment by Huayu Ouyang [ 27/Jun/23 ]

From srcCluster-rs-27020.log (which is a secondary) it seems like we successfully create the userWriteBlock coll

{"t":{"$date":"2023-04-24T14:38:20.120+00:00"},"s":"I",  "c":"REPL",     "id":7360109, "ctx":"ReplBatcher","msg":"Processing DDL command oplog entry in OplogBatcher","attr":{"oplogEntry":{"oplogEntry":{"op":"c","ns":"testDB.$cmd","ui":{"$uuid":"3ca88158-8e77-49fb-9fcd-1bff14d26f5f"},"o":{"create":"userWriteBlockColl","idIndex":{"v":2,"key":{"_id":1},"name":"_id_"}},"ts":{"$timestamp":{"t":1682347100,"i":2}},"t":2,"v":2,"wall":{"$date":"2023-04-24T14:38:20.119Z"}}}}}
{"t":{"$date":"2023-04-24T14:38:20.120+00:00"},"s":"I",  "c":"REPL",     "id":7360110, "ctx":"ReplWriterWorker-0","msg":"Applying DDL command oplog entry","attr":{"oplogEntry":{"oplogEntry":{"op":"c","ns":"testDB.$cmd","ui":{"$uuid":"3ca88158-8e77-49fb-9fcd-1bff14d26f5f"},"o":{"create":"userWriteBlockColl","idIndex":{"v":2,"key":{"_id":1},"name":"_id_"}},"ts":{"$timestamp":{"t":1682347100,"i":2}},"t":2,"v":2,"wall":{"$date":"2023-04-24T14:38:20.119Z"}}},"oplogApplicationMode":"Secondary"}}
{"t":{"$date":"2023-04-24T14:38:20.120+00:00"},"s":"D1", "c":"STORAGE",  "id":20324,   "ctx":"ReplWriterWorker-0","msg":"create collection {namespace} {collectionOptions}","attr":{"namespace":"testDB.userWriteBlockColl","collectionOptions":{"uuid":{"$uuid":"3ca88158-8e77-49fb-9fcd-1bff14d26f5f"}}}}
{"t":{"$date":"2023-04-24T14:38:20.121+00:00"},"s":"I",  "c":"STORAGE",  "id":20320,   "ctx":"ReplWriterWorker-0","msg":"createCollection","attr":{"namespace":"testDB.userWriteBlockColl","uuidDisposition":"provided","uuid":{"uuid":{"$uuid":"3ca88158-8e77-49fb-9fcd-1bff14d26f5f"}},"options":{"uuid":{"$uuid":"3ca88158-8e77-49fb-9fcd-1bff14d26f5f"}}}}
{"t":{"$date":"2023-04-24T14:38:20.134+00:00"},"s":"D1", "c":"STORAGE",  "id":20280,   "ctx":"ReplWriterWorker-0","msg":"Registering collection","attr":{"namespace":"testDB.userWriteBlockColl","uuid":{"uuid":{"$uuid":"3ca88158-8e77-49fb-9fcd-1bff14d26f5f"}}}}
{"t":{"$date":"2023-04-24T14:38:20.134+00:00"},"s":"D1", "c":"STORAGE",  "id":5255601, "ctx":"ReplWriterWorker-0","msg":"Finished writing to the CollectionCatalog","attr":{"jobs":1}}
{"t":{"$date":"2023-04-24T14:38:20.134+00:00"},"s":"I",  "c":"INDEX",    "id":20345,   "ctx":"ReplWriterWorker-0","msg":"Index build: done building","attr":{"buildUUID":null,"collectionUUID":{"uuid":{"$uuid":"3ca88158-8e77-49fb-9fcd-1bff14d26f5f"}},"namespace":"testDB.userWriteBlockColl","index":"_id_","ident":"index-558--4346920690633467779","collectionIdent":"collection-557--4346920690633467779","commitTimestamp":{"$timestamp":{"t":1682347100,"i":2}}}}
{"t":{"$date":"2023-04-24T14:38:20.134+00:00"},"s":"D1", "c":"STORAGE",  "id":5255601, "ctx":"ReplWriterWorker-0","msg":"Finished writing to the CollectionCatalog","attr":{"jobs":1}}
{"t":{"$date":"2023-04-24T14:38:20.134+00:00"},"s":"I",  "c":"REPL",     "id":51801,   "ctx":"ReplWriterWorker-0","msg":"Applied op","attr":{"command":{"op":"c","ns":"testDB.$cmd","ui":{"$uuid":"3ca88158-8e77-49fb-9fcd-1bff14d26f5f"},"o":{"create":"userWriteBlockColl","idIndex":{"v":2,"key":{"_id":1},"name":"_id_"}},"ts":{"$timestamp":{"t":1682347100,"i":2}},"t":2,"v":2,"wall":{"$date":"2023-04-24T14:38:20.119Z"}},"durationMillis":14}}

Immediately afterwards we get this user assertion:

{"t":{"$date":"2023-04-24T14:38:20.134+00:00"},"s":"D1", "c":"ASSERT",   "id":23074,   "ctx":"conn503","msg":"User assertion","attr":{"error":"CollectionUUIDMismatch{ db: \"testDB\", collectionUUID: UUID(\"3ca88158-8e77-49fb-9fcd-1bff14d26f5f\"), expectedCollection: \"userWriteBlockColl\", actualCollection: \"userWriteBlockColl\" }: Collection UUID does not match that specified","file":"src/mongo/db/catalog/collection_uuid_mismatch.cpp","line":70}}

This comes from here.
A similar thing happened in SERVER-77685, but that was on sharded clusters, and this is on replica sets.

It seems like we're uasserting because the collection we get vs the UUID that is passed in don't have the same UUID, but then when we lookup the namespace of the UUID that is passed in, we DO get a namespace that is the same as the expected namespace.

On mongosync we do writes with majority write concern, but we're doing a read on the secondary right now, so it's possible the write didn't reach this secondary. However, we should be seeing a consistent view of the catalog throughout this operation, so when we lookup of the namespace of the passed in UUID, it should have not returned any namespace if the collection wasn't created yet.

I looked at the CollectionCatalog::lookupNSSByUUID function and it seems like it first does UncommittedCatalogUpdates::lookupCollection so I'm wondering if this might be getting the new collection that was created?

Talked to gregory.noma@mongodb.com offline and we noted that related tickets REP-832 and/or REP-2743 might solve this on the mongosync side but I will continue investigating why this is occurring on the server side.

Generated at Thu Feb 08 06:33:11 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.