Hello !

Depuis le début du mois d’Avril, je suis de retour sur Marseille et j’ai profité de changer la machine Syno qui me sert de NAS par une autre récupéré sur Nancy. Elle demande encore moins de puissance pour fonctionner notamment au niveau du processeur. Vu que je ne compte pas faire de virtualisation ou d’un quelconque usage poussé, je l’ai prise pour voir sur le long terme comment se comporte un processeur AMD. La machine est donc aujourd’hui composé d’un Sempron LE-1250 dont sa première année de production date de 2009. C’est un peu vieux mais il remplie bien son rôle avec son seul cœur cadencé à une fréquence de 2.2Ghz.

A propos du système, j’utilisais une version cracké de l’OS Synology appelé DSM 5.2. Mais finalement lors de la migration, je suis passé sous Debian 8 pour être libre de personnaliser mon système comme je l’entends. Sous DSM il y avait quelques soucis pour installer correctement des paquets. Par exemple, j’ai eu des soucis de versions pour installer les modules correspondant à la gestion de comptes mails. De plus, l’interface était longue à charger pour le peu que j’en faisais. Son point fort réside sur la compatibilité du raid 1 car je n’ai pas eu besoin de recréer le raid sur la nouvelle machine. Il m’a suffit de déplacer physiquement le raid d’une machine à une autre pour que ça marche. Au boot, mdadm l’a détecté automatiquement et rien de plus à faire. Entrons dans le vif du sujet

Tout se passe bien jusqu’a ce que je m’intéresse enfin (5 mois plus tard…) à ce mail :

This is an automatically generated mail message from mdadm
running on nas.bruno-tatu.com

A SparesMissing event had been detected on md device /dev/md5.

Faithfully yours, etc.

P.S. The /proc/mdstat file currently contains the following :

Personalities : [raid6] [raid5] [raid4]
md5 : active raid5 sda1[0] sdd1[4] sdc1[2] sdb1[1]
1171737600 blocks super 1.2 level 5, 512k chunk, algorithm 2 [4/4] [UUUU]
bitmap : 0/3 pages [0KB], 65536KB chunk

unused devices :

Il me rappel que j’ai oublié d’ajouter un disque de rechange (spare) dans le raid. C’était mon 1er RAID5 dont la commande suivante avait été tapé :

# mdadm —create /dev/md5 —level=5 —raid-devices=4 /dev/sda1 /dev/sdb1 /dev/sdc1 /dev/sdd1

Il aurait fallut que je rajoute l’argument suivant pour que la commande soit correcte :

# mdadm —create /dev/md5 —level=5 —raid-devices=3 /dev/sda1 /dev/sdb1 /dev/sdc1 —spare-devices=1 /dev/sdd1

Plus bas je parlerais de l’incidence qui m’a permis de découvrir mdamd plus intelligent que je le pensais. Ce n’est qu’au moment de la récupération de mes données que je me suis aperçu (d’après nmon) que le disque /dev/sdd1 était en fait pas du tout utilisé contrairement aux autres !

En d’autres termes, suite à la lecture de ce mail, j’ai provoqué une catastrophe majeure qui m’a permis d’acquérir des nouvelles petites notions telles que diagnostiquer l’état des disques avec les méta-données SMART, détecter si le système de fichier est corrompus ou pas, etc. Historique des évènements

Quelques minutes plus tard, j’ai trouvé plusieurs fois dans le fichier de log des daemons (/var/log/daemon.log) cet avertissement de la part de smartmontools :

Device : /dev/sdb [SAT], Failed SMART usage Attribute : 184 End-to-End_Error.

L’attribue 184 nommé “End-to-End_Error” est une fonctionnalité des disques de la marque HP. Elle signifie qu’il y a eu des échecs de transfères de données depuis la mémoire tampon vers le disque dur. Cette anomalie a pu être détecté grâce à la gestion de parité. Si le contenu n’est pas identique entre la source et la destination alors il y a un problème. D’après la page kb.acronis.com mon disque indiquait une défaillance imminente !

Naturellement je l’ai donc enlevé :

# mdadm —manage /dev/md5 —set-faulty /dev/sdb1
# mdadm —manage /dev/md5 —remove /dev/sdb1

Les messages en provenance du kernel (/var/log/message.log) témoignent bien mes actions :

