VMware vSphere : Décoder les erreurs SCSI

Do you speak SCSI ?

Vous êtes-vous déjà demandé comment l’ESXi communiquait avec son stockage ?
Ou peut-être avez-vous déjà lu quelques logs (presque) incompréhensibles.

Aujourd’hui je vais vous parler un peu du protocole SCSI et j’aborderai plus précisément la localisation et l’interprétation de logs dans le cadre de problèmes stockage en environnement vSphere.

 

Rappel sur le protocole SCSI

Que vous utilisiez le protocole Fibre Channel ou iSCSI, ces deux protocoles de transport encapsulent en réalité des commandes SCSI.

Toute communication SCSI se fait entre un initiateur (INITIATOR ; dans notre cas le périphérique présent sur l’ESXi : HBA/Eth/…) qui envoie des commandes à un périphérique cible (TARGET ; soit la baie de stockage).

Pour chaque commande envoyée par l’initiateur, la cible renvoie un code de retour (« occupé », « échec » ou « vérifié avec succès »). De cette manière, l’initiateur sait si oui ou non la commande envoyée a bien été bien effectuée. Il y a près de 60 commandes SCSI différentes.

 

Pourquoi et quand aller voir les logs ?

Lorsque vous rencontrez un problème lié au stockage sur votre plateforme (Problème de MPIO (Multipathing), latence, déconnexion de Datastore, …) il est essentiel de consulter les logs ESXi.

Une tendance assez commune lors de problèmes stockage est d’incriminer directement l’ESXi parfois (souvent) à tord. Afin de « disculper » l’ESXi mais essentiellement de pouvoir identifier la Root Cause de vos problèmes stockages il est essentiel de consulter les logs de l’ESXi.

 

Où trouver les logs ESXi ?

Pour ceux qui ne sont pas familiers avec les logs ESXi voici une liste non exhaustive des différents fichiers de log:

  • /var/log/syslog.log: Management service initialization, watchdogs, scheduled tasks and DCUI use.
  • /var/log/usb.log: USB device arbitration events, such as discovery and pass-through to virtual machines.
  • /var/log/vob.log: VMkernel Observation events, similar to vob.component.event.
  • /var/log/vmkernel.log: Core VMkernel logs, including device discovery, storage and networking device and driver events, and virtual machine startup.
  • /var/log/vmkwarning.log: A summary of Warning and Alert log messages excerpted from the VMkernel logs.
  • /var/log/vmksummary.log: A summary of ESXi host startup and shutdown, and an hourly heartbeat with uptime, number of virtual machines running, and service resource consumption.
  • /var/log/vpxa.log: vCenter Server vpxa agent logs, including communication with vCenter Server and the Host Management hostd agent.
  • /var/log/fdm.log: vSphere High Availability logs, produced by the fdm service

 

Le fichier vmkwarning.log contient entre autre les messages d’erreurs relatifs à une latence trop importante ou à des problèmes de I_T NEXUS (nom donné à une connexion SCSI) au niveau iSCSI.

Un exemple ici :

2014-10-30T19:26:44.833Z cpu19:3341331)WARNING: ScsiDeviceIO: 1224: Device naa.6000d310003995000000000000000068 performance has deteriorated. I/O latency increased from average value of 5542 microseconds to 300056 microseconds.
2014-09-17T13:19:05.707Z cpu2:8406)WARNING: NMP: vmk_NmpSatpIssueTUR:1019:Device naa.6000d3100039950000000000000000e0 path vmhba2:C0:T1:L109 has been unmapped from the array

 

Pour la suite de l’article nous allons nous concentrer sur l’analyse du fichier vmkernel.log. Il s’agit d’un des principaux fichiers log du vmkernel et on y trouve notamment des événements concernant le stockage. Il est donc essentiel lors d’un troubleshooting d’aller consulter ce fichier.

Ci-dessous, un message extrait du log contenant des codes SCSI :

2013-10-06T18:07:53.133Z cpu5:4101)ScsiDeviceIO: 2309: Cmd(0x412401189d80) 0x28, CmdSN 0x80000051 from world 5733331 to dev « naa.6006048c2fa126da3fd9e1b661512cc2 » failed H:0x0 D:0x2 P:0x0 Possible sense data: 0x3 0x11 0x0.

 

