Cloud Connected

Pendant longtemps j’ai cherché comment uniformiser les logs de mes applications PHP, et plus particulièrement des nombreux scripts en ligne de commande qui s’exécutent régulièrement (oui, je suis un grand fan de PHP en ligne de commande) et des applis web quand elles génèrent une erreur. Pour aller droit au but : j’ai trouvé (mais ça, vous vous en doutiez) et maintenant j’utilise du syslog partout. Mais patience, je vais y venir.

D’abord qu’est-ce que j’entends par “logs” ? Il y a bien sûr tous les messages d’erreurs, que ce soit des erreurs générées par PHP (genre “la base de données ne répond plus”) ou des erreurs générées manuellement (genre “c’est quoi ce bordel je devrais jamais tomber dans ce cas là”). Mais il y a également les messages d’informations sur l’état d’avancement du script en ligne de commande (que personne ne lit mais qui pourront peut-être être utile le jour où le script va faire n’importe quoi) ou encore les messages de debug (pratique pour le développement). Pour les applications web, toutes les erreurs génèrent un code HTTP 500 et une page d’erreur propre pour le client, mais j’aimerais bien pouvoir garder une trace de ce qui a foiré.

Pour un script en ligne de commande

Pour cette partie je vais essayer de détailler le plus possible, mais il vaut mieux être familier avec les systèmes Unix, car cela concerne exclusivement des scripts qui sont exécutés avec la SAPI CLI (plus d’infos dans la doc de PHP).

Affichage standard

Au départ, reflexe de programmeur PHP, j’utilisais simplement les fonctions echo (ou printf), mais ça devient vite un casse-tête de filtrer les messages selon leur niveau d’importance. Et quand le script n’est pas lancé en ligne de commande (par exemple s’il est lancé via une cron), ces messages ne sont plus visibles. Il est cependant possible de les archiver en redirigeant le flux de sortie standard vers un fichier. Mais il faut penser faire la rotation de ce fichier de log manuellement (voir logrotate) et on se retrouve vite avec une multitude de fichiers de log éparpillés sur le disque, ce qui ne facilite pas la maintenance.

Exemple, pouet.php contient :

echo "pouet\n";

On redirige le flux :

$ php pouet.php > /tmp/pouet

Choisir la sortie

Pour améliorer un peu le filtrage des messages d’erreur, on peut utiliser fprintf (voir la doc) et utiliser les constantes STDOUT et STDERR pour envoyer les messages respectivement sur la sortie standard et sur la sortie d’erreur. Il est ainsi possible de rediriger les messages d’erreurs dans un fichier et les messages “standards” (information, debug, etc.) vers /dev/null. C’est un mécanisme très classique, mais c’est bien de savoir que PHP le propose nativement.

Exemple, pouet2.php contient :

fprintf(STDOUT, "un message normal\n");
fprintf(STDERR, "un message d'erreur\n");

On peut rediriger l’un ou l’autre des flux pour filtrer les messages :

$ php pouet.php
un message normal
un message d'erreur
$ php pouet.php 1> /dev/null
un message d'erreur
$ php pouet.php 2> /dev/null
un message normal

Mais avec ce système il a toujours le problème de la maintenance des fichiers de logs. Donc au bout d’un moment j’ai décidé d’abonner mes méthodes de développeur PHP et d’aborder le problème sous un autre angle : comment fait-on dans les autres langages pour développer des scripts propres ? Réponse on utilise syslog, l’outil de log centralisé des systèmes Unix (voir la page sur Wikipedia). “Oui mais PHP c’est fait pour faire du web, l’API n’existe surement pas”, me dis-je naïvement. Et bien comme quoi il en faut pas se fier aux clichés : PHP a fait beaucoup de progrès (je vous parlerais un jour des forks et autres trucs rigolos) et les fonctions syslog existent et fonctionnent très bien !

Syslog

Pour utiliser syslog, il faut d’abord faire appel à define_syslog_variables qui initialise toutes les variables utilisées dans les fonctions syslog et à la fonction openlog qui permet d’ouvrir la connexion avec l’historique système. Ensuite, la fonction syslog permet de logguer une chaine de caractère, tout simplement. Vous trouverez toutes les infos sur les docs des fonctions openlog et syslog.

