[GODRIVER-1763] Unable to authenticate with SCRAM-SHA-256 Created: 07/Oct/20  Updated: 27/Oct/23  Resolved: 23/Nov/20

Status: Closed
Project: Go Driver
Component/s: Authentication
Affects Version/s: 1.4.2
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: Derek Smith Assignee: Kevin Albertson
Resolution: Gone away Votes: 1
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

Running in a debian based docker image



 Description   

I am trying to connect to a database that is setup with authentication using SCRAM-SHA-256 using the go mongodb driver but I cannot make it work.  What else do I need to do on this machine to get this to work?  Do I have to install SASL libraries?

auth error: sasl conversation error: unable to authenticate using mechanism "SCRAM-SHA-256": (AuthenticationFailed) Authentication failed.



 Comments   
Comment by 镇龙 张 [ 15/Mar/21 ]

I ran into the same problem too.

connection() : auth error: sasl conversation error: unable to authenticate using mechanism "SCRAM-SHA-256": (KeyNotFound) Cache Reader No keys found for HMAC that is valid for time: { ts: Timestamp(1615779225, 1) } with id: 0

Here's the log : 

2021-03-15T11:33:45.860+0800 I  NETWORK  [listener] connection accepted from x.x.x.x:39986 #268372 (33 connections now open)
2021-03-15T11:33:45.861+0800 I  NETWORK  [conn268372] received client metadata from x.x.x.x:39986 conn268372: { driver: { name: "mongo-go-driver", version: "v1.4.6" }, os: { type: "linux", architecture: "amd64" }, platform: "go1.16" }
2021-03-15T11:33:45.861+0800 D3 NETWORK  [conn268372] Starting server-side compression negotiation
2021-03-15T11:33:45.861+0800 D3 NETWORK  [conn268372] No compressors provided
2021-03-15T11:33:45.861+0800 D1 ACCESS   [conn268372] Returning user xxxxxx@admin from cache
2021-03-15T11:33:45.867+0800 D2 NETWORK  [conn268372] Session from x.x.x.x:39986 encountered a network error during SourceMessage: HostUnreachable: Connection closed by peer
2021-03-15T11:33:45.867+0800 I  NETWORK  [conn268372] end connection x.x.x.x:39986 (32 connections now open)
2021-03-15T11:33:45.867+0800 D3 NETWORK  [conn268372] Cancelling outstanding I/O operations on connection to x.x.x.x:39986

 

 

Comment by Backlog - Core Eng Program Management Team [ 23/Nov/20 ]

There hasn't been any recent activity on this ticket, so we're resolving it. Thanks for reaching out! Please feel free to comment on this if you're able to provide more information.

Comment by Kevin Albertson [ 06/Nov/20 ]

Hi dereksmith.dev@gmail.com,

Thank you for the additional information. I attempted to closely match your environment and the user (which only has SCRAM-SHA-256 credentials without SCRAM-SHA-1 credentials) but I am still able to authenticate with the Go driver 1.4.2.

Server logs with higher verbosity may provide additional error information. By increasing the logComponentVerbosity for the "command" and "accessControl" components, I am able to get some additional information about which step in the authentication handshake fails, and additional error information.

For example, I started a 4.2.6 mongod with with increased log verbosity:

mongod --setParameter logComponentVerbosity='{"command": {"verbosity": 3},"accessControl": {"verbosity": 5}}'

And connected using the Go driver 1.4.2 with a faulty password, and was able to see the following logs:

