Tue 23 June 2015
By Rodolphe Quiédeville
• Tags:
application_name
django
logging
postgresql
settings
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.