Aug 13 18:53:25 nas kernel : [3364000.410213] md : unbind<sdb1>
Aug 13 18:53:25 nas kernel : [3364000.410233] md : export_rdev(sdb1)
Aug 13 19:04:37 nas kernel : [3364671.977243] md : requested-resync of RAID array md5
Aug 13 19:04:37 nas kernel : [3364671.977253] md : minimum _guaranteed_ speed : 1000 KB/sec/disk.
Aug 13 19:04:37 nas kernel : [3364671.977258] md : using maximum available idle IO bandwidth (but not more than 200000 KB/sec) for requested-resync.
Aug 13 19:04:37 nas kernel : [3364671.977266] md : using 128k window, over a total of 390579200k.
Aug 13 19:04:37 nas kernel : [3364671.977281] md : md5 : requested-resync done

L’état du RAID me semblait propre alors une pierre deux coups, je me suis demandé pourquoi ne pas profiter de le redimensionner pour que mdadm comprennent qu’il doit nativement supporter 3 disques et non 4. Ça me permettra par la suite d’ajouter un autre disque en tant que spare.

Quelques minutes de recherches sur Internet m’ont permis de découvrir ce super tutoriel : Reducing the number of devices in a RAID-5.

J’ai donc vérifié la structure du système de fichier, compressé les données et le redimensionné du raid ainsi :

# e2fsck -f /dev/md5
# resize2fs -M -p /dev/md5
# mdadm /dev/md5 —grow —array-size=781158400
# mdadm /dev/md5 —grow —raid-devices=3 —backup-file=/tmp/backup

La suite de ces commandes ont retourné ceci dans le journal du kernel :

Aug 13 21:19:45 nas kernel : [3372780.356336] md5 : detected capacity change from 1199859302400 to 799906201600
Aug 13 21:20:58 nas kernel : [3372852.881333] fuse init (API version 7.23)
Aug 13 21:27:06 nas kernel : [3373220.633925] md : reshape of RAID array md5

Avec près de 350Go de données, j’ai laissé travailler mon serveur toute la nuit. Le lendemain, je découvre que la synchronisation ne s’était pas terminé correctement :

Non seulement il y avait eu un disque qui a lâché en cours de route, mais en plus elle s’est figée à 93,6% de sa progression !!

Du coup, je ne sais pas comment mdadm a géré les bits de parités vu qu’il en réalité deux disques sur les quatre qui ont réellement fonctionné. Néanmois, le disque sda a pu se reconnecter à la nappe entre temps et par moment il partait. Pas super… Bref, j’ai dû laisser tourner pendant une semaine le temps de trouver une solution.

Voici les messages retrouvés dans /var/log/message.log :

Aug 14 05:18:05 nas kernel : [3401479.603045] ata1.00 : configured for UDMA/33
Aug 14 05:18:05 nas kernel : [3401479.603087] sd 1:0:0:0 : [sda] Unhandled sense code
Aug 14 05:18:05 nas kernel : [3401479.603092] sd 1:0:0:0 : [sda]
Aug 14 05:18:05 nas kernel : [3401479.603095] Result : hostbyte=DID_OK driverbyte=DRIVER_SENSE
Aug 14 05:18:05 nas kernel : [3401479.603100] sd 1:0:0:0 : [sda]
Aug 14 05:18:05 nas kernel : [3401479.603103] Sense Key : Medium Error [current] [descriptor]
Aug 14 05:18:05 nas kernel : [3401479.603110] Descriptor sense data with sense descriptors (in hex) :
Aug 14 05:18:05 nas kernel : [3401479.603112] 72 03 11 04 00 00 00 0c 00 0a 80 00 00 00 00 00
Aug 14 05:18:05 nas kernel : [3401479.603127] 02 ef cc 15
Aug 14 05:18:05 nas kernel : [3401479.603134] sd 1:0:0:0 : [sda]
Aug 14 05:18:05 nas kernel : [3401479.603140] Add. Sense : Unrecovered read error - auto reallocate failed
Aug 14 05:18:05 nas kernel : [3401479.603145] sd 1:0:0:0 : [sda] CDB :
Aug 14 05:18:05 nas kernel : [3401479.603148] Read(10) : 28 00 02 ef cc 10 00 00 08 00
Aug 14 05:18:05 nas kernel : [3401479.603723] md/raid:md5 : read error not correctable (sector 49267728 on sda1).
Aug 14 05:18:05 nas kernel : [3401479.603775] ata1 : EH complete
Aug 14 05:34:45 nas kernel : [3402480.077104] md5_reshape D ffff88001b02d888 0 519 2 0x00000000
Aug 14 05:34:45 nas kernel : [3402480.077109] ffff88001b02d430 0000000000000046 0000000000012f40 ffff880000b07fd8
Aug 14 05:34:45 nas kernel : [3402480.077112] 0000000000012f40 ffff88001b02d430 ffff88001b67c810 ffff88001b67c800
Aug 14 05:34:45 nas kernel : [3402480.077115] ffff880000b07b70 ffff88001b67ca18 ffff88001b67c9a8 0000000001f27b10
Aug 14 05:34:45 nas kernel : [3402480.077118] Call Trace :
Aug 14 05:34:45 nas kernel : [3402480.077145] [<ffffffffa0185122>] ? get_active_stripe+0x1d2/0x720 [raid456]

