Avec cf bind-service ou cf unbind-service, le Servicebroker (composant Cloud Foundry) crée de nouvelles informations d'identification générées de manière aléatoire (voir cf env $APP). Avec notre offre de service MongoEnterprise, Service Broker se connecte à l'API Ops Manager et déploie un nouvel utilisateur sur le réplicas mongod.
Lorsque Ops Manager déploie l'utilisateur (createUser) il utilise WriteConcern « majorité », ce qui signifie au moins un des besoins secondaires à reconnaître l'écriture.
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
En raison du mongorestore, qui a été réalisée quelques heures avant que ce problème est survenu, il y a une possibilité que la commande createUser était hors délai en raison du manque de reconnaissance des secondaries qui étaient des indices de construction occupés au premier plan et arrière-plan. La construction de l'index (options mongorestore par défaut) est d'abord effectuée sur le primaire et, lorsqu'elle est terminée, sera en cours dans les secondaires. Ceci explique l'augmentation du retard sur les secondaires au cours de createUser.
Les générations d'index peuvent prendre beaucoup de temps, en fonction de l'index et de la taille des données. Nous avons entendu beaucoup de clients se plaindre de la construction de l'index prendre trop de temps.
Voici les journaux de la construction de l'index. Dans Ops Manager, le client peut voir streamé mongodb.log (opsmanager.service.consul) avec un peu de retard de la part de tous les membres du jeu de réplicas.
...
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
Ce sont les erreurs de Automation Agent (Ops directeur parle via HTTP avec l'agent Autoamtion sur la gestion VM, l'agent d'automatisation parle alors avec mongod avec protocole natif)
[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([email protected]_$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([email protected]_$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([email protected]_$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([email protected]_$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([email protected]_$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([email protected]_$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
Résumé: tout avec WriteConcern primaire fonctionne bien, mais WriteConcern fois majoritaire, ce qui bloque les builds d'index.