[SERVER-32459] mongos incorrectly assumed collection was unsharded Created: 26/Dec/17  Updated: 11/Jan/23  Resolved: 22/Jan/18

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

Type: Bug Priority: Critical - P2
Reporter: Sven Henderson Assignee: Randolph Tan
Resolution: Duplicate Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

Ubuntu 14.04


Issue Links:
Duplicate
duplicates SERVER-32198 Missing collection metadata on the sh... Closed
Related
is related to SERVER-22611 ChunkManager refresh can occasionally... Closed
Operating System: ALL
Steps To Reproduce:

Unknown.

Participants:

 Description   

We have a sharded collection with approximately 170k chunks (spread across 11 replica sets) that a single mongos process incorrectly assumed was unsharded. This caused all reads/writes from that mongos process for the collection to go to the primary RS resulting in data inconsistency/loss from the view of that mongos process and the rest of the mongos processes in our environment.

Dec 22 13:55:07 web28 mongos.27011[99921]: [conn915497] ChunkManager loading chunks for trello.collection_1 sequenceNumber: 6047 based on: (empty)
Dec 22 13:55:07 web28 mongos.27011[99921]: [conn927627] ChunkManager loading chunks for trello.collection_2 sequenceNumber: 6048 based on: 41884|1||521778b1ca72fc747e2a31a5
Dec 22 13:55:07 web28 mongos.27011[99921]: [conn927627] ChunkManager load took 109 ms and found version 41885|1||521778b1ca72fc747e2a31a5
Dec 22 13:55:08 web28 mongos.27011[99921]: [conn915497] inconsistent chunks found when reloading trello.collection_1, previous version was 141470|3571||521778afca72fc747e2a31a3, this should be rare
Dec 22 13:55:08 web28 mongos.27011[99921]: [conn915497] ChunkManager load failed after 1858 ms and will be retried up to 2 more times
Dec 22 13:55:08 web28 mongos.27011[99921]: [conn915497] ChunkManager loading chunks for trello.collection_1 sequenceNumber: 6047 based on: (empty)
Dec 22 13:55:09 web28 mongos.27011[99921]: [conn915497] got invalid chunk version 13976|1||521778afca72fc747e2a31a3 in document { _id: "trello.collection_1-idModel_ObjectId('545d1808cc454be8aed72d8b')date_new Date(1415387523080)", ns: "trello.collection_1", min: { idModel: ObjectId('545d1808cc454be8aed72d8b'), date: new Date(1415387523080) }, max: { idModel: ObjectId('545d182bc40615e260371473'), date: new Date(1415685077013) }, shard: "rs2", lastmod: Timestamp 13976000|1, lastmodEpoch: ObjectId('521778afca72fc747e2a31a3') } when trying to load differing chunks at version 0|0||000000000000000000000000
Dec 22 13:55:09 web28 mongos.27011[99921]: [conn915497] major change in chunk information found when reloading trello.collection_1, previous version was 0|0||000000000000000000000000
Dec 22 13:55:09 web28 mongos.27011[99921]: [conn915497] ChunkManager load took 872 ms and found version 0|0||000000000000000000000000
Dec 22 13:55:09 web28 mongos.27011[99921]: [conn915497] no chunks found for collection trello.collection_1, assuming unsharded
Dec 22 13:55:09 web28 mongos.27011[99921]: [conn915497] ChunkManager loading chunks for trello.collection_3 sequenceNumber: 6049 based on: (empty)
Dec 22 13:55:09 web28 mongos.27011[99921]: [conn915497] ChunkManager load took 1 ms and found version 93|0||56f2ce47fefe6d524c67bfe4
Dec 22 13:55:09 web28 mongos.27011[99921]: [conn915497] ChunkManager loading chunks for trello.collection_4 sequenceNumber: 6050 based on: (empty)
Dec 22 13:55:09 web28 mongos.27011[99921]: [conn915497] ChunkManager load took 0 ms and found version 25|6||5205a989629b64bf3e892fba
...

It is worth noting we were manually splitting large chunks for collection_1 in a script with the split admin command at the time. These are the relevant logs from the instance running the script.

