mongodb - 应用程序无法连接到带有 "Authentication failed"的 MongoDB Enterprise，Ops Manager 卡在 "AdjustUsers"

Question

新部署的应用程序的凭据被 MongoDB 拒绝并显示“身份验证失败”。 MongoDB Ops Manager 已经停留在“AdjustUsers”几个小时了。

---

验证者:

cf service-connector 8080 opsmanager.service.consul:8080

打开浏览器 http://localhost:8080并使用在门户网站上获得的 mongodb 服务 key 登录:

"ops_manager_url": "http://opsmanager.service.consul:8080",
"ops_manager_user": "xxx",
"ops_manager_password": "xxx",

---

我最近使用 mongorestore 恢复了大约 20GB 的数据:

cf service-connector 27020 xxx-0.service.consul:33602
mongorestore --gzip --port 27020 --username xxx --password xxx --db rs_xxx /backup/mongodump/ > mongorestore.log 2>&1 &

---

其他已经存在的应用程序没有问题。只有我使用蓝绿部署部署的应用无法连接:

cf push $APP-new 
cf map-route $APP-new $DOMAIN --hostname $APP
cf unmap-route $APP $DOMAIN --hostname $APP || true
cf unmap-route $APP-new $DOMAIN --hostname $APP-new
cf delete -f   $APP
cf rename      $APP-new $APP

在我的应用程序中，我没有指定 WriteConcern，所以我假设它只是主要的(“w: 1”)

Answer 1

对于每个cf bind-service 或cf unbind-service Servicebroker (一个 Cloud Foundry 组件)创建新的随机生成的凭证(用 cf env $APP 查看它)。通过我们的 MongoEnterprise 服务产品，Service Broker 连接到 Ops Manager API 并将新用户部署到 mongod 副本集。

当 Ops Manager 部署用户 (createUser) 时，他使用 WriteConcern“多数”，这意味着至少有一个次级需要确认写入。

COMMAND  [conn53768] command rs_$DBNAME.$cmd command: createUser { createUser: "$USERNAME", pwd: "xxx", digestPassword: false, roles: [ { role: "readWrite", db: "rs_$DBNAME" } ], writeConcern: { w: "majority" } } keyUpdates:0 writeConflicts:0 numYields:0 reslen:138 locks:{ Global: { acquireCount: { r: 2, w: 2 } }, Database: { acquireCount: { W: 2 } }, Collection: { acquireCount: { w: 2 } } } protocol:op_query 9811ms

由于 mongorestore 是在该问题发生前几个小时执行的，因此 createUser 命令可能因缺乏确认而超时来自忙于在前台和后台建立索引的辅助节点。索引构建(默认 mongorestore 选项)首先在主节点上完成，完成后将在辅助节点上进行。这解释了 createUser 期间辅助节点的延迟上升。

索引构建可能需要很长时间，具体取决于索引和数据大小。我们听到很多客户提示索引构建时间太长。

这是索引构建的日志。在 Ops Manager 中，客户可以看到流式传输的 mongodb.log (opsmanager.service.consul)，所有副本集成员都有一点延迟。

...
2017-02-15T10:40:06.199+0000 I INDEX    [repl writer worker 10] build index done.  scanned 1108917 total records. 672 secs
2017-02-15T10:50:08.553+0000 I INDEX    [repl writer worker 4] build index done.  scanned 1108917 total records. 602 secs
2017-02-15T11:01:13.888+0000 I INDEX    [repl writer worker 7] build index done.  scanned 1108917 total records. 665 secs
...
2017-02-15T15:01:37.405+0000 I INDEX    [repl index builder 176] build index done.  scanned 1109531 total records. 659 secs
2017-02-15T15:01:37.406+0000 I INDEX    [repl index builder 170] build index done.  scanned 1109531 total records. 659 secs
2017-02-15T15:16:20.139+0000 I INDEX    [repl index builder 170] build index done.  scanned 1109699 total records. 882 secs