2020-11-06T08:57:40.418-0500 D2 COMMAND  [conn4] run command admin.$cmd { isMaster: 1, compression: [], client: { driver: { name: "mongo-go-driver", version: "v1.4.2" }, os: { type: "darwin", architecture: "amd64" }, platform: "go1.15.1" }, $readPreference: { mode: "secondaryPreferred" }, $db: "admin" }
2020-11-06T08:57:40.418-0500 I  NETWORK  [conn4] received client metadata from 127.0.0.1:64248 conn4: { driver: { name: "mongo-go-driver", version: "v1.4.2" }, os: { type: "darwin", architecture: "amd64" }, platform: "go1.15.1" }
2020-11-06T08:57:40.418-0500 D2 COMMAND  [conn5] run command admin.$cmd { isMaster: 1, compression: [], client: { driver: { name: "mongo-go-driver", version: "v1.4.2" }, os: { type: "darwin", architecture: "amd64" }, platform: "go1.15.1" }, $readPreference: { mode: "secondaryPreferred" }, $db: "admin" }
2020-11-06T08:57:40.418-0500 I  COMMAND  [conn4] command admin.$cmd command: isMaster { isMaster: 1, compression: [], client: { driver: { name: "mongo-go-driver", version: "v1.4.2" }, os: { type: "darwin", architecture: "amd64" }, platform: "go1.15.1" }, $readPreference: { mode: "secondaryPreferred" }, $db: "admin" } numYields:0 reslen:685 locks:{} protocol:op_query 0ms
2020-11-06T08:57:40.418-0500 I  NETWORK  [conn5] received client metadata from 127.0.0.1:64249 conn5: { driver: { name: "mongo-go-driver", version: "v1.4.2" }, os: { type: "darwin", architecture: "amd64" }, platform: "go1.15.1" }
2020-11-06T08:57:40.418-0500 I  COMMAND  [conn5] command admin.$cmd command: isMaster { isMaster: 1, compression: [], client: { driver: { name: "mongo-go-driver", version: "v1.4.2" }, os: { type: "darwin", architecture: "amd64" }, platform: "go1.15.1" }, $readPreference: { mode: "secondaryPreferred" }, $db: "admin" } numYields:0 reslen:685 locks:{} protocol:op_query 0ms
2020-11-06T08:57:40.420-0500 I  NETWORK  [listener] connection accepted from 127.0.0.1:64251 #6 (3 connections now open)
2020-11-06T08:57:40.420-0500 D2 COMMAND  [conn6] run command admin.$cmd { isMaster: 1, speculativeAuthenticate: { saslStart: 1, mechanism: "SCRAM-SHA-256", payload: "xxx", db: "test", options: { skipEmptyExchange: true } }, compression: [], client: { driver: { name: "mongo-go-driver", version: "v1.4.2" }, os: { type: "darwin", architecture: "amd64" }, platform: "go1.15.1" }, $readPreference: { mode: "secondaryPreferred" }, $db: "admin" }
2020-11-06T08:57:40.420-0500 I  NETWORK  [conn6] received client metadata from 127.0.0.1:64251 conn6: { driver: { name: "mongo-go-driver", version: "v1.4.2" }, os: { type: "darwin", architecture: "amd64" }, platform: "go1.15.1" }
2020-11-06T08:57:40.420-0500 I  COMMAND  [conn6] command admin.$cmd command: isMaster { isMaster: 1, speculativeAuthenticate: { saslStart: 1, mechanism: "SCRAM-SHA-256", payload: "xxx", db: "test", options: { skipEmptyExchange: true } }, compression: [], client: { driver: { name: "mongo-go-driver", version: "v1.4.2" }, os: { type: "darwin", architecture: "amd64" }, platform: "go1.15.1" }, $readPreference: { mode: "secondaryPreferred" }, $db: "admin" } numYields:0 reslen:685 locks:{} protocol:op_query 0ms
2020-11-06T08:57:40.420-0500 D2 COMMAND  [conn6] run command test.$cmd { saslStart: 1, mechanism: "SCRAM-SHA-256", payload: "xxx", options: { skipEmptyExchange: true }, $clusterTime: { clusterTime: Timestamp(1604671054, 1), signature: { hash: BinData(0, 58A9FF61EE58F65DCDFBE2B8C2C8AF6374D80CD9), keyId: 6888056936286126084 } }, $db: "test", $readPreference: { mode: "primaryPreferred" } }
2020-11-06T08:57:40.420-0500 D1 ACCESS   [conn6] Getting user user2@test from disk
2020-11-06T08:57:40.421-0500 I  ACCESS   [conn6] SASL SCRAM-SHA-256 authentication failed for user2 on test from client 127.0.0.1:64251 ; UserNotFound: Could not find user "user2" for db "test"
2020-11-06T08:57:40.421-0500 D1 COMMAND  [conn6] assertion while executing command 'saslStart' on database 'test' with arguments '{ saslStart: 1, mechanism: "SCRAM-SHA-256", payload: "xxx", options: { skipEmptyExchange: true }, $clusterTime: { clusterTime: Timestamp(1604671054, 1), signature: { hash: BinData(0, 58A9FF61EE58F65DCDFBE2B8C2C8AF6374D80CD9), keyId: 6888056936286126084 } }, $db: "test", $readPreference: { mode: "primaryPreferred" } }': AuthenticationFailed: Authentication failed.
2020-11-06T08:57:40.421-0500 I  COMMAND  [conn6] command admin.system.users command: saslStart { saslStart: 1, mechanism: "SCRAM-SHA-256", payload: "xxx", options: { skipEmptyExchange: true }, $clusterTime: { clusterTime: Timestamp(1604671054, 1), signature: { hash: BinData(0, 58A9FF61EE58F65DCDFBE2B8C2C8AF6374D80CD9), keyId: 6888056936286126084 } }, $db: "test", $readPreference: { mode: "primaryPreferred" } } numYields:0 queryHash:0A298B98 planCacheKey:C2D1BA7E ok:0 errMsg:"Authentication failed." errName:AuthenticationFailed errCode:18 reslen:243 locks:{ ReplicationStateTransition: { acquireCount: { w: 1 } }, Global: { acquireCount: { r: 1 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 1 } }, Mutex: { acquireCount: { r: 1 } } } storage:{} protocol:op_msg 0ms
2020-11-06T08:57:40.421-0500 I  NETWORK  [conn6] end connection 127.0.0.1:64251 (2 connections now open)
2020-11-06T08:57:40.421-0500 I  NETWORK  [conn5] end connection 127.0.0.1:64249 (1 connection now open)
2020-11-06T08:57:40.422-0500 I  NETWORK  [conn4] end connection 127.0.0.1:64248 (0 connections now open)

