Deux jours de galère, de lecture de KB divers zé variés, une douzaine de rollback de snapshots, pour tenter une douzaine de manipulations différentes et enfin, trouver la solution (temporaire). Voila en substance le bilan de l’expiration d’un certificat SSL sur un “vieux” vCenter 6.0 que nous gardons encore pour quelques machines spécifiques.
VMware a fait beaucoup de progrès depuis vSphere 5 concernant la mise à jour des certificats SSL de ses différents produits et solutions. Pour autant, il reste encore des subtilités qui m’échappent, ou des exceptions non documentées (ou peut-être spécifiques à nos environnements) qui font qu’une opération qui, a priori, s’annonçait relativement simple, se transforme en un parcours du combattant. Petit récit de la mésaventure de cette semaine.
Malgré nos efforts pour superviser toujours plus précisément et finement l’ensemble de nos infrastructures techniques, il reste encore des “trous” que nous comblons au gré des revues de supervision régulières et des évolutions de nos produits (roue de Deming tout ça) … et c’est à cause de l’un de ces trous que ce Lundi, nous nous sommes retrouvé dans le noir sur un vCenter 6.0 satellite de notre production principale.
Le symptôme initial était relativement explicite : l’accès au vSphere Client nous renvoyait invariablement une belle erreur 500 :
Après quelques vérifications et manipulations classiques de notre service de MCO (espace disque disponible, reboot etc.), force était de constater que la machine refusait obstinément de nous donner l’accès au client web. La première chose que j’ai trouvé en cherchant un peu dans les logs c’est que le service chargé de la Content Library, aka vmware-vdcs, ne démarrait pas correctement. Pour se faire, j’ai utilisé une manip bien pratique sur les services vCSA :
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 |
vcenterprd2:~ # service-control --status INFO:root:Service: vmware-rhttpproxy, Action: status Service: vmware-rhttpproxy, Action: status 2019-01-08T15:21:14.258Z Running command: ['/sbin/service', u'vmware-rhttpproxy', 'status'] 2019-01-08T15:21:14.295Z Done running command INFO:root:Service: vmware-cis-license, Action: status Service: vmware-cis-license, Action: status 2019-01-08T15:21:14.295Z Running command: ['/sbin/service', u'vmware-cis-license', 'status'] 2019-01-08T15:21:14.404Z Done running command INFO:root:Service: vmware-psc-client, Action: status Service: vmware-psc-client, Action: status 2019-01-08T15:21:14.405Z Running command: ['/sbin/service', u'vmware-psc-client', 'status'] 2019-01-08T15:21:14.424Z Done running command (...) INFO:root:Service: vmware-vws, Action: status Service: vmware-vws, Action: status 2019-01-08T15:21:15.965Z Running command: ['/sbin/service', u'vmware-vws', 'status'] 2019-01-08T15:21:16.030Z Done running command INFO:root:Stopped: vmware-mbcs (VMware Message Bus Configuration Service) vmware-netdumper (VMware vSphere ESXi Dump Collector) vmware-rbd-watchdog (VMware vSphere Auto Deploy Waiter) vmware-vdcs (VMware Content Library Service) Stopped: vmware-mbcs (VMware Message Bus Configuration Service) vmware-netdumper (VMware vSphere ESXi Dump Collector) vmware-rbd-watchdog (VMware vSphere Auto Deploy Waiter) vmware-vdcs (VMware Content Library Service) |
On visualise très vite quels sont les services arrêtés. Pour certains, suivant les fonctions que vous utilisez, c’est normal, par contre, pour vmware-vdcs, il y avait clairement un problème. Même si je trouvais étrange qu’un service satellite comme celui là provoque un plantage complet du vSphere Client, j’ai creusé un peu et repéré une corruption du fichier “.pid” qui habituellement héberge le process ID du démon. Une petite suppression forcée après, le service se lançait correctement (la note KB#2147891 décrit précisément la situation, à lire).
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 |
vcenterprd2:~ # more /var/log/vmware/vdcs/wrapper.log DEBUG | wrapper | 2019/01/08 15:15:55 | An encoding declaration is missing from the top of configuration file, /etc/vmware/wrapper_common.conf, trying the system encoding. DEBUG | wrapper | 2019/01/08 15:15:55 | An encoding declaration is missing from the top of configuration file, /etc/vmware/wrapper_linux.conf, trying the system encoding. DEBUG | wrapper | 2019/01/08 15:15:55 | Spawning intermediate process... DEBUG | wrapper | 2019/01/08 15:15:55 | Spawning daemon process... DEBUG | wrapper | 2019/01/08 15:15:55 | Reloading configuration. DEBUG | wrapper | 2019/01/08 15:15:55 | An encoding declaration is missing from the top of configuration file, /etc/vmware/wrapper_common.conf, trying the system encoding. DEBUG | wrapper | 2019/01/08 15:15:55 | An encoding declaration is missing from the top of configuration file, /etc/vmware/wrapper_linux.conf, trying the system encoding. DEBUG | wrapper | 2019/01/08 15:15:55 | active log file changed: /var/log/vmware/vdcs/wrapper.log DEBUG | wrapper | 2019/01/08 15:15:55 | active log file changed: /var/log/vmware/vdcs/wrapper.log ERROR | wrapper | 2019/01/08 15:15:55 | 19710 pid file, /var/log/vmware/vdcs/vmware-vdcs.pid, already exists. FATAL | wrapper | 2019/01/08 15:15:55 | ERROR: Could not write pid file /var/log/vmware/vdcs/vmware-vdcs.pid: Inappropriate ioctl for device vcenterprd2:~ # cd /var/log/vmware/vdcs vcenterprd2:~ # rm vmware-vdcs.pid vcenterprd2:~ # service-control --start vmware-vdcs INFO:root:Service: vmware-vdcs, Action: start Service: vmware-vdcs, Action: start 2019-01-10T10:47:49.524Z Running command: ['/sbin/chkconfig', u'vmware-vdcs'] 2019-01-10T10:47:49.563Z Done running command 2019-01-10T10:47:49.563Z Running command: ['/sbin/service', u'vmware-vdcs', 'status'] 2019-01-10T10:47:49.702Z Done running command |
Malgré ce premier petit souci réglé – ça aurait été trop facile – vCenter refusait encore d’afficher quoi que ce soit. Toujours cette fichue erreur 500. Nos investigations se sont ensuite portées sur les logs des autres services et notamment celui du démon “Component Manager”, ce qui nous a mené sur une autre piste. Celui-ci nous affichait régulièrement des messages d’erreurs sur les certificats SSL en place :
1 2 |
Server certificate chain is not trusted sun.security.validator.ValidatorException: PKIX path validation failed: java.security.cert.CertPathValidatorException: timestamp check failed |
Dieu me tamponne, mais oui… Ooops… le certificat du vCenter était expiré ! Le “trou de supervision” était donc identifié, nous n’avions pas de test d’expiration sur la VCSA. Sur ce constat plutôt rassurant finalement, nous avons donc déroulé la procédure de renouvellement de certificat. Lors de l’installation de la plateforme, nous avions à l’époque installé un certificat issu de notre PKI Infrastructure interne qui reposait sur l’algorithme de hashage SHA-1, dont vous savez certainement qu’il est déclaré “unsecure” depuis déjà un paquet d’années (voir cet article comme tant d’autres, sur Wikipedia). Depuis nous avons créé une nouvelle autorité intermédiaire reposant sur SHA-256, avec laquelle nous certifions désormais tous nos équipements et services de production.
Pour le coup, je me suis dit que nous allions faire d’une pierre deux coups et j’ai entrepris de créer un nouveau certificat via cette nouvelle PKI. La procédure est bien décrite par VMware et repose sur l’utilisation de l’outil “certificate-manager” disponible directement en ligne de commande (pour plus d’info sur son utilisation, consultez le KB#2112277).
Et pourtant, tout semblait être sur la bonne voie pour rétablir l’accès au service rapidement. C’était sans compter sur ce vCenter “tête de mule”. En effet, lors de l’injection du nouveau certificat SSL (tamponné par notre PKI SHA-256, donc, vous suivez ?), le service Component Manager a refusé de démarrer avec encore une erreur de type “Server certificate chain is not trusted” à la clef. Nous sommes reparti à la pèche aux infos via les logs, analyses diverses, beaucoup de lectures sur le Net, pour tomber sur cet article KB#2111571 qui précise qu’il ne faut pas oublier de rajouter la chaîne de certification dans le dépôt officiel de la PSC lorsque l’on injecte un nouveau certificat issue d’une autorité différente. Effectivement, j’avais bien lu cela quelques années auparavant. Dont acte ! Ré-injectons donc cette autorité intermédiaire SHA-256 :
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 |
vcenterprd2:~/newcert # /usr/lib/vmware-vmafd/bin/dir-cli trustedcert list Enter password for administrator@vsphere.local: Number of certificates: 2 #1: CN(id): 030FA6DAEA1ACEA02105372E3BE120ABF49CFA77 Subject DN: CN=CA, DC=vsphere, DC=local, C=US, O=vcenterprd2.yoyodyne.fr CRL present: yes #2: CN(id): 8C047CDDF03B4CDEC0E8D3064642B0F88E82279D Subject DN: C=FR, O=Yoyodyne, OU=0002 26440013600026, CN=AUTORITE INFRASTRUCTURE AUTHENTIFICATION CRL present: no vcenterprd2:~/newcert # /usr/lib/vmware-vmafd/bin/dir-cli trustedcert publish --chain --cert ~/newcert/chain.pem Enter password for administrator@vsphere.local: xxxxxxxx vcenterprd2:~/newcert # /usr/lib/vmware-vmafd/bin/dir-cli trustedcert list Enter password for administrator@vsphere.local: xxxxxxxx Number of certificates: 4 #1: CN(id): 030FA6DAEA1ACEA02105372E3BE120ABF49CFA77 Subject DN: CN=CA, DC=vsphere, DC=local, C=US, O=vcenterprd2.yoyodyne.fr CRL present: yes #2: CN(id): 8C047CDDF03B4CDEC0E8D3064642B0F88E82279D Subject DN: C=FR, O=Yoyodyne, OU=0002 26440013600026, CN=AUTORITE INFRASTRUCTURE AUTHENTIFICATION CRL present: no #3: CN(id): D8EDF4AE23C9B352F7949041E46BBE73073B4499 Subject DN: C=FR, O=Yoyodyne, OU=0002 26440013600026, CN=AUTORITE INFRASTRUCTURE AUTHENTIFICATION SHA256 CRL present: no vcenterprd2:~/newcert # |
Ensuite, on relance la procédure de remplacement de certificat… et … PAF, et non ! toujours ce satané service Component Manager qui refuse de se lancer ! Incompréhensible, incroyable, frustrant … et les heures qui tournent pendant ce temps là pour notre équipe de prod, sans accès au vCenter. En désespoir de cause, il me vient une idée saugrenue et plutôt “de la dernière chance” : essayons de générer un certificat sur l’ancienne PKI SHA-1 et d’utiliser celui-ci. Ce n’est pas l’idéal et il faudra tôt ou tard corriger cette faiblesse de chiffrement mais si cela permet de rétablir le service rapidement, ce sera déjà ça de gagné.
Je relance donc le certificate-manager avec ce certificat obsolète, mais fonctionnel et dont la date d’expiration laisse le temps de voir venir. Miracle ! Tout ce petit monde redémarre tranquillement et vCenter est de nouveau accessible !
Cette petite “tranche de prod” est encore très fraîche et je n’ai pas encore de root cause identifié vis à vis de ce comportement. Est-ce documenté quelque part ? Aucune idée, en tout cas je n’ai pas trouvé de KB spécifique expliquant le phénomène. La prochaine étape, et bien sûr, je vous tiendrai au courant dans un prochain billet, c’est, alors que le vCenter est à nouveau opérationnel, de tenter de réinjecter un certificat SHA-256 pour vérifier si cela se reproduit. On pourra, en fonction du résultat, tirer des conséquences plus précise de ce qui s’est passé et contacter VMware pour obtenir l’explication.
Mais, vous allez me dire : “pourquoi n’as-tu pas appelé VMware et ouvert un SR ?”. En fait nous l’avons fait au bout de quelques heures de débugging, mais malheureusement, la personne qui a assisté l’ingénieur via webex n’était pas au courant de tous nos tests. Du coup, regardant, comme nous, les logs, le support VMware a répondu, comme nous la première fois, qu’il s’agissait d’un problème de certificat et qu’il fallait en refaire un. En gros, on a trouvé la solution de contournement dans l’intervalle.
Si vous avez des explications de votre coté ou des pistes de réflexions, n’hésitez pas à me les proposer dans les commentaires !
Bonne fin de semaine à vous !
3