Utiliser l'application_name de PostgreSQL avec Django

L'utilisation d'un ORM efficace comme celui de Django abstrait la base de données au point de rendre parfois le debug malaisé voire difficile. Il n'est pas souvent évident de remonter jusqu'à la vue qui a généré une requête SQL consommatrice de ressources qui aurait été détectée dans les logs d'un serveur de production. Nous avons déjà pour cela mis en oeuvre chez PeopleDoc une app Django nommée django-sql-log. Dans la suite logique de cette démarche nous allons voir dans ce billet comment enrichir la chaîne de connexion pour ajouter de l'information dans les logs du serveur PostgreSQL.

La libpq de PostgreSQL inclut un paramètre optionnel nommé application_name constitué d'une chaine de caractères laissée à la disposition des développeurs d'application. Il faut entendre ici le mot application dans son sens générique et non pas dans un contexte Django. Cette information, si présente, est consultable dans les logs (au moyen du format %a du paramètre de log_line_prefix), mais également dans des vues systèmes comme pg_stat_activity.

L'utilisation de cette option depuis Django se fait au moyen de l'entrée OPTIONS du dict DATABASES dans les settings comme suit.

DATABASES = {
    'default': {
        'ENGINE': 'django.db.backends.postgresql_psycopg2',
        'HOST': 'localhost',
        'PORT': 5432,
        'NAME': 'foo',
        'USER': 'rodo',
        'PASSWORD': 'neverusetoto',
        'OPTIONS': {'application_name': 'foo'}
    }
},

Le dict OPTIONS est passé tel quel à la bibliothèque psycopg2, mais n'inclut pas encore à ce jour toutes les options possibles de la libpq.

Utilisé de cette manière, tout le code utilisant ces settings signera ses actions dans les logs avec le nom foo.

L'intérêt devient plus évident si vous utilisez un application_name différent pour certaines tâches spécifiques au sein de votre code comme dans une commande de management, vous pouvez en effet surcharger directement les settings dans une commande comme suit :

from django.conf import settings
from django.core.management.base import BaseCommand

class Command(BaseCommand):
    help = 'A real big command'

    def handle(self, *args, **options):
        # toujours le faire au plus tôt avant d'utiliser une QuerySet
        settings.DATABASES['default']['OPTIONS'] = {'application_name': 'expire_all'}
        dothejob()

Ainsi si vous paramétrez vos logs PostgreSQL avec un log_line_prefix de ce type :

djangofoo=# select current_setting('log_line_prefix');
-[ RECORD 1 ]---+----------------------------------------------
current_setting | %t [%p]: [%l-1] user=%u,db=%d,host=%h,app=%a

vous obtiendrez dans les logs les lignes suivantes ; où il devient de suite plus aisé de retrouver l'origine d'un COUNT désastreux.

2015-06-22 20:18:14 CEST [4761]: [14-1]
user=rodo,db=djangofoo,host=::1,app=expire_all LOG:  duration: 7.471 ms
statement: SELECT COUNT(*) FROM "hotel_hotel WHERE town_id=23"
2015-06-22 20:18:21 CEST [4601]: [7-1] user=rodo,db=djangofoo,host=::1,app=[unknown] LOG:  duration: 377.968 ms
statement: SELECT COUNT(*) FROM "hotel_hotel"
2015-06-22 20:19:03 CEST [4809]: [1-1] user=rodo,db=djangofoo,host=[local],app=psql LOG:  duration: 9.583 ms
statement: SELECT COUNT(*) FROM hotel_hotel WHERE closed=true;

Dans ce cas, la première commande a été éxécutée dans la commande manage que l'on a nommée expire_all, la deuxième dans un shell Django (oui il serait judicieux que cela soit plus explicite) et enfin la dernière directement avec le client psql. Sans cette information les 3 commandes ayant été exécutées depuis la même machine avec le même user il aurait été impossible de retrouver nos petits.

Il ne faut pas que cette solution vous dévie toutefois de la meilleure séparation possible en créant des utilisateurs spécifiques suivants les contextes, qui permet non seulement d'identifier la source mais aussi de borner le périmètre d'action afin de se protéger d'éventuelles erreurs applicatives.