Exemple :

// au début
define_syslog_variables();
openlog(basename(__FILE__), LOG_PID | LOG_PERROR, LOG_LOCAL0);

// à n'importe quel moment du script
syslog(LOG_ERR, 'Une erreur est survenue');
syslog(LOG_DEBUG, 'Un message de debug');

// à la fin du script, optionnel
closelog();

• Le premier paramètre de openlog est un identifiant qui sera ajouté au début de chaque ligne de log, pour s’y retrouver parmi tous les logs systèmes. En passant basename(__FILE__), j’ajoute systématiquement le nom du fichier PHP.
• L’option LOG_PERROR est très pratique pour le développement car elle permet d’envoyer une copie du message sur la sortie standard.
• Le dernier paramètre de openlog permet de choisir la “facility” des logs. C’est purement du système, alors demandez à votre administrateur système. :-) En général il voudra que vous utilisiez les facility locales LOG_LOCAL0 jusqu’à LOG_LOCAL8 ou éventuellement LOG_USER.
• Le premier paramètre de syslog détermine la priorité du message. Il y en a 8, de LOG_DEBUG (la plus basse) jusqu’à LOG_EMERG (la plus haute) ce qui laisse une grande marche de manœuvre pour classer ses messages.

Ce système possède pas mal d’avantages : les logs sont centralisés dans /var/log/syslog (il est ensuite possible de configurer syslog pour dispatcher les logs dans d’autres fichiers), la rotation est gérée automatiquement (comme tous les autres logs du système), il est possible de filtrer facilement les logs selon le niveau de priorité, et surtout l’utilisation pour le développeur est simple et uniforme dans tous les scripts.

Pour une application web

Une erreur qui se produit quelque part sur mes applications génère automatiquement une erreur HTTP 500 (Internal Server Error) avec une page d’erreur personnalisée. Bon, ça c’est le framework qui gère, et ce n’est pas le sujet de l’article. Donc depuis longtemps mon problème était le suivant : quoi afficher sur cette page pour ne pas donner trop d’infos à l’utilisateur mais en même temps lui donner suffisamment d’infos pour me permettre de comprendre/reproduire l’erreur si besoin ? Si j’affiche simplement “Erreur”, l’utilisateur va me dire “ça marche pas”, et je serais bien avancé. Si j’affiche toutes les informations de debug (par exemple le dump complet de l’exception avec message d’erreur, nom du fichier, numéro de la ligne, backtrace, etc.), ça donne beaucoup trop d’informations sur l’architecture de l’application.

La solution que j’ai choisie est de générer un ID unique pour l’erreur et de logguer avec cet ID toutes les informations qui me seront utiles. Ensuite, j’affiche uniquement cet ID à l’utilisateur, en lui demandant de le fournir pour toute correspondance ultérieure. Il n’y aura plus qu’à rechercher cet ID dans les logs (vive grep) pour retrouver les infos de debug nécessaires.

Pour générer l’ID, j’utilise la fonction uniqid de PHP. Pour logguer, vous l’aurez compris puisque c’est le sujet de cet article, j’utilise syslog. Pourquoi pas MySQL ? Parce que si l’erreur c’est justement que le serveur MySQL est injoignable je suis niqué… Il y a toujours la solution de passer par un fichier, mais il y a tous les problèmes de maintenance évoqués plus haut. Enfin il y a la solution d’envoyer un mail, mais vu que les mails ne sont pas un système très fiable, je préfère ne pas me reposer entièrement dessus (l’application envoit aussi un mail, mais c’est en plus).

Exemple, dans un handler d’erreur fictif :

function handleError($exception)
{
	// log de l'erreur dans syslog
	define_syslog_variables();
	// je ne log pas le PID (ça ne sert à rien)
	openlog('MON_APPLICATION', 0, LOG_LOCAL0);

	$error_id = uniqid();

	syslog(LOG_ERR, sprintf(
		'[%s] %s (file %s, line %s)',
		$error_id,
		$exception->getMessage(),
		$exception->getFile(),
		$exception->getLine()
	));
	closelog();

	// envoyer en plus un mail si besoin

	// afficher le template avec $error_id
}