这些是来自 Automation Agent 的错误(Ops Manager 通过 HTTP 与托管 VM 上的 Autoamtion Agent 对话，然后 Automation Agent 使用 native 协议(protocol)与 mongod 对话)

[2017/02/15 13:33:36.297] [.error] [cm/mongoctl/authctl.go:updateUser26Style:697] [101] <rs_$DB_NAME> [13:33:36.297] Error updating 2.6-style user = AuthUser($USER@rs_$DB_NAME,roles=AuthRoles(1:{"Rolename":"readWrite","Db":"rs_$DB_NAME"}),interned=true,identity=2) in db = rs_$DB_NAME : <rs_$DB_NAME> [13:33:36.297] Timed out (timeout=-1ns) trying to runCommandWithTimeout(dbName=rs_$DB_NAME, cmd=[{"Name":"updateUser","Value":"$USER"},{"Name":"pwd","Value":"$PASSWORD"},{"Name":"digestPassword","Value":false},{"Name":"roles","Value":[{"db":"rs_$DB_NAME","role":"readWrite"}]}])
[2017/02/15 13:33:36.297] [.error] [cm/mongoctl/authctl.go:UpsertUser:516] [101] <rs_$DB_NAME> [13:33:36.297] Error upserting 2.6-style user = AuthUser($USER@rs_$DB_NAME,roles=AuthRoles(1:{"Rolename":"readWrite","Db":"rs_$DB_NAME"}),interned=true,identity=2) : <rs_$DB_NAME> [13:33:36.297] Error updating 2.6-style user = AuthUser($USER@rs_$DB_NAME,roles=AuthRoles(1:{"Rolename":"readWrite","Db":"rs_$DB_NAME"}),interned=true,identity=2) in db = rs_$DB_NAME : <rs_$DB_NAME> [13:33:36.297] Timed out (timeout=-1ns) trying to runCommandWithTimeout(dbName=rs_$DB_NAME, cmd=[{"Name":"updateUser","Value":"$USER"},{"Name":"pwd","Value":"$PASSWORD"},{"Name":"digestPassword","Value":false},{"Name":"roles","Value":[{"db":"rs_$DB_NAME","role":"readWrite"}]}])
[2017/02/15 13:33:36.297] [.error] [cm/action/adjustusers.go:adjustUsers:52] [101] <rs_$DB_NAME> [13:33:36.297] Error upserting user = AuthUser($USER@rs_$DB_NAME,roles=AuthRoles(1:{"Rolename":"readWrite","Db":"rs_$DB_NAME"}),interned=true,identity=2). Trying to proceed though. : <rs_$DB_NAME> [13:33:36.297] Error upserting 2.6-style user = AuthUser($USER@rs_$DB_NAME,roles=AuthRoles(1:{"Rolename":"readWrite","Db":"rs_$DB_NAME"}),interned=true,identity=2) : <rs_$DB_NAME> [13:33:36.297] Error updating 2.6-style user = AuthUser($USER@rs_$DB_NAME,roles=AuthRoles(1:{"Rolename":"readWrite","Db":"rs_$DB_NAME"}),interned=true,identity=2) in db = rs_$DB_NAME : <rs_$DB_NAME> [13:33:36.297] Timed out (timeout=-1ns) trying to runCommandWithTimeout(dbName=rs_$DB_NAME, cmd=[{"Name":"updateUser","Value":"$USER"},{"Name":"pwd","Value":"$PASSWORD"},{"Name":"digestPassword","Value":false},{"Name":"roles","Value":[{"db":"rs_$DB_NAME","role":"readWrite"}]}])
[2017/02/15 13:33:36.381] [.error] [cm/executor/executor.go:ExecutePlan:184] <rs_$DB_NAME> [13:33:36.381] Postcondition failed for step AdjustUsers because
[The value of 'currentState.UsersRight' = false, but it should be true]. Outcome=3

总结:WriteConcern primary 的一切工作正常，但 WriteConcern majority 超时，导致阻塞索引构建。