Dec 22 13:54:55 admin1 mongos.27018[10455]: [conn1019044] splitting chunk [{ idModel: ObjectId('546234baf3603a0b88fa84b6'), date: new Date(1430908962051) },{ id
Model: ObjectId('546236b3560532670a785dae'), date: new Date(1445238746777) }) in collection trello.collection_1 on shard rs2
Dec 22 13:54:55 admin1 mongos.27018[10455]: [conn1019044] ChunkManager loading chunks for trello.collection_1 sequenceNumber: 7322 based on: 141470|3561||521778afca
72fc747e2a31a3
Dec 22 13:54:56 admin1 mongos.27018[10455]: [conn1019044] ChunkManager load took 453 ms and found version 141470|3563||521778afca72fc747e2a31a3
Dec 22 13:54:58 admin1 mongos.27018[10455]: [conn1019044] splitting chunk [{ idModel: ObjectId('546247903ff470605f91bdbe'), date: new Date(1444235259298) },{ id
Model: ObjectId('54624819f94e7792881237f9'), date: new Date(1418289843165) }) in collection trello.collection_1 on shard rs2
Dec 22 13:54:58 admin1 mongos.27018[10455]: [conn1019044] ChunkManager loading chunks for trello.collection_1 sequenceNumber: 7323 based on: 141470|3563||521778afca
72fc747e2a31a3
Dec 22 13:54:59 admin1 mongos.27018[10455]: [conn1019044] ChunkManager load took 466 ms and found version 141470|3565||521778afca72fc747e2a31a3
Dec 22 13:54:59 admin1 mongos.27018[10455]: [conn1019044] splitting chunk [{ idModel: ObjectId('54624bb26b3af67855b71e67'), date: new Date(1435336429738) },{ id
Model: ObjectId('54624f2cb0a0e4dd31604c91'), date: new Date(1361988839380) }) in collection trello.collection_1 on shard rs2
Dec 22 13:55:00 admin1 mongos.27018[10455]: [mongosMain] connection accepted from 127.0.0.1:45906 #1021778 (4 connections now open)
Dec 22 13:55:00 admin1 mongos.27018[10455]: [mongosMain] connection accepted from 127.0.0.1:45907 #1021779 (5 connections now open)
Dec 22 13:55:00 admin1 mongos.27018[10455]: [conn1019044] ChunkManager loading chunks for trello.collection_1 sequenceNumber: 7324 based on: 141470|3565||521778afca72fc747e2a31a3
Dec 22 13:55:00 admin1 mongos.27018[10455]: [conn1021778] end connection 127.0.0.1:45906 (4 connections now open)
Dec 22 13:55:00 admin1 mongos.27018[10455]: [conn1021779] end connection 127.0.0.1:45907 (3 connections now open)
Dec 22 13:55:00 admin1 mongos.27018[10455]: [conn1019044] ChunkManager load took 456 ms and found version 141470|3567||521778afca72fc747e2a31a3
Dec 22 13:55:01 admin1 mongos.27018[10455]: [conn1019044] splitting chunk [{ idModel: ObjectId('546251f294b5b390883cffc4'), date: new Date(1444319064779) },{ idModel: ObjectId('5462555272ca804e14f8d262'), date: new Date(1416054342508) }) in collection trello.collection_1 on shard rs2
Dec 22 13:55:02 admin1 mongos.27018[10455]: [conn1019044] ChunkManager loading chunks for trello.collection_1 sequenceNumber: 7325 based on: 141470|3567||521778afca72fc747e2a31a3
Dec 22 13:55:02 admin1 mongos.27018[10455]: [conn1019044] ChunkManager load took 455 ms and found version 141470|3569||521778afca72fc747e2a31a3
Dec 22 13:55:06 admin1 mongos.27018[10455]: [conn1019044] splitting chunk [{ idModel: ObjectId('5462771a6d6090d3aab69185'), date: new Date(1417582120683) },{ idModel: ObjectId('54627aa769c3cd28a24f65fd'), date: new Date(1415740158381) }) in collection trello.collection_1 on shard rs2
Dec 22 13:55:07 admin1 mongos.27018[10455]: [conn1019044] ChunkManager loading chunks for trello.collection_1 sequenceNumber: 7326 based on: 141470|3569||521778afca72fc747e2a31a3
Dec 22 13:55:07 admin1 mongos.27018[10455]: [conn1019044] ChunkManager load took 451 ms and found version 141470|3571||521778afca72fc747e2a31a3
Dec 22 13:55:10 admin1 mongos.27018[10455]: [mongosMain] connection accepted from 127.0.0.1:45915 #1021780 (4 connections now open)
Dec 22 13:55:10 admin1 mongos.27018[10455]: [mongosMain] connection accepted from 127.0.0.1:45916 #1021781 (5 connections now open)
Dec 22 13:55:10 admin1 mongos.27018[10455]: [conn1021780] end connection 127.0.0.1:45915 (4 connections now open)
Dec 22 13:55:10 admin1 mongos.27018[10455]: [conn1021781] end connection 127.0.0.1:45916 (3 connections now open)
Dec 22 13:55:10 admin1 mongos.27018[10455]: [conn1019044] splitting chunk [{ idModel: ObjectId('5462a50a66b3264817ddd377'), date: new Date(1389628810403) },{ idModel: ObjectId('5462ad9dba3d75d3ece4ca07'), date: new Date(1416019961869) }) in collection trello.collection_1 on shard rs40
Dec 22 13:55:11 admin1 mongos.27018[10455]: [conn1019044] ChunkManager loading chunks for trello.collection_1 sequenceNumber: 7327 based on: 141470|3571||521778afca72fc747e2a31a3
Dec 22 13:55:11 admin1 mongos.27018[10455]: [conn1019044] ChunkManager load took 452 ms and found version 141470|3573||521778afca72fc747e2a31a3



 Comments   