Pour faire court, le kernel dit qu’il y a eu des problèmes de lecture sur le disque sda et que la commande md5_reshape n’a pas pu corriger les erreurs présentes sur les secteurs 49267728 et 49267736 de la partition sda1. Le kernel nous monte également la trace des appels systèmes nous permettant de comprendre explicitement ce qu’il s’est passé. On ne détaillera pas cette partie car on a cerné la plus grosse partie du problème.

Ainsi durant plusieurs soirées, je me suis amusé sur une machine virtuelle à reproduire le problème en simulant diverses pannes. Ça m’a permis de découvrir de nouveaux outils telles que :

• dumpe2fs = il permet d’afficher les informations relatives au système de fichier utilisé
• nmon (option d) = pour visualiser en temps réel les écritures et lecture des disques
• ioping = affiche le temps de latence pour accéder aux disques
• testdisk = Consulte les informations sur le disque. Il permet également de se déplacer dans les dossiers présents sur le disque si toutefois il y a un système de fichier.
• smartctl -a = Utile pour visualiser les attribues du disque. On retrouve notamment le code smart 184 que j’ai expliqué plus haut.

Après de nombreuses tentatives théorique, je remarque sur le NAS le processus md5_raid5 qui ne voulait pas se stopper même avec des méthodes brutales (via le signale SIGKILL). Il était toujours actif et continue à utiliser toutes les ressources processeur…. Peu après, le 17 août, j’ai finalement eu le disque sda qui m’a lâché. J’ai donc décidé d’arrêter totalement la machine et le plus proprement possible malgré ces erreurs persistantes que l’on connaît déjà :

Aug 17 22:36:16 nas kernel : [3722971.314521] md/raid:md5 : read error not correctable (sector 262144 on sda1).
[... même erreur plusieurs fois ...]
Aug 17 22:36:16 nas kernel : [3722971.314552] md/raid:md5 : read error not correctable (sector 262216 on sda1).
Aug 17 23:28:59 nas kernel : [3726133.891191] md : md5 in immediate safe mode
Une histoire qui finit bien

Ce n’est que le 18 août soir (après le boulot) où j’ai simplement exécuté cette commande pour forcer l’assemblage du raid sans qu’il puisse reprendre sa tâche précédente (qui était de retailler le raid) :

# mdadm —assemble —force —freeze-reshape /dev/md5 /dev/sda1 /dev/sdc1 /dev/sdd1 —backup-file=/tmp/

Il me restait plus qu’à le remonter dans un point de montage :

# mount /dev/md5 /mnt

Par la suite, j’ai directement copié tout son contenu sur plusieurs machines (Je ne dispose pas assez d’espace de stockage pour toutes les déplacer à un seul endroit). J’ai pu tout récupérer car il était à 93% de son reshape ce qui m’a permis, à ce jour, de ne pas trouver de fichiers corrompus ou une perte de donnée.

Une fois cette étape terminée, le stress est retombé et je me suis posé des questions sur mes futurs besoins en terme d’espace de stockage. Sachant qu’il y a également ma famille qui compte l’utiliser pour divers usage. Je vais sans doute songer à repérer une nouvelle machine en partant sur du matériel neuf qui fera guise de cadeau pour Noël pour mes parents.

En conclusion, j’espère ne pas avoir dit de bêtise (merci de me le faire savoir dans le cas contraire). Beaucoup de nouveautés pour moi et je me rends compte que le succès de ce projet tenais qu’à un cheveu près… Faites donc attentions aux commandes que vous tapez lorsque vous utilisez le compte root !

@+ !