[SERVER-50241] PeriodicShardedIndexConsistencyChecker should skip dropped collections Created: 11/Aug/20  Updated: 29/Oct/23  Resolved: 21/Oct/20

Status: Closed
Project: Core Server
Component/s: Logging, Replication, Sharding
Affects Version/s: 4.2.8, 4.4.0
Fix Version/s: 4.9.0, 4.2.18, 4.4.10

Type: Bug Priority: Minor - P4
Reporter: Kin Wai Cheung Assignee: Jaume Moragues (Inactive)
Resolution: Fixed Votes: 0
Labels: sharding-wfbf-day
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Attachments: File mongod.log-202008011.gz    
Issue Links:
Backports
Backwards Compatibility: Fully Compatible
Operating System: ALL
Backport Requested:
v4.4, v4.2
Steps To Reproduce:

*no* further _formatting_ is done here

Sprint: Sharding 2020-10-19, Sharding 2020-11-02
Participants:

 Description   

The consistency checker performs checks even on dropped collections (this is because dropped collections still appear in config.collections with dropped: true). This can lead to noisy NamespaceNotFound in logs on the config server.

original description:

 

cluster topology:

sharded cluster with 1 config node (primary replica set) , 2 different databearing nodes  (primary replica set) and 1 router.

 

We upgraded our mongo cluster  from 4.0.9 to 4.2.8 and a couple of days later to 4.4.0

In the config logs we see every 10 minutes like below (attached mongod log of config).

The databases mentioned are supposed to be dropped from the data bearing nodes.

I'm finding  entries in config.collections (config) or  config.cached.collections (data bearing nodes) that reference to already dropped db's.

Also initiated flushrouterconfig but that didn't help.

4.2.8

2020-08-09T03:11:01.807+0200 I SHARDING [PeriodicShardedIndexConsistencyChecker] Checking consistency of sharded collection indexes across the cluster
2020-08-09T03:11:01.824+0200 I SH_REFR [ConfigServerCatalogCacheLoader-139] Refresh for database acc took 0 ms and failed :: caused by :: NamespaceNotFound: database acc not found
2020-08-09T03:11:01.828+0200 I SH_REFR [ConfigServerCatalogCacheLoader-139] Refresh for database lukes-test took 0 ms and failed :: caused by :: NamespaceNotFound: database lukes-test not found
2020-08-09T03:11:01.830+0200 I SH_REFR [ConfigServerCatalogCacheLoader-139] Refresh for database ctr-integration-tests_1492084538520 took 0 ms and failed :: caused by :: NamespaceNotFound: database ctr-integration-tests_1492084538520 not found
2020-08-09T03:11:01.831+0200 I SH_REFR [ConfigServerCatalogCacheLoader-139] Refresh for database ctr-integration-tests_1492085358785 took 0 ms and failed :: caused by :: NamespaceNotFound: database ctr-integration-tests_1492085358785 not found
2020-08-09T03:11:01.831+0200 I SH_REFR [ConfigServerCatalogCacheLoader-139] Refresh for database ctr-integration-tests_1492093702966 took 0 ms and failed :: caused by :: NamespaceNotFound: database ctr-integration-tests_1492093702966 not found
2020-08-09T03:11:01.831+0200 I SH_REFR [ConfigServerCatalogCacheLoader-139] Refresh for database ctr-integration-tests_1492094907720 took 0 ms and failed :: caused by :: NamespaceNotFound: database ctr-integration-tests_1492094907720 not found
.
.
.
2020-08-09T03:11:02.874+0200 I  SH_REFR  [ConfigServerCatalogCacheLoader-139] Refresh for database ctr-integration-tests_2020-08-07-00-00-46 took 0 ms and failed :: caused by :: NamespaceNotFound: database ctr-integration-tests_2020-08-07-00-00-46 not found
2020-08-09T03:11:02.874+0200 I  SH_REFR  [ConfigServerCatalogCacheLoader-139] Refresh for database ctr-integration-tests_2020-08-07-00-02-08 took 0 ms and failed :: caused by :: NamespaceNotFound: database ctr-integration-tests_2020-08-07-00-02-08 not found
2020-08-09T03:11:02.874+0200 I  SH_REFR  [ConfigServerCatalogCacheLoader-139] Refresh for database ctr-integration-tests_2020-08-07-00-02-08 took 0 ms and failed :: caused by :: NamespaceNotFound: database ctr-integration-tests_2020-08-07-00-02-08 not found
2020-08-09T03:11:02.874+0200 I  SH_REFR  [ConfigServerCatalogCacheLoader-139] Refresh for database ctr-integration-tests_2020-08-07-00-02-08 took 0 ms and failed :: caused by :: NamespaceNotFound: database ctr-integration-tests_2020-08-07-00-02-08 not found
2020-08-09T03:11:02.875+0200 I  SH_REFR  [ConfigServerCatalogCacheLoader-139] Refresh for database ctr-integration-tests_2020-08-07-00-04-07 took 0 ms and failed :: caused by :: NamespaceNotFound: database ctr-integration-tests_2020-08-07-00-04-07 not found
2020-08-09T03:11:02.875+0200 I  SH_REFR  [ConfigServerCatalogCacheLoader-139] Refresh for database ctr-integration-tests_2020-08-07-00-04-07 took 0 ms and failed :: caused by :: NamespaceNotFound: database ctr-integration-tests_2020-08-07-00-04-07 not found
2020-08-09T03:11:02.875+0200 I  SH_REFR  [ConfigServerCatalogCacheLoader-139] Refresh for database ctr-integration-tests_2020-08-07-00-04-07 took 0 ms and failed :: caused by :: NamespaceNotFound: database ctr-integration-tests_2020-08-07-00-04-07 not found
2020-08-09T03:11:02.875+0200 I  SHARDING [PeriodicShardedIndexConsistencyChecker] Found 0 collections with inconsistent indexes

 

 also seen after an upgrade to 4.4.0 but there is not end message from the Checker that 0 collections are found. 

