CDuv Blog

Après avoir installé et configuré logrotate sur son serveur il peut arriver de recevoir des courriels de cron contenant le message (visiblement d'erreur) suivant :

/etc/cron.daily/logrotate:
gzip: stdin: file size changed while zipping

N'arrivant pas à chaque fois et sans vraiment plus d'informations que ça : on recevra ce message encore quelques fois avant de se décider à faire quelque chose...

Le sujet du courriel "test -x /usr/sbin/anacron || ( cd / && run-parts --report /etc/cron.daily )" nous indique que c'est un script présent dans /etc/cron.daily qui a rencontré/soulevé le problème, mais si on regarde le corps on a même mieux : le script quotidien de logrotate est en cause.
Le message en lui même semble indiquer qu'un flux (stdin) en cours de compression par gzip a changé de taille (file size changed while zipping) et que ça ne lui a pas plus (et on le comprends).

Dis m'en plus

Le problème est que le courriel ne contient que ce qui a été "affiché" (STDIN) par le script /etc/cron.daily/logrotate lors de son exécution par run-parts et c'est pas beaucoup.
On va donc le forcer à nous en dire plus en modifiant le script qui est actuellement (version 3.8.1-4) comme suit :

#!/bin/sh

test -x /usr/sbin/logrotate || exit 0
/usr/sbin/logrotate /etc/logrotate.conf

On voit que le gros du procédé est fait par /usr/sbin/logrotate qui, heureusement pour nous, accepte un paramètre "--verbose" le rendant plus prolixe :

#!/bin/sh

test -x /usr/sbin/logrotate || exit 0
/usr/sbin/logrotate --verbose /etc/logrotate.conf

A partir de cet instant, notre script quotidien de rotation de journaux indiquera pas à pas ses actions et avec un peu de chance, le problème se reproduira la prochaine fois nous permettant de le localiser :

/etc/cron.daily/logrotate:
reading config file /etc/logrotate.conf
including /etc/logrotate.d
[...]
reading config file samba

Handling 15 logs

rotating pattern: /var/log/apache2/*.log
weekly (52 rotations)
[...]
rotating pattern: /var/log/samba/log.nmbd weekly (7 rotations)
empty log files are not rotated, old logs are removed
considering log /var/log/samba/log.nmbd
log needs rotating
rotating log /var/log/samba/log.nmbd, log->rotateCount is 7
dateext suffix '-20130915'
glob pattern '-[0-9][0-9][0-9][0-9][0-9][0-9][0-9][0-9]'
renaming /var/log/samba/log.nmbd.7.gz to /var/log/samba/log.nmbd.8.gz (rotatecount 7, logstart 1, i 7),
renaming /var/log/samba/log.nmbd.6.gz to /var/log/samba/log.nmbd.7.gz (rotatecount 7, logstart 1, i 6),
renaming /var/log/samba/log.nmbd.5.gz to /var/log/samba/log.nmbd.6.gz (rotatecount 7, logstart 1, i 5),
renaming /var/log/samba/log.nmbd.4.gz to /var/log/samba/log.nmbd.5.gz (rotatecount 7, logstart 1, i 4),
renaming /var/log/samba/log.nmbd.3.gz to /var/log/samba/log.nmbd.4.gz (rotatecount 7, logstart 1, i 3),
renaming /var/log/samba/log.nmbd.2.gz to /var/log/samba/log.nmbd.3.gz (rotatecount 7, logstart 1, i 2),
renaming /var/log/samba/log.nmbd.1.gz to /var/log/samba/log.nmbd.2.gz (rotatecount 7, logstart 1, i 1),
renaming /var/log/samba/log.nmbd.0.gz to /var/log/samba/log.nmbd.1.gz (rotatecount 7, logstart 1, i 0),
old log /var/log/samba/log.nmbd.0.gz does not exist
renaming /var/log/samba/log.nmbd to /var/log/samba/log.nmbd.1
creating new /var/log/samba/log.nmbd mode = 0644 uid = 0 gid = 0
running postrotate script
compressing log with: /bin/gzip
gzip: stdin: file size changed while zipping
removing old log /var/log/samba/log.nmbd.8.gz
[...]

Bingo : on retrouve notre "file size changed while zipping", c'est donc avec les journaux de samba (dans mon cas) que le problème se pose.

Connu ?

En cherchant un peu sur Internet, je suis tombé sur un article de distrosfaqs "Logrotate: File Size Changed While Zipping" citant à la fois logrotate, la compression et samba mais ne donnait pas vraiment de reponse.
Finalement je suis tombé sur ce bugreport Debian "logrotate: file size changed while zipping" qui, bien que concernant Prosody, m'a conduit dans la bonne direction :

Looks like Prosody does not immediately close the old log file before it is compressed.

Upstream recently added delaycompress option to logrotate:
http://hg.prosody.im/debian/rev/b3998cd5c1b9

Le producteur de journaux serait encore en train d'écrire dedans alors que logrotate le compresse : Ça colle avec ce qu'on avait trouvé plus haut.
Mais il y a mieux : Le bugreport indique que l'author de Prosody a corrigé son script pour y ajouter l'option logrotate delaycompress :

diff -r 7ead6ae15c3c -r b3998cd5c1b9 prosody.logrotate
--- a/prosody.logrotate	Sat May 04 19:50:19 2013 +0100
+++ b/prosody.logrotate	Tue May 28 21:11:51 2013 +0200
@@ -2,6 +2,7 @@
 	daily
 	rotate 14
 	compress
+	delaycompress
 	create 640 prosody adm
 	postrotate
 		/etc/init.d/prosody reload > /dev/null

Renseignement pris (grâce à man logrotate) delaycompress, permet de :

Postpone compression of the previous log file to the next rotation cycle. This only has effect when used in combination with compress. It can be used when some program cannot be told to close its logfile and thus might continue writing to the previous log file for some time.

Retarder la compression est une fonctionnalité proposée par logrotate qui pouvoir résoudre le problème (laissant environ 24 heures au programme pour arrêter d'écrire dans le fichier de log)

Correction du problème

Après vérifications le script gérant les journaux de samba (/etc/logrotate.d/samba) n'utilise pas l'option delaycompress, tout comme (/etc/logrotate.d/munin-update d'ailleurs.
Il suffit juste de le rajouter (en dessous de compress) et d'attendre pour constater que le problème ne se reproduit plus (et que les journaux continuent bien d'être "tournés" : très important ça) 🙂

La commande suivante, devrait vous lister tous les scripts de rotation qui compressent (compress présent) mais sans faire retarder (pas de delaycompress) :

grep -l -R -E "\Wcompress" . | xargs grep -L "delaycompress"

Sans prétentions elle n'est clairement pas à l'abri de problèmes puisqu'un fichier de rotation peut contenir plusieurs blocs de configuration différents (et l'un peut présenter compress+delaycompress tandis que l'autre uniquement compress) mais ça permet de dégrossir un peu.

Étiquettes : cron, gzip, logrotate