If it's possible to reattempt with higher verbosity logs, that may help diagnose the issue. If you are able to obtain these logs, please redact the "payload" field of the "speculativeAuthenticate" document before including them.

Another, perhaps unlikely, hypothesis is that somehow the connection is going to an unexpected mongod / mongos. Connecting without auth, and running the isMaster command could verify you are connecting to the expected mongos.

Comment by Derek Smith [ 30/Oct/20 ]

Kevin,

 

Here is the user document.

 

 

{
    "_id" : "admin.nvgoadmin",
    "user" : "nvgoadmin",
    "db" : "admin",
    "credentials" : {
        "SCRAM-SHA-256" : {
            "iterationCount" : NumberInt(15000),
            "salt" : "",
            "storedKey" : "",
            "serverKey" : ""
        }
    },
    "roles" : [
        {
            "role" : "clusterAdmin",
            "db" : "admin"
        },
        {
            "role" : "userAdminAnyDatabase",
            "db" : "admin"
        }
    ],
    "authenticationRestrictions" : [
    ],
    "userId" : UUID("2125fda2-44bf-4325-9154-74646bf9f837")
}

 

The user has a simple password that consists of alpha characters only.  

 

Comment by Kevin Albertson [ 27/Oct/20 ]

Hi dereksmith.dev@gmail.com, I have not yet been able to reproduce this. I will continue to attempt (working on setting up a local kubernetes cluster to more closely match your environment), but here is an update in the meantime.