The sharded cluster was succesfully upgraded around 10:40 CEST

faced an issue and use the workaround as mentioned in https://jira.mongodb.org/browse/SERVER-50137

 

{"t":{"$date":"2020-08-11T03:00:23.147+02:00"},"s":"I",  "c":"SHARDING", "id":22049,   "ctx":"PeriodicShardedIndexConsistencyChecker","msg":"Checking consistency of sharded collection indexes across the cluster"}
{"t":{"$date":"2020-08-11T03:00:23.163+02:00"},"s":"I",  "c":"SH_REFR",  "id":24100,   "ctx":"ConfigServerCatalogCacheLoader-47","msg":"Error refreshing cached database entry","attr":{"db":"acc","durationMillis":0,"error":"NamespaceNotFound: database acc not found"}}
{"t":{"$date":"2020-08-11T03:00:23.163+02:00"},"s":"I",  "c":"SH_REFR",  "id":24100,   "ctx":"ConfigServerCatalogCacheLoader-47","msg":"Error refreshing cached database entry","attr":{"db":"at-dev","durationMillis":0,"error":"NamespaceNotFound: database at-dev not found"}}
{"t":{"$date":"2020-08-11T03:00:23.166+02:00"},"s":"I",  "c":"SH_REFR",  "id":24100,   "ctx":"ConfigServerCatalogCacheLoader-47","msg":"Error refreshing cached database entry","attr":{"db":"ctr-test","durationMillis":0,"error":"NamespaceNotFound: database ctr-test not found"}}
{"t":{"$date":"2020-08-11T03:00:23.167+02:00"},"s":"I",  "c":"SH_REFR",  "id":24100,   "ctx":"ConfigServerCatalogCacheLoader-47","msg":"Error refreshing cached database entry","attr":{"db":"ctr-integration-tests_1492084538520","durationMillis":0,"error":"NamespaceNotFound: database ctr-integration-tests_1492084538520 not found"}}
{"t":{"$date":"2020-08-11T03:00:23.167+02:00"},"s":"I",  "c":"SH_REFR",  "id":24100,   "ctx":"ConfigServerCatalogCacheLoader-47","msg":"Error refreshing cached database entry","attr":{"db":"ctr-integration-tests_1492085358785","durationMillis":0,"error":"NamespaceNotFound: database ctr-integration-tests_1492085358785 not found"}}
 
.
.
.
{"t":{"$date":"2020-08-11T03:00:24.234+02:00"},"s":"I", "c":"SH_REFR", "id":24100, "ctx":"ConfigServerCatalogCacheLoader-47","msg":"Error refreshing cached database entry","attr":{"db":"ctr-integration-tests_2020-08-07-00-04-07","durationMillis":0,"error":"NamespaceNotFound: database ctr-integration-tests_2020-08-07-00-04-07 not found"}}
{"t":{"$date":"2020-08-11T03:00:24.234+02:00"},"s":"I", "c":"SH_REFR", "id":24100, "ctx":"ConfigServerCatalogCacheLoader-47","msg":"Error refreshing cached database entry","attr":{"db":"ctr-integration-tests_2020-08-07-00-04-07","durationMillis":0,"error":"NamespaceNotFound: database ctr-integration-tests_2020-08-07-00-04-07 not found"}}
{"t":{"$date":"2020-08-11T03:00:24.234+02:00"},"s":"I", "c":"SH_REFR", "id":24100, "ctx":"ConfigServerCatalogCacheLoader-47","msg":"Error refreshing cached database entry","attr":{"db":"ctr-integration-tests_2020-08-07-00-04-07","durationMillis":0,"error":"NamespaceNotFound: database ctr-integration-tests_2020-08-07-00-04-07 not found"}}
{"t":{"$date":"2020-08-11T03:00:24.235+02:00"},"s":"I", "c":"SH_REFR", "id":24100, "ctx":"ConfigServerCatalogCacheLoader-47","msg":"Error refreshing cached database entry","attr":{"db":"ctr-integration-tests_2020-08-10-11-50-03","durationMillis":0,"error":"NamespaceNotFound: database ctr-integration-tests_2020-08-10-11-50-03 not found"}}
{"t":{"$date":"2020-08-11T03:00:24.235+02:00"},"s":"I", "c":"SH_REFR", "id":24100, "ctx":"ConfigServerCatalogCacheLoader-47","msg":"Error refreshing cached database entry","attr":{"db":"ctr-integration-tests_2020-08-10-11-50-03","durationMillis":0,"error":"NamespaceNotFound: database ctr-integration-tests_2020-08-10-11-50-03 not found"}}
{"t":{"$date":"2020-08-11T03:00:24.235+02:00"},"s":"I", "c":"SH_REFR", "id":24100, "ctx":"ConfigServerCatalogCacheLoader-47","msg":"Error refreshing cached database entry","attr":{"db":"ctr-integration-tests_2020-08-10-11-50-03","durationMillis":0,"error":"NamespaceNotFound: database ctr-integration-tests_2020-08-10-11-50-03 not found"}}
{"t":{"$date":"2020-08-11T03:00:24.235+02:00"},"s":"I", "c":"SH_REFR", "id":24100, "ctx":"ConfigServerCatalogCacheLoader-47","msg":"Error refreshing cached database entry","attr":{"db":"ctr-integration-tests_2020-08-11-00-01-39","durationMillis":0,"error":"NamespaceNotFound: database ctr-integration-tests_2020-08-11-00-01-39 not found"}}
{"t":{"$date":"2020-08-11T03:00:24.235+02:00"},"s":"I", "c":"SH_REFR", "id":24100, "ctx":"ConfigServerCatalogCacheLoader-47","msg":"Error refreshing cached database entry","attr":{"db":"ctr-integration-tests_2020-08-11-00-01-39","durationMillis":0,"error":"NamespaceNotFound: database ctr-integration-tests_2020-08-11-00-01-39 not found"}}
{"t":{"$date":"2020-08-11T03:00:24.236+02:00"},"s":"I", "c":"SH_REFR", "id":24100, "ctx":"ConfigServerCatalogCacheLoader-47","msg":"Error refreshing cached database entry","attr":{"db":"ctr-integration-tests_2020-08-11-00-01-39","durationMillis":0,"error":"NamespaceNotFound: database ctr-integration-tests_2020-08-11-00-01-39 not found"}}
{"t":{"$date":"2020-08-11T03:00:24.292+02:00"},"s":"I", "c":"SHARDING", "id":20997, "ctx":"conn4315","msg":"Refreshed RWC defaults","attr":{"newDefaults":{}}}



 Comments   
Comment by Githook User [ 05/Oct/21 ]

Author:

{'name': 'jaume.moragues', 'email': 'jaume.moragues@mongodb.com'}

Message: SERVER-50241 PeriodicShardedIndexConsistencyChecker should skip dropped collections

(cherry picked from commit d78140ecb9ee4487d5442082fa46717a1ea3e0b1)
Branch: v4.2
https://github.com/mongodb/mongo/commit/19e18e0b0e4afa0fa807115b83a377dc3a68c505

Comment by Githook User [ 05/Oct/21 ]

Author:

{'name': 'jaume.moragues', 'email': 'jaume.moragues@mongodb.com'}

Message: SERVER-50241 PeriodicShardedIndexConsistencyChecker should skip dropped collections

(cherry picked from commit d78140ecb9ee4487d5442082fa46717a1ea3e0b1)
Branch: v4.4
https://github.com/mongodb/mongo/commit/3aae8cc5bc9d3d6b4476aebc63b67138375a81af

Comment by Githook User [ 21/Oct/20 ]

Author:

{'name': 'jaume.moragues', 'email': 'jaume.moragues@mongodb.com'}

Message: SERVER-50241 PeriodicShardedIndexConsistencyChecker should skip dropped collections
Branch: master
https://github.com/mongodb/mongo/commit/d78140ecb9ee4487d5442082fa46717a1ea3e0b1

Comment by Randolph Tan [ 17/Sep/20 ]

The messages in this case are harmless. The issue here is that the periodic index checker is trying to perform checks on collections that were already dropped instead of just skipping them.

Comment by Kin Wai Cheung [ 14/Sep/20 ]

currently everytime our developement create and drop a database (with collections in it) it will add an extra line in the log.

Will this cause a problem in the long run?

Generated at Thu Feb 08 05:22:09 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.