2013-10-06T18:07:53 = Date et heure (attention format UTC)

cpu5: = cpu/core qui a attrapé l’exception

4101 = World ID or WID du processus

ScsiDeviceIO: = Partie du code source du vmkernel qui reporte le message

2309: = ligne de code qui reporte le message

Cmd(0x412401189d80) 0x28, CmdSN 0x80000051 from world 5733331 to dev « naa.6006048c2fa126da3fd9e1b661512cc2 » failed H:0x0 D:0x2 P:0x0 Possible sense data: 0x3 0x11 0x0. = Message

 

Et bien sûr ici c’est le « Message » qui nous intéresse ! Que l’on pourra décomposer comme suit :

Cmd(0x412401189d80) 0x28, CmdSN 0x80000051 from world 5733331 to dev « naa.6006048c2fa126da3fd9e1b661512cc2 » failed H:0x0 D:0x2 P:0x0 Valid sense data: 0x3 0x11 0x0

Cmd 0x28 = Commande SCSI (appelé aussi op code), ici 0x28 est une commande de lecture
CmdSN 0x80000051 = Numéro de série de la commande adressée au périphérique (utilisé pour identifier une commande SCSI de manière unique)
world 5733331 = World ID qui transmet la commande
naa.600508e00000000063bf7ecc1b572d0b =  Périphérique logique sur la baie de stockage ou le contrôleur RAID.

H:0x0 = (Host) Ce code est appelé Host Status Code. Le code 0x0 signifie que driver de l’ESXi n’a pas reporté d’erreurs.
D:0x2 -> (Device) Ce code est appelé « Device Status Code ». Le code 0x2 indique un CHECK CONDITION. La baie de stockage ou le contrôleur RAID reporte un problème.
P:0x0 -> Le plugin d’accès ne reporte pas d’erreur. (Specifique VMware notamment pour les VAAI)


Valid sense data
= Informations supplémentaires disponibles (Après que l’on ai envoyé la commande SCSI « Request SENSE »)
0x3 = Ce code est appelé Sense Key. Le code 0x3 indique une Erreur de périphérique.
0x11 0x0 = Ce code est appelé ASC/ASCQ. Le couple 0x11 0x0 indique une Erreur de lecture non récupérable.

Donc pour résumer :
Suite à l’envoi d’une commande de lecture sur la LUN naa.600508e00000000063bf7ecc1b572d0b pour la VM ayant le World ID 5733331, la baie de stockage a rencontré un problème de lecture non récupérable au niveau du périphérique. Il est temps d’aller voir du coté baie de stockage !

 

Ici un schéma simplifié du déroulement des différentes requêtes SCSI.

 

Outils permettant de comprendre les codes SCSI

Pour déchiffrer les codes SCSI vous pouvez vous rendre sur :

https://www.virten.net/vmware/esxi-scsi-sense-code-decoder/

http://www.t10.org/lists/1spc-lst.htm
http://kb.vmware.com/selfservice/microsites/search.do?language=en_US&cmd=displayKC&externalId=289902
http://kb.vmware.com/selfservice/microsites/search.do?language=en_US&cmd=displayKC&externalId=1029039
http://kb.vmware.com/selfservice/microsites/search.do?language=en_US&cmd=displayKC&externalId=1030381

 

Ici un outil bien pratique développé par Pierre Ancelot qui permet de décoder vos codes SCSI :
http://www.neko-consulting.com/scsidecoder/start

 

Note : Si vous voyez des codes SCSI de ce type : « 0x5 », « 0x24 », 0x0 sur des périphériques USB ou CD-ROM, rien d’inquiétant : il arrive que l’ESXi effectue une requête sur ces périphériques qui ne supportent pas le VPD (Vital Product Data).

 

Pour aller plus loin

www.seagate.com/staticfiles/support/disc/manuals/scsi/100293068a.pdf
http://en.wikipedia.org/wiki/SCSI_command

Share !
Share on Google+Tweet about this on TwitterShare on LinkedInEmail this to someone