The Go driver depends on https://github.com/xdg-go/scram to support the SCRAM-SHA-1 and SCRAM-SHA-256 auth mechanisms. There should not be any missing external libraries.

I tested connecting with the Go driver with SCRAM-SHA-256 against a 4.2.6 single node replica set and was able to connect without issue.

I have a few other questions which may help diagnose.

1. Does specifying an explicit auth mechanism of SCRAM-SHA-1 work? E.g.
mongodb://mongodb-metabase@mongodb.default:27017/?authSource=admin&authMechanism=SCRAM-SHA-1
If so, that could narrow it down to an issue in the SCRAM-SHA-256 conversation specifically.

2. Does the username or password contain multi-byte UTF-8 characters? That could indicate an issue in the Go driver's implementation of SASLPrep.

3. If possible, can you include the redacted contents of the user's document in the admin database system.users collection? It should resemble the following:

{
	"_id" : "admin.user",
	"userId" : UUID("ca756df5-5cc8-4a74-a5af-a1ab055312f6"),
	"user" : "user",
	"db" : "admin",
	"credentials" : {
		"SCRAM-SHA-1" : {
			"iterationCount" : 10000,
			"salt" : "(redacted)",
			"storedKey" : "(redacted)",
			"serverKey" : "(redacted)"
		},
		"SCRAM-SHA-256" : {
			"iterationCount" : 15000,
			"salt" : "(redacted)",
			"storedKey" : "(redacted)",
			"serverKey" : "(redacted)"
		}
	},
	"roles" : [
		{
			"role" : "root",
			"db" : "admin"
		}
	]
}

Comment by Derek Smith [ 17/Oct/20 ]

Kevin, here is some more information regarding my issue.

I am running the MongoDB Kubernetes Operator (https://github.com/mongodb/mongodb-kubernetes-operator) inside of a microk8s cluster.  It is running MongoDB version 4.2.6.  Inside of this cluster I have dotnet core (C#) and Golang workloads that communicate with the MongoDB server.  The dotnet core libraries are able to connect to the database just fine, but the golang code is not.  I am also using Studio 3T for MongoDB on my machine and am able to connect to the cluster with that.  

 

Connection string used by Mongo 3T Studio:  (passwords redacted)

mongodb://nvgoadmin@192.168.64.2:27017/?serverSelectionTimeoutMS=5000&connectTimeoutMS=10000&authSource=admin&authMechanism=SCRAM-SHA-256

Connection string used by dotnet core and golang inside the cluster:

mongodb://mongodb-metabase@mongodb.default:27017/?authSource=admin&authMechanism=SCRAM-SHA-256

The go code is using this driver:

go.mongodb.org/mongo-driver v1.4.2

The code is being run inside of a docker container.  Is there an external library I need to install on the box for this to work?

 

Comment by Kevin Albertson [ 14/Oct/20 ]

Thank you for the report! I may need more information to investigate and reproduce. Those errors are generated from server responses. What version of the server are you authenticating against, and how is it deployed (standalone, replica set, sharded cluster)? Are you able to reproduce this with a new user? If so, can you include the steps you are using to create?

Comment by 琦智 王 [ 10/Oct/20 ]

I got this error too.
In mongo cluster, connect with "go.mongodb.org/mongo-driver v1.4.1".

Might be made for:

error: connection() : auth error: sasl conversation error: unable to authenticate using mechanism "SCRAM-SHA-256": (KeyNotFound) Cache Reader No keys found for HMAC that is valid for time: { ts: Timestamp(1602313084, 2) } with id: 0

And change to "SCRAM-SHA-1", error also exist:

do FindOne failed, err:connection() : auth error: sasl conversation error: unable to authenticate using mechanism "SCRAM-SHA-1": (KeyNotFound) Cache Reader No keys found for HMAC that is valid for time: { ts: Timestamp(1601372808, 1) } with id: 0

PTAL.

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