I set the access network, and replica level logs to verbose, and I do see “Error while waiting for hello response” where the time limit was exceeded in the replica log. I’m assuming that just means it timed out and nothing changed in the topology though.
Would adjusting timeout settings from the default help here, or is this normal behavior?
I tried doubling the values a few times, then reverted to the default values in the replication cfg as this seems unrelated to the reauth messages and made no difference on the hello messages.
I also see good information in level-3 ACCESS logs. It appears to behave as though it has no user/pass (empty strings for both fields), and it falls back to the system default and is able to proceed? The nodes are obviously not authenticating properly. Did I miss some step in setting up the nodes?
{"t":{"$date":"2023-02-27T21:25:25.184+00:00"},"s":"D3", "c":"ACCESS", "id":5286300, "ctx":"conn33","msg":"Starting authentication step","attr":{"step":"SaslSupportedMechanisms"}}
{"t":{"$date":"2023-02-27T21:25:25.184+00:00"},"s":"D3", "c":"ACCESS", "id":5859101, "ctx":"conn33","msg":"Set user name for session","attr":{"userName":{"user":"__system","db":"local"},"oldName":{"user":"","db":""}}}
{"t":{"$date":"2023-02-27T21:25:25.184+00:00"},"s":"D3", "c":"ACCESS", "id":5286301, "ctx":"conn33","msg":"Finished authentication step","attr":{"step":"SaslSupportedMechanisms"}}
{"t":{"$date":"2023-02-27T21:25:25.185+00:00"},"s":"D3", "c":"ACCESS", "id":5286300, "ctx":"conn32","msg":"Starting authentication step","attr":{"step":"SaslSupportedMechanisms"}}
{"t":{"$date":"2023-02-27T21:25:25.185+00:00"},"s":"D3", "c":"ACCESS", "id":5859101, "ctx":"conn32","msg":"Set user name for session","attr":{"userName":{"user":"__system","db":"local"},"oldName":{"user":"","db":""}}}
{"t":{"$date":"2023-02-27T21:25:25.185+00:00"},"s":"D3", "c":"ACCESS", "id":5286301, "ctx":"conn32","msg":"Finished authentication step","attr":{"step":"SaslSupportedMechanisms"}}
{"t":{"$date":"2023-02-27T21:25:25.191+00:00"},"s":"D3", "c":"ACCESS", "id":5286300, "ctx":"conn33","msg":"Starting authentication step","attr":{"step":"SaslStart"}}
{"t":{"$date":"2023-02-27T21:25:25.191+00:00"},"s":"D3", "c":"ACCESS", "id":5286203, "ctx":"conn33","msg":"Updating user name for session","attr":{"userName":{"user":"","db":"local"},"oldName":{"user":"","db":""}}}
{"t":{"$date":"2023-02-27T21:25:25.191+00:00"},"s":"D3", "c":"ACCESS", "id":5286200, "ctx":"conn33","msg":"Setting mechanism name","attr":{"mechanism":"SCRAM-SHA-256"}}
{"t":{"$date":"2023-02-27T21:25:25.191+00:00"},"s":"D3", "c":"ACCESS", "id":5286304, "ctx":"conn33","msg":"Determined mechanism for authentication"}
{"t":{"$date":"2023-02-27T21:25:25.191+00:00"},"s":"D3", "c":"ACCESS", "id":5286301, "ctx":"conn33","msg":"Finished authentication step","attr":{"step":"SaslStart"}}
{"t":{"$date":"2023-02-27T21:25:25.191+00:00"},"s":"D3", "c":"ACCESS", "id":5286300, "ctx":"conn32","msg":"Starting authentication step","attr":{"step":"SaslStart"}}
{"t":{"$date":"2023-02-27T21:25:25.191+00:00"},"s":"D3", "c":"ACCESS", "id":5286203, "ctx":"conn32","msg":"Updating user name for session","attr":{"userName":{"user":"","db":"local"},"oldName":{"user":"","db":""}}}
{"t":{"$date":"2023-02-27T21:25:25.191+00:00"},"s":"D3", "c":"ACCESS", "id":5286200, "ctx":"conn32","msg":"Setting mechanism name","attr":{"mechanism":"SCRAM-SHA-256"}}
{"t":{"$date":"2023-02-27T21:25:25.191+00:00"},"s":"D3", "c":"ACCESS", "id":5286304, "ctx":"conn32","msg":"Determined mechanism for authentication"}
{"t":{"$date":"2023-02-27T21:25:25.191+00:00"},"s":"D3", "c":"ACCESS", "id":5286301, "ctx":"conn32","msg":"Finished authentication step","attr":{"step":"SaslStart"}}
{"t":{"$date":"2023-02-27T21:25:25.196+00:00"},"s":"D3", "c":"ACCESS", "id":5286300, "ctx":"conn33","msg":"Starting authentication step","attr":{"step":"SaslContinue"}}
{"t":{"$date":"2023-02-27T21:25:25.196+00:00"},"s":"W", "c":"ACCESS", "id":5626700, "ctx":"conn33","msg":"Client has attempted to reauthenticate as a single user","attr":{"user":{"user":"__system","db":"local"}}}
{"t":{"$date":"2023-02-27T21:25:25.196+00:00"},"s":"I", "c":"ACCESS", "id":20250, "ctx":"conn33","msg":"Authentication succeeded","attr":{"mechanism":"SCRAM-SHA-256","speculative":false,"principalName":"__system","authenticationDatabase":"local","remote":"10.2.1.4:56091","extraInfo":{}}}
{"t":{"$date":"2023-02-27T21:25:25.196+00:00"},"s":"D3", "c":"ACCESS", "id":5286305, "ctx":"conn33","msg":"Marking as cluster member"}