[SERVER-57516] RWC defaults pollutes the logs with duplicate "Refreshed RWC defaults" messages Created: 08/Jun/21  Updated: 29/Oct/23  Resolved: 10/Jan/22

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

Type: Bug Priority: Major - P3
Reporter: Kaloian Manassiev Assignee: Vesselina Ratcheva (Inactive)
Resolution: Fixed Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Backports
Backwards Compatibility: Fully Compatible
Operating System: ALL
Backport Requested:
v5.0, v4.4
Sprint: Replication 2021-11-15, Replication 2021-11-29, Replication 2021-12-13, Replication 2021-12-27, Replication 2022-01-10
Participants:

 Description   

The RWC defaults subsystem pollutes the logs on MongoS with the following lines every 10 seconds:

{"t":{"$date":"2021-06-08T05:20:42.757+00:00"},"s":"I",  "c":"SHARDING", "id":20997,   "ctx":"Uptime-reporter","msg":"Refreshed RWC defaults","attr":{"newDefaults":{}}}
{"t":{"$date":"2021-06-08T05:20:52.772+00:00"},"s":"I",  "c":"SHARDING", "id":20997,   "ctx":"Uptime-reporter","msg":"Refreshed RWC defaults","attr":{"newDefaults":{}}}
...
kaloianm@kal-ubuntu1:~/Temp/Data/mtools$ grep 'Refreshed RWC' mongos.log | wc -l
3699

The logging should happen only when there is actually a change in the defaults rather than all the time.



 Comments   
Comment by Githook User [ 10/Jan/22 ]

Author:

{'name': 'Vesselina Ratcheva', 'email': 'vesselina.ratcheva@10gen.com', 'username': 'vessy-mongodb'}

Message: SERVER-57516 Eliminate redundant 'Refreshed RWC defaults' messages
Branch: master
https://github.com/mongodb/mongo/commit/32a1cab2757c53fd29c4d9909fa3b0f07ecfac03

Comment by Igor Solodovnikov [ 20/Jul/21 ]

This  message is logged from 'ReadWriteConcernDefaults::refreshIfNecessary' function under following condition:

if (!currentDefaultsHandle || !possibleNewDefaults->getUpdateOpTime() ||
        (possibleNewDefaults->getUpdateOpTime() > currentDefaultsHandle->getUpdateOpTime())) 

which is basically

if (X || Y || Z)
 
where
X: !currentDefaultsHandle
Y: !possibleNewDefaults->getUpdateOpTime()
Z: possibleNewDefaults->getUpdateOpTime() > currentDefaultsHandle->getUpdateOpTime()

in mongos X is always false so the condition is effectively

if (Y || Z)

Y is true on fresh sharded cluster - that is on the sharded cluster where `setDefaultRWConcern` command has not been called. After first `setDefaultRWConcern` call defaults are persisted in the CSRS and Y becomes false.

Thus there is a workaround to prevent excessive log messages: just do a `setDefaultRWConcern` call. For example if defaults are not necessary set them to empty values:

db.adminCommand({
  "setDefaultRWConcern" : 1,
  "defaultReadConcern" : {},
  "defaultWriteConcern" : {}
})

Unfortunately due to another bug condition Z is never true (both times are always equal) so log will not receive "Refreshed RWC defaults" message when defaults are really changed. And following line is not executed too:

setDefault(opCtx, std::move(*possibleNewDefaults));

But is seems defaults are updated somewhere else. 

Comment by Eric Sedor [ 12/Jul/21 ]

This line does add a lot of noise, particularly to mongos and config server logs. I'm preemptively requesting backport as far back as 4.4.

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