Mariadb s'est arreté sans raison apparente et ne redémare pas

Support Debian
#1

Bonjour,
J’ai un petit serveur à la maison qui n’est pas très chargé, mais qui m’amuse bien en plus de servir le son et les vidéos dans la maison.
Mon bricolage du moment est avec des arduinos et ESP, j’envoie la température… via http sur le réseaux local, pour enregistrer tout cela dans une base de données sur le serveur.
Tout marchait bien, et hier je n’ai que changé une page PHP (rien de méchant, juste ajouté une requete pour sauver les données d’un nouveau capteur. C’est un copier coller de la requete habituelle, avec juste un indice qui change (indice lié à une valeur dans une table de la bdd).

Ce matin je vois que les enregistrements ne marchent plus, que je ne peux même pas me logger à phpmyadmin… Je regarde et je vois que mariadb est arrêté. :thinking:

Je tente de relancer, sans succès, j’en profite pour faire une mise à jour (mais rien à mettre à jour c’était déjà propre). Je peux me le permettre, alors je reboote, mais mariadb refuse toujours de démarer
Voici le log

root@server:~# systemctl status mariadb.service
mariadb.service - MariaDB 10.5.12 database server
 Loaded: loaded (/lib/systemd/system/mariadb.service; enabled; vendor preset: enabled)
 Active: failed (Result: exit-code) since Wed 2022-02-09 11:17:53 CST; 3min 2s ago
   Docs: man:mariadbd(8)
         https://mariadb.com/kb/en/library/systemd/
Process: 403 ExecStartPre=/usr/bin/install -m 755 -o mysql -g root -d /var/run/mysqld (code=exited, status=0/SUCCESS)
Process: 439 ExecStartPre=/bin/sh -c systemctl unset-environment _WSREP_START_POSITION (code=exited, status=0/SUCCESS)
Process: 441 ExecStartPre=/bin/sh -c [ ! -e /usr/bin/galera_recovery ] && VAR= ||   VAR=`cd /usr/bin/..; /usr/bin/galera_recovery`; [ $? -eq 0 ]   && systemctl se>
Process: 526 ExecStart=/usr/sbin/mariadbd $MYSQLD_OPTS $_WSREP_NEW_CLUSTER $_WSREP_START_POSITION (code=exited, status=1/FAILURE)
Main PID: 526 (code=exited, status=1/FAILURE)
 Status: "MariaDB server is down"
    CPU: 518ms

févr. 09 11:17:28 server systemd[1]: Starting MariaDB 10.5.12 database server...
févr. 09 11:17:44 server mariadbd[526]: 2022-02-09 11:17:44 0 [Note] /usr/sbin/mariadbd (mysqld 10.5.12-MariaDB-0+deb11u1) starting as process 526 ...
févr. 09 11:17:53 server systemd[1]: mariadb.service: Main process exited, code=exited, status=1/FAILURE
févr. 09 11:17:53 server systemd[1]: mariadb.service: Failed with result 'exit-code'.
févr. 09 11:17:53 server systemd[1]: Failed to start MariaDB 10.5.12 database server.
root@server:~#

Je ne vois pas comment investiguer l’affaire, il n’y a vraiment pas grand chose dans ce log.

root@server:~# journalctl -xe
févr. 09 11:40:35 server systemd[1]: mariadb.service: Main process exited, code=exited, status=1/FAILURE
░░ Subject: Unit process exited
░░ Defined-By: systemd
░░ Support: https://www.debian.org/support
░░ 
░░ An ExecStart= process belonging to unit mariadb.service has exited.
░░ 
░░ The process' exit code is 'exited' and its exit status is 1.
févr. 09 11:40:35 server systemd[1]: mariadb.service: Failed with result 'exit-code'.
░░ Subject: Unit failed
░░ Defined-By: systemd
░░ Support: https://www.debian.org/support
░░ 
░░ The unit mariadb.service has entered the 'failed' state with result 'exit-code'.
févr. 09 11:40:35 server systemd[1]: Failed to start MariaDB 10.5.12 database server.
░░ Subject: L'unité (unit) mariadb.service a échoué
░░ Defined-By: systemd
░░ Support: https://www.debian.org/support
░░ 
░░ L'unité (unit) mariadb.service a échoué, avec le résultat failed.
root@server:~#

Pourriez-vous m’orienter?
Bonne journée

#2

Bonjour

EDIT : Dans ce message, j’avais fait une erreur de conversion dans les fuseaux horaires.
Donc, ne pas tenir compte de ce message.

Bizarre : tu as envoyé ce message le **mercredi 9 février à 04:41 CET** et la date la plus récente citée dans les messages retournés par les lignes de commandes que tu as entrées est : `févr. 09 11:17:28` et dans un autre message, on peut lire : `… Wed 2022-02-09 11:17:53 CST …` (CST <=> Central Standard Time)
Au moment où j'ecris ce message, la date/heure est : `mardi 8 février 2022 22:28:34 CST` ce qui correspond à ; `mercredi 09 février 2022 04:28:34 UTC` et à : `mercredi 09 février 2022 05:28:34 CET` (heure en France)

Donc :

  • soit tu nous envoyé ce message depuis le futur, et dans ce cas, ça m’intéresserait vraiment, mais vraiment beaucoup de savoir comment tu as pu faire ça,

  • ou alors, c’est ta machine qui n’est pas à l’heure, mais ça, ça m’intéresse beaucoup moins parce que je sais déjà comment le faire.

1 J'aime
#3

Il y a une 3ème solution, bien plus simple.
Je ne suis pas dans le même fuseau horaire que le serveur de Debian-fr…

Tu peux même te faire une idée d’ou le suis.
En tout cas, mon problème ne vient pas de là :expressionless: Ça aurait été bien.

#4

Bonjour,
juste une idée :
Tu as de la place sur tes disques durs ?

#5

Oui, 35% d’utilisé sur la racine, ou il y a /var/www… and /var/lib/mysql/
J’ai vérifié c’est bien le chemin pour le stockage des bdd.

Ça valait le coup de vérifier.

#6

Bonjour,

Il faut regarder les logs dans /var/log/mysql/error.log

#7

Je viens de tenter de relancer mysql comme cela je repère facilement tous les logs liés au redémarrage. Voici le résultat

2022-02-09 16:30:34 0 [Note] InnoDB: Uses event mutexes
2022-02-09 16:30:34 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2022-02-09 16:30:34 0 [Note] InnoDB: Number of pools: 1
2022-02-09 16:30:34 0 [Note] InnoDB: Using generic crc32 instructions
2022-02-09 16:30:34 0 [Note] mariadbd: O_TMPFILE is not supported on /tmp (disabling future attempts)
2022-02-09 16:30:34 0 [Note] InnoDB: Using Linux native AIO
2022-02-09 16:30:34 0 [Note] InnoDB: Initializing buffer pool, total size = 134217728, chunk size = 134217728
2022-02-09 16:30:34 0 [Note] InnoDB: Completed initialization of buffer pool
2022-02-09 16:30:34 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=2491278908,2491278908
2022-02-09 16:30:34 0 [ERROR] InnoDB: Malformed log record; set innodb_force_recovery=1 to ignore.
2022-02-09 16:30:34 0 [Note] InnoDB: Dump from the start of the mini-transaction (LSN=2491278912) to 100 bytes after the record: len 100; hex 6b6f1cb508000101d6c3000c00b3000056c3000c00a04b031c002f000000004c56e03e000001f9023704726f6f740203045a5eed4704397b226c616e67223a226672222c22636f6c6c6174696f6e5f636f6e6e656374696f6e223a22757466386d62345f; asc ko              V     K   /    LV >     7 root   Z^ G 9{"lang":"fr","collation_connection":"utf8mb4_;
2022-02-09 16:30:34 0 [Warning] InnoDB: Log scan aborted at LSN 2491343872
2022-02-09 16:30:34 0 [ERROR] InnoDB: Plugin initialization aborted with error Generic error
2022-02-09 16:30:34 0 [Note] InnoDB: Starting shutdown...
2022-02-09 16:30:34 0 [ERROR] Plugin 'InnoDB' init function returned error.
2022-02-09 16:30:34 0 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed.
2022-02-09 16:30:34 0 [Note] Plugin 'FEEDBACK' is disabled.
2022-02-09 16:30:34 0 [ERROR] Unknown/unsupported storage engine: InnoDB
2022-02-09 16:30:34 0 [ERROR] Aborting

Je suppose, d’après cette partie qu’il y a un problème de log
[ERROR] InnoDB: Malformed log record; set innodb_force_recovery=1 to ignore.
Donc si j’arrive à vider le log pour repartir sur un fichier vierge ça devrait être bon. En même temps, c’est surprenant que le ignore ne suffise pas.

Une question du coup. Y a t il d’autres logs que ceux dans /var/log/mysql/ , Ou suffirait-il de les effacer? Avez-vous une opinion? Je vais renomer le dossier mysql en mysql-back pour essayer, mais je ne voudrais pas qu’il y ait des conséquences à long terme…

#8

Mon test de renomer le fichier des logs pour forcer le départ sur un fichier vierge ne marche pas…

Il y a aussi le message suivant qui me surprend.

mariadbd: O_TMPFILE is not supported on /tmp (disabling future attempts)
#9

Cette erreur ne concerne pas le fichier de log au sens où tu l’entends mais indique une corruption des données.

Il faut ajouter innodb_force_recovery = 1 sous la section [mysqld] de ton fichier /etc/mysql/mariadb.conf.d/50-server.cnf
Redémarrer le service, et suivre la procédure indiquée en bas du document en lien « Fixing things »

#10

C’est juste une information pas une erreur. Probablement parce que tu as monté /tmp en tmpfs Cela n’empêche pas mariadb de fonctionner.

#11

Merci, J’essaye ça… En espérant que le niveau 2 suffira.

#12

Clairement c’est insufisant, ou c’est que j’ai mal fait.

Voici ce que j’ai mis:

# this is only for the mysqld standalone daemon
[mysqld]
innodb_force_recovery = 1

#
# * Basic Settings
#

Peux-tu me confirmer que je ne fais pas de bêtise?

#13

Oui, mais Discourse gère les fuseau horaire et c’est lui qui indique l’heure à laquelle le message est publié, du coup, ta troisième solution n’est pas possible. Vérifie quand même que ta machine est bien à l’heure (ou que tu n’utilises pas une connexion IPoT).

#14

Je suis en chine, donc j’utilise en VPN pour pouvoir me connecter au site, Je pense que ça perturbe Discourse qui se trompe sur mon lieu réel…

#15

C’est correct. Est-ce que tu as toujours les mes erreurs dans les logs (error.log) avec les valeurs 1 et 2 ?
Est-ce que tu as une sauvegarde logique (dump) de tes bases de données ?

#16

Oui, même chose jusqu’au niveau 4. Je pense que c’est bien cassé.
Je n’avais pas de sauvergarde car juste pour jouer un peu. Je dois bien avoir quelque vielles sauvegardes, mais rien de bien fondamental. Je vais juste perdre le setting de quelques vieux projets.

Je suppose que le plus simple est de purger Mariadb et de reinstaller complètement…
As tu une autre proposition?

#17

Je te propose de supprimer les fichiers suivants (en root ou avec sudo):

rm -i /var/lib/mysql/ib*"

puis de tenter un démarrage de mariadb.

#18

EDIT : Dans ce message, je persistais dans mon erreur de conversion de fuseaux horaires, donc, ne pas tenir compte de ce message.

Et non, cette possibilité n'en est pas une, puisque la date/heure retournée par le message d'erreur cité dans tes messages est antérieure de plus de 14 heures à la date/heure à laquelle ton message a été reçu sur ce forum. J'ai donné, dans mon précédent message, des dates/heures en précisant le fuseau horaire correspondant (CST UTC et CET) et, à moins de voyager dans le temps, il n'existe aucun [fuseau horaire dans le monde](https://www.reveil-en-ligne.com/carte-des-fuseaux-horaires/monde.html) qui puisse indiquer au même instant une date/heure heure postérieure à l'heure UTC+12 et antérieure à l'heure UTC-12 Ton message a été reçu `mercredi 9 février 2022 04:41 CET` (heure locale en France <=> UTC+1) ce qui correspond à : `mercredi 9 février 2022 03:41 UTC` (heure UTC <=> Coordinated Universal Time) ce qui correspond à : `mercredi 9 février 2022 11:41 CST` (heure locale à Shanghai <=> UTC+8) Dans un des messages d'erreur que tu nous as copié/collé, on peut lire une date/heure basée sur le fuseau horaire (CST <=> UTC+8) `Wed 2022-02-09 11:17:53 CST` dont la date/heure équivalente en heure UTC est : `Mercredi 9 février 2022 18:17:53 UTC` et la date/heure équivalente en France est : `Mercredi 9 février 2022 19:17:53 CET` alors que ton message a été reçu sur ce forum le : `Mercredi 9 février 2022 à 04:41 CET`

J’en conclu que ton message d’erreur a été créé sur ta machine dans le futur.

Donne le retour de la ligne de commande suivante : 
timedatectl
#19

Je n’ai pas suivi cette histoire de problème de date, mais c’est une piste pour expliquer la corruption de la base de données. Donc à éclaircir.

#20

Il y a une confusion dans l’horaire et les timezones.
CST Chine Standard Time est effectivement UTC+8
Donc UTC est 8 heures de moins que CST
Donc Mercredi 11:17 CST est Mercredi 03:17 UTC
Je vous assure qu’en ce moment il est bien 20:40 à Shanghai alors que c’est l’après midi en France…