Comment by Randolph Tan [ 22/Jan/18 ]

After looking at the primary shard logs again, I believe you are experiencing SERVER-32198. The logs shows that the shard thinks that the collection is 'unsharded'. This is because it currently does not differentiate between uninitialized/unknown version and zero version. In addition, this shard doesn't own any chunks for this collection, so no other request would send a non-zero version request to this shard and force it to refresh. The SERVER-22611 fix in v3.4 should make this issue harder to manifest until we fully fix SERVER-32198.

Comment by Sven Henderson [ 17/Jan/18 ]

Hi Randolph,

We did not issue any queries through the mongos that assumed the collection was unsharded so I cannot completely confirm what it was doing.

However, from the point of view of a working mongos process the data that was being inserted into the unsharded collection on the primary RS (presumably by the confused mongos) was not visible. Those ~20k documents were "missing" from the collection. To recover those lost documents we ran flushRouterConfig on the confused mongos (this stopped docs from being inserted), dumped the 20k docs directly from the mongod instance in the primary RS, and then restored those docs back into a working mongos.

Comment by Randolph Tan [ 17/Jan/18 ]

Hi,

May I ask whether you saw inconsistencies or was just suspecting that there might be inconsistencies? The reason why I'm asking is because the "inconsistent chunk" logs just means that either the config server metadata was somewhat corrupted or the mongos screwed up. If it's the former, you will keep on hitting this error indefinitely. If it's the latter, mongos will simply clear the cache and reload again. The latter will not cause any data loss/inconsistency but it can cause queries to be delayed because it will need to load the full metadata for that collection again instead of doing it incrementally. We fixed an issue (SERVER-22611) that can cause mongos to have "inconsistent chunk" in v3.4.

Comment by Sven Henderson [ 17/Jan/18 ]

Hi Randolph,

Almost all of our queries use the default read/write concern and read preference with a very small number reading only from the secondaries. For the collection in question, I can really only confirm that in the hour that it was assumed to be unsharded, mongos inserted ~20k docs into the collection on the primary RS.

Comment by Randolph Tan [ 03/Jan/18 ]

Hi,

What kind of reads and writes are you using? Most of the reads and writes are versioned, so even if the mongos was wrong, the shard will return a stale version error and cause the mongos to refresh the routing table (unless the shard just restarted or just became primary recently - SERVER-24960). Some exceptions to this behavior are updates/removes with multi = true and secondary ok reads. v3.6 introduced safe secondary reads which makes reading from a secondary properly versioned.

Comment by Sven Henderson [ 26/Dec/17 ]

Hi Kelsey,

Your quick response is much appreciated. To answer your questions...

  1. We are using mirrored (SCCC) config servers
  2. I uploaded the logs for each service for the day affected
  3. I uploaded the compressed config database dump

Let me know if I can provide any additional information.

Sven

Comment by Kelsey Schubert [ 26/Dec/17 ]

Hi sven@trello.com,

Thank you for reporting this issue. So we can better understand what occurred, would you please provide some additional information?

  1. Are you running with config servers as a replica set or with mirrored (SCCC) config servers?
  2. Would you please provide the complete logs from the following processes?
    1. the primary or first config server
    2. affected mongos
    3. mongos running the the the split commands
    4. the primary of the primary replicaset that began receiving writes/reads from the affected mongos
  3. Would you please provide a mongodump of the config database?

    mongodump --host MONGOS_HOST --port MONGOS_PORT -d config -o configdump
    tar czf configdump.tgz configdump
    

I've created a secure upload portal for you to use to provide these files. Files uploaded to this portal are only visible to MongoDB employees investigating this issue and are routinely deleted after some time.

Thank you again,
Kelsey

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