"Client has attempted to reauthenticate as a single user" messages from replica set members filling our logs

I’m running MongoDB 5.0.6 in our newly setup staging environment as a 3 member replica set.

Comparing to our ancient production replica set running a much older version of MongoDB, we noticed our logs keep filling with entries like these:

Logs

{"t":{"$date":"2022-03-30T13:42:57.825+00:00"},"s":"W",  "c":"ACCESS",   "id":5626700, "ctx":"conn20","msg":"Client has attempted to reauthenticate as a single user","attr":{"user":{"user":"__system","db":"local"}}}
{"t":{"$date":"2022-03-30T13:42:57.825+00:00"},"s":"I",  "c":"ACCESS",   "id":20250,   "ctx":"conn20","msg":"Authentication succeeded","attr":{"mechanism":"SCRAM-SHA-256","speculative":false,"principalName":"__system","authenticationDatabase":"local","remote":"10.0.1.3:37808","extraInfo":{}}}
{"t":{"$date":"2022-03-30T13:42:57.825+00:00"},"s":"W",  "c":"ACCESS",   "id":5626700, "ctx":"conn21","msg":"Client has attempted to reauthenticate as a single user","attr":{"user":{"user":"__system","db":"local"}}}
{"t":{"$date":"2022-03-30T13:42:57.825+00:00"},"s":"I",  "c":"ACCESS",   "id":20250,   "ctx":"conn21","msg":"Authentication succeeded","attr":{"mechanism":"SCRAM-SHA-256","speculative":false,"principalName":"__system","authenticationDatabase":"local","remote":"10.0.1.3:37810","extraInfo":{}}}
{"t":{"$date":"2022-03-30T13:42:57.902+00:00"},"s":"W",  "c":"ACCESS",   "id":5626700, "ctx":"conn20","msg":"Client has attempted to reauthenticate as a single user","attr":{"user":{"user":"__system","db":"local"}}}
ncipalName":"__system","authenticationDatabase":"local","remote":"10.0.1.3:37808","extraInfo":{}}}
{"t":{"$date":"2022-03-30T13:42:57.979+00:00"},"s":"W",  "c":"ACCESS",   "id":5626700, "ctx":"conn20","msg":"Client has attempted to reauthenticate as a single user","attr":{"user":{"user":"__system","db":"local"}}}
{"t":{"$date":"2022-03-30T13:42:57.979+00:00"},"s":"I",  "c":"ACCESS",   "id":20250,   "ctx":"conn20","msg":"Authentication succeeded","attr":{"mechanism":"SCRAM-SHA-256","speculative":false,"principalName":"__system","authenticationDatabase":"local","remote":"10.0.1.3:37808","extraInfo":{}}}
{"t":{"$date":"2022-03-30T13:42:58.056+00:00"},"s":"W",  "c":"ACCESS",   "id":5626700, "ctx":"conn20","msg":"Client has attempted to reauthenticate as a single user","attr":{"user":{"user":"__system","db":"local"}}}
{"t":{"$date":"2022-03-30T13:42:58.056+00:00"},"s":"I",  "c":"ACCESS",   "id":20250,   "ctx":"conn20","msg":"Authentication succeeded","attr":{"mechanism":"SCRAM-SHA-256","speculative":false,"principalName":"__system","authenticationDatabase":"local","remote":"10.0.1.3:37808","extraInfo":{}}}
{"t":{"$date":"2022-03-30T13:42:58.382+00:00"},"s":"W",  "c":"ACCESS",   "id":5626700, "ctx":"conn23","msg":"Client has attempted to reauthenticate as a single user","attr":{"user":{"user":"__system","db":"local"}}}
{"t":{"$date":"2022-03-30T13:42:58.382+00:00"},"s":"W",  "c":"ACCESS",   "id":5626700, "ctx":"conn22","msg":"Client has attempted to reauthenticate as a single user","attr":{"user":{"user":"__system","db":"local"}}}
{"t":{"$date":"2022-03-30T13:42:58.382+00:00"},"s":"I",  "c":"ACCESS",   "id":20250,   "ctx":"conn22","msg":"Authentication succeeded","attr":{"mechanism":"SCRAM-SHA-256","speculative":false,"principalName":"__system","authenticationDatabase":"local","remote":"10.0.1.2:46998","extraInfo":{}}}
{"t":{"$date":"2022-03-30T13:42:58.382+00:00"},"s":"I",  "c":"ACCESS",   "id":20250,   "ctx":"conn23","msg":"Authentication succeeded","attr":{"mechanism":"SCRAM-SHA-256","speculative":false,"principalName":"__system","authenticationDatabase":"local","remote":"10.0.1.2:47000","extraInfo":{}}}
{"t":{"$date":"2022-03-30T13:42:58.454+00:00"},"s":"W",  "c":"ACCESS",   "id":5626700, "ctx":"conn23","msg":"Client has attempted to reauthenticate as a single user","attr":{"user":{"user":"__system","db":"local"}}}
{"t":{"$date":"2022-03-30T13:42:58.455+00:00"},"s":"I",  "c":"ACCESS",   "id":20250,   "ctx":"conn23","msg":"Authentication succeeded","attr":{"mechanism":"SCRAM-SHA-256","speculative":false,"principalName":"__system","authenticationDatabase":"local","remote":"10.0.1.2:47000","extraInfo":{}}}
{"t":{"$date":"2022-03-30T13:42:58.527+00:00"},"s":"W",  "c":"ACCESS",   "id":5626700, "ctx":"conn23","msg":"Client has attempted to reauthenticate as a single user","attr":{"user":{"user":"__system","db":"local"}}}
{"t":{"$date":"2022-03-30T13:42:58.527+00:00"},"s":"I",  "c":"ACCESS",   "id":20250,   "ctx":"conn23","msg":"Authentication succeeded","attr":{"mechanism":"SCRAM-SHA-256","speculative":false,"principalName":"__system","authenticationDatabase":"local","remote":"10.0.1.2:47000","extraInfo":{}}}
{"t":{"$date":"2022-03-30T13:42:58.600+00:00"},"s":"W",  "c":"ACCESS",   "id":5626700, "ctx":"conn23","msg":"Client has attempted to reauthenticate as a single user","attr":{"user":{"user":"__system","db":"local"}}}
{"t":{"$date":"2022-03-30T13:42:58.600+00:00"},"s":"I",  "c":"ACCESS",   "id":20250,   "ctx":"conn23","msg":"Authentication succeeded","attr":{"mechanism":"SCRAM-SHA-256","speculative":false,"principalName":"__system","authenticationDatabase":"local","remote":"10.0.1.2:47000","extraInfo":{}}}

Trying to Google for any explanation yields zero results and it seems I’m the only person in this universe with this problem.

Any help in understanding the root cause is much appreciated and I will gladly attempt to provide any information about our setup.

I noticed these log messages appear at exactly 5 min intervals :thinking:

Anyone? This seems odd, since my setup was rather simple - just following the replica set deployment guide and applying some of the “production notes” optimisations.

I switched the replica set from keyfile auth to clusterAuthMode x509 and the errors disappeared :person_shrugging: