|
Hypothesis:
This is related to performing speculative authentication against an arbiter.
Observations:
Using a patch with verbose test logging, the test logs the an ismaster reply with "ok":0 and the message "aborting keys cache refresh because node is shutting down":
2020/06/07 21:33:01.0594: [22473]: DEBUG: monitor: [localhost:27019] error in server reply: aborting keys cache refresh because node is shutting down
|
localhost:27019 is an arbiter. The full server logs are attached as mongod-arbiter-27019.log with some annotations starting with "#NOTE".
This has only been observed on 4.4+ replica set tests with authentication.
Similar to PHPC-1634, the arbiter's logs show many "User not Found" errors and other errors related to auth.
Here are the logs for one connection.
{"t":{"$date":"2020-06-07T21:32:15.731+00:00"},"s":"I", "c":"NETWORK", "id":51800, "ctx":"conn18","msg":"client metadata","attr":{"remote":"127.0.0.1:38911","client":"conn18","doc":{"driver":{"name":"mongoc","version":"1.17.0-pre"},"os":{"type":"Linux","name":"Ubuntu","version":"16.04","architecture":"x86_64"},"platform":"cfg=0x02a15620c9 posix=200809 stdc=201112 CC=clang 3.8.0 (tags/RELEASE_380/final)"}}}
|
{"t":{"$date":"2020-06-07T21:32:15.731+00:00"},"s":"D1", "c":"EXECUTOR", "id":23104, "ctx":"AuthorizationManager-1","msg":"Starting thread","attr":{"threadName":"AuthorizationManager-1","poolName":"AuthorizationManager"}}
|
{"t":{"$date":"2020-06-07T21:32:15.731+00:00"},"s":"D1", "c":"ACCESS", "id":20238, "ctx":"AuthorizationManager-1","msg":"Getting user record","attr":{"user":"bob@admin"}}
|
{"t":{"$date":"2020-06-07T21:32:15.731+00:00"},"s":"D1", "c":"-", "id":23074, "ctx":"AuthorizationManager-1","msg":"User assertion","attr":{"error":"UserNotFound: Could not find user \"bob\" for db \"admin\"","file":"src/mongo/db/auth/authorization_manager_impl.cpp","line":713}}
|
{"t":{"$date":"2020-06-07T21:32:15.731+00:00"},"s":"D1", "c":"-", "id":23074, "ctx":"conn18","msg":"User assertion","attr":{"error":"UserNotFound: Could not find user \"bob\" for db \"admin\"","file":"src/mongo/util/future_impl.h","line":674}}
|
{"t":{"$date":"2020-06-07T21:32:15.731+00:00"},"s":"I", "c":"ACCESS", "id":20251, "ctx":"conn18","msg":"Supported SASL mechanisms requested for unknown user","attr":{"user":"bob@admin"}}
|
{"t":{"$date":"2020-06-07T21:32:15.731+00:00"},"s":"D1", "c":"ACCESS", "id":20238, "ctx":"AuthorizationManager-1","msg":"Getting user record","attr":{"user":"bob@admin"}}
|
{"t":{"$date":"2020-06-07T21:32:15.731+00:00"},"s":"D1", "c":"-", "id":23074, "ctx":"AuthorizationManager-1","msg":"User assertion","attr":{"error":"UserNotFound: Could not find user \"bob\" for db \"admin\"","file":"src/mongo/db/auth/authorization_manager_impl.cpp","line":713}}
|
{"t":{"$date":"2020-06-07T21:32:15.731+00:00"},"s":"D1", "c":"-", "id":23074, "ctx":"conn18","msg":"User assertion","attr":{"error":"UserNotFound: Could not find user \"bob\" for db \"admin\"","file":"src/mongo/util/future_impl.h","line":674}}
|
{"t":{"$date":"2020-06-07T21:32:15.731+00:00"},"s":"I", "c":"ACCESS", "id":20249, "ctx":"conn18","msg":"Authentication failed","attr":{"mechanism":"SCRAM-SHA-256","principalName":"bob","authenticationDatabase":"admin","client":"127.0.0.1:38911","result":"UserNotFound: Could not find user \"bob\" for db \"admin\""}}
|
{"t":{"$date":"2020-06-07T21:32:15.731+00:00"},"s":"D1", "c":"-", "id":23074, "ctx":"conn18","msg":"User assertion","attr":{"error":"AuthenticationFailed: Authentication failed.","file":"src/mongo/db/auth/sasl_commands.cpp","line":336}}
|
{"t":{"$date":"2020-06-07T21:32:15.731+00:00"},"s":"I", "c":"COMMAND", "id":51803, "ctx":"conn18","msg":"Slow query","attr":{"type":"command","ns":"admin.$cmd","command":{"isMaster":1,"client":{"driver":{"name":"mongoc","version":"1.17.0-pre"},"os":{"type":"Linux","name":"Ubuntu","version":"16.04","architecture":"x86_64"},"platform":"cfg=0x02a15620c9 posix=200809 stdc=201112 CC=clang 3.8.0 (tags/RELEASE_380/final)"},"compression":[],"saslSupportedMechs":"admin.bob","speculativeAuthenticate":{"saslStart":1,"mechanism":"SCRAM-SHA-256","payload":{"$binary":{"base64":"biwsbj1ib2Iscj1Cd0RTdEQ1bE1kUVQxc3JrTXQzeUUvbTRCT0xBWUhFeg==","subType":"0"}},"autoAuthorize":1,"options":{"skipEmptyExchange":true},"db":"admin"},"$readPreference":{"mode":"secondaryPreferred"},"$db":"admin"},"numYields":0,"reslen":675,"locks":{},"protocol":"op_query","durationMillis":0}}
|
{"t":{"$date":"2020-06-07T21:32:15.731+00:00"},"s":"D1", "c":"QUERY", "id":22783, "ctx":"conn18","msg":"received interrupt request for unknown op: {opId}{printKnownOps_inlock}","attr":{"opId":558,"printKnownOps_inlock":""}}
|
{"t":{"$date":"2020-06-07T21:32:15.766+00:00"},"s":"I", "c":"NETWORK", "id":22944, "ctx":"conn18","msg":"connection ended","attr":{"remote":"127.0.0.1:38911","connectionCount":2}}
|
The ismaster command includes saslSupportedMechs and speculativeAuthentication.
These are the logs for the connection that receives the "ok": 0 reply:
{"t":{"$date":"2020-06-07T21:33:01.594+00:00"},"s":"D1", "c":"-", "id":23074, "ctx":"conn288","msg":"User assertion","attr":{"error":"ShutdownInProgress: aborting keys cache refresh because node is shutting down","file":"src/mongo/db/keys_collection_manager.cpp","line":203}}
|
{"t":{"$date":"2020-06-07T21:33:01.594+00:00"},"s":"D1", "c":"COMMAND", "id":21962, "ctx":"conn288","msg":"Assertion while executing command","attr":{"command":"isMaster","db":"admin","commandArgs":{"isMaster":1,"client":{"driver":{"name":"mongoc","version":"1.17.0-pre"},"os":{"type":"Linux","name":"Ubuntu","version":"16.04","architecture":"x86_64"},"platform":"cfg=0x02a15620c9 posix=200809 stdc=201112 CC=clang 3.8.0 (tags/RELEASE_380/final)"},"compression":[],"$clusterTime":{"clusterTime":{"$timestamp":{"t":1591565581,"i":1}},"signature":{"hash":{"$binary":{"base64":"CVas/c3Osh+SGBmIqSELxHsztFc=","subType":"0"}},"keyId":6835721630207967235}},"$readPreference":{"mode":"secondaryPreferred"},"$db":"admin"},"error":"ShutdownInProgress: aborting keys cache refresh because node is shutting down"}}
|
{"t":{"$date":"2020-06-07T21:33:01.594+00:00"},"s":"I", "c":"COMMAND", "id":51803, "ctx":"conn288","msg":"Slow query","attr":{"type":"command","ns":"admin.$cmd","command":{"isMaster":1,"client":{"driver":{"name":"mongoc","version":"1.17.0-pre"},"os":{"type":"Linux","name":"Ubuntu","version":"16.04","architecture":"x86_64"},"platform":"cfg=0x02a15620c9 posix=200809 stdc=201112 CC=clang 3.8.0 (tags/RELEASE_380/final)"},"compression":[],"$clusterTime":{"clusterTime":{"$timestamp":{"t":1591565581,"i":1}},"signature":{"hash":{"$binary":{"base64":"CVas/c3Osh+SGBmIqSELxHsztFc=","subType":"0"}},"keyId":6835721630207967235}},"$readPreference":{"mode":"secondaryPreferred"},"$db":"admin"},"numYields":0,"ok":0,"errMsg":"aborting keys cache refresh because node is shutting down","errName":"ShutdownInProgress","errCode":91,"reslen":166,"locks":{},"protocol":"op_query","durationMillis":0}}
|
{"t":{"$date":"2020-06-07T21:33:01.594+00:00"},"s":"D1", "c":"QUERY", "id":22783, "ctx":"conn288","msg":"received interrupt request for unknown op: {opId}{printKnownOps_inlock}","attr":{"opId":2067,"printKnownOps_inlock":""}}
|
{"t":{"$date":"2020-06-07T21:33:01.595+00:00"},"s":"I", "c":"NETWORK", "id":22944, "ctx":"conn288","msg":"connection ended","attr":{"remote":"127.0.0.1:41374","connectionCount":2}}
|
That ismaster command does not include saslSupportedMechs or speculativeAuthenticate. In the context of the test, this is an ismaster sent in multi-threaded monitoring, so it does not do auth negotiation or speculative auth (whereas single-threaded monitoring would).
CC sara.golemon do you think this could be related to speculative auth against the arbiter? It is not yet clear to me what is triggering the server to enter shutdown, so I might be barking up the wrong tree.
|