Logger les octets transmits par expressjs

Vouloir logger les temps de rendu ou encore le volume de données transmis par requête pour une application nodejs/expressjs peut se révéler compliqué si l'on ne sait pas par quel bout prendre la chaîne des middlewares. L'idée ici est de vous proposer une méthode simple pour tout type de calcul dépendant d'un état pré-requête et post-requête.

Le besoin

Apache dispose de logs bien utiles qui permettent, entre autre, de connaître le status de réponse d'une requête ou encore le volume des données envoyées vers le client, voir, plus récemment, le temps en millisecondes du rendu d'une page.

Avec nodejs/expressjs cette fonctionnalité n'existe pas en standard. Il faut pour l'implémenter utiliser une petite astuce. Ce n'est pas bien sorcier, je vous rassure.

Middleware de base

Dans la mesure où cet article parle d'expressjs, et que vous êtes en train de le lire, je présume que vous êtes habitué au principe de middleware. Normalement un middleware fait partie d'une chaîne de middlewares. La requête entrante est passée au premier qui la traite ou la passe à son suivant, jusqu'à l'épuisement de la chaîne.

L'idée ici est donc de créer un middleware très simple qui va littéralement encadrer la chaine de traitement de sorte à permettre de déterminer un état avant l'émission des données et calculer ainsi les différences en sortie de chaîne (temps, octets envoyés, etc).

Pour cela partons d'un exemple bien stupide que nous initialisons ainsi:

mkdir test; cd test
npm install express

Puis dans le dossier, créez un fichier index.js que nous remplissons comme suit :

var express = require('express')
var app = express()

app.get('/', function (request, response) {
  console.log("j'envoie...");
  response.send('coucou')
})

var server = app.listen(3000, function () {
  var host = server.address().address;
  var port = server.address().port;
  console.log('ça écoute sur %s:%s', host, port)
})

Là, de base, notre exemple une fois lancé va afficher son coucou dés que l'on ira sur http://localhost:3000. Ajoutons maintenant notre middleware de log.

var express = require('express')
var app = express()

app.use(function(request, response, next) {
  console.log('Je log');
  if (typeof next === 'function') next();
});

app.get('/', function (request, response) {
  console.log("j'envoie...");
  response.send('coucou')
})

var server = app.listen(3000, function () {
  var host = server.address().address;
  var port = server.address().port;
  console.log('ça écoute sur %s:%s', host, port)
})

Encadrement de la chaîne de middlewares

À l'exécution de l'exemple précédent, le message Je log va arriver avant que le message J'envoie... ne vous parvienne. Aucun intérêt dans notre cas car à ce stade, rien n'a été envoyé et nous ne pourrons donc avoir ni le nombre d'octets émis, ni le code de statut de la page. Pas de souci, une petite modification va inverser la situation.

var express = require('express')
var app = express()

app.use(function(request, response, next) {
  var end = response.end;
  response.end = function() {
    end.apply(this, arguments);
    console.log('Je log');
  }
  if (typeof next === 'function') next();
});


app.get('/', function (request, response) {
  console.log("j'envoie...");
  response.send('coucou')
})

var server = app.listen(3000, function () {
  var host = server.address().address;
  var port = server.address().port;
  console.log('ça écoute sur %s:%s', host, port)
})

L'astuce est simple, nous allons écraser au début du traitement (car notre middleware est le premier de la chaîne) la fonction response::end qui est invoquée par expressjs au moment de libérer le socket. Bien évidement avant de l'écraser, nous la sauvegardons dans une variable locale au middleware. Nous l'invoquerons ensuite dynamiquement via end.apply(this, arguments) lorsque notre end sera appelé pour qu'expressjs n'y voit que du feu.

La trace en console est collée juste après cet appel de sorte à ce que si nous lançons maintenant l'exemple, le message Je log arrive bien après j'envoie.

middleware final

C'est presque gagné, il ne nous reste plus qu'à coder les statistiques.

Notez que vous devez en plus installer le paquet microtime pour que ce qui suit fonctionne.

var express = require('express')
var microtime = require('microtime');
var app = express()

app.use(function(request, response, next) {
  var end = response.end;
  request.stats = {
    temps: microtime.now(),
    octets: request.socket.bytesWritten
  }
  response.end = function() {
    end.apply(this, arguments);
    var octets = request.socket.bytesWritten-request.stats.octets;
    var temps = microtime.now()-request.stats.temps;
    console.log('Octets envoyés : %d', octets);
    console.log('Temps pris     : %d', temps);
    console.log('Code de retour : %d', response.statusCode);
  }
  if (typeof next === 'function') next();
});

app.get('/', function (request, response) {
  console.log("j'envoie...");
  response.send('coucou')
})

var server = app.listen(3000, function () {
  var host = server.address().address;
  var port = server.address().port;
  console.log('ça écoute sur %s:%s', host, port)
})

Et voilà, nous avons à chaque exécution de requête, le nombre d'octets envoyés, le temps pris en microsecondes, et le code de retour. Le principe a été d'ajouter en plus de l'écrasement de la fonction request::end un bloc de données stats que l'on colle directement à l'objet request. Son objectif est de permettre la différence d'état avant/après (surtout pour le temps, car logiquement, le nombre d'octets est toujours 0).

Ensuite dans notre fonction end, et après avoir exécuté la fonction end d'expressjs on effectue nos petits calculs et on affiche les résultats.

Conclusion

Il est possible d'aller bien plus loin dans les données collectées. L'objet Socket dispose notamment des données lues (champ bytesRead). Perso, j'ai simulé ainsi les logs apache (access.log) de sorte à permettre à mes applications d'être analysés par des outils comme awstats. C'est ce qui m'a donné l'idée de partager cette astuce.