Le module logging de Python a d’excellentes options pour gérer la taille des logs, notamment le RotatingFileHandler.

Sous Linux, c’est logrotate qui fait le boulot pour le système. C’est performant, ça marche super bien, c’est hyper simple à utiliser, et c’est dispo partout.

Bref, en prod, un petit vi sur /etc/logrotate.d/ton_projet et pouf, on peut demander une rotation en 10 lignes:

/var/www/ton_projet/*.log
{
    size 100K
    daily
    rotate 5
    missingok
    notifempty
}

Y a rien à activer, un cron lance déjà logrotate tous les jours.

Par contre, si votre process utilise systemd pour démarrer, inutile de logger manuellement. Tout ce qui est sur la sortie standard est automatiquement loggué avec rotation et accessible avec un petit journalctl -u ton_process.service --since today.

Bref, attendez encore un peu avant de rajouter logstash à votre stack.

Suite aux superbes articles sur les décorateurs et sur l’écriture des logs en python j’ai voulu mettre en pratique dans mon projet.
C’est là que les ennuis ont commencé !

Objectif :

Créer un décorateur qui me permette de tracer le passage dans certaines méthodes.
Celui-ci doit :

• Être débrayable facilement.
• Récupérer automatiquement le nom de la méthode, sa classe et son module.

Première étape : le logger

Avant toute chose mettons en place l’environnement pour pouvoir tracer en utilisant le module logging.
Pour simplifier les exemples, nous associons un seul handler de type terminal.
La fonction log_debug permet de faire appel au logger pour tracer une information.

logger.py :

import functools
import logging

__DECO_ACTIVATED = True
__logger = None

def init_logger():
    global __logger
    __logger = logging.getLogger()
    __logger.setLevel(logging.DEBUG)
    terminalHandler = logging.StreamHandler()
    terminalHandler.setLevel(logging.DEBUG)
    __logger.addHandler(terminalHandler)

def log_debug(text):
    __logger.debug(text)

Deuxième étape : le décorateur, version basique

Pour commencer, le décorateur débrayable :

logger.py :

def log_decorator(func):
    if not __DECO_ACTIVATED:
        return func

    @functools.wraps(func)
    def wrapped(*args, **kwargs):
        __logger.debug("BEGIN")
        data = func(*args, **kwargs)
        __logger.debug("END")
        return data
    return wrapped

Remarques :

• La fonction est décorée selon la valeur de la variable __DECO_ACTIVATED.
• La fonction wraps du module functools reporte les attributs de la fonction originale sur la version wrappée (dont les docstrings).

Et maintenant un module pour tester ça :

main.py :

import logger

class Generic():
    @logger.log_decorator
    def do_it(self, arg1):
        logger.log_debug(arg1)

if __name__ == "__main__":
    logger.init_logger()
    generic = Generic()
    generic.do_it("NOW")

Et voilà le résultat :

BEGIN
NOW
END

Troisième étape : les noms de module et de fonction

Ces informations se récupèrent facilement, voici la nouvelle version du décorateur :

logger.py :

def log_decorator(func):
    if not __DECO_ACTIVATED:
        return func
    module_name = func.__module__
    func_name = func.__name__

    @functools.wraps(func)
    def wrapped(*args, **kwargs):
        msg = "Module={} Function={}".format(module_name, func_name)
        __logger.debug("BEGIN " + msg)
        data = func(*args, **kwargs)
        __logger.debug("END " + msg)
        return data
    return wrapped

Et maintenant le résultat :

BEGIN Module=__main__ Function=do_it
NOW
END Module=__main__ Function=do_it

Jusqu’ici tout va bien.

Quatrième étape : le nom de la classe

Et c’est maintenant que les choses se corsent !
Tout d’abord, l’objet func que nous manipulons est une fonction et non une méthode de classe :

print(func)

En effet lors de l’exécution du décorateur, la classe en tant qu’objet n’existe pas encore.
Il n’y a pas de lien direct entre la fonction et sa future classe.

Bon nombre de développeurs bien intentionnés nous conseillent d’utiliser self pour déterminer sa classe.

Oui mais :

• Si la fonction n’est pas une méthode, pas de self !
• La classe n’est pas obligatoirement celle de la méthode. Il peut s’agir d’une classe héritée.

Pour s’en convaincre, voici le nouveau décorateur :

logger.py :

def log_decorator(func):
    if not __DECO_ACTIVATED:
        return func
    module_name = func.__module__
    func_name = func.__name__

    @functools.wraps(func)
    def wrapped(*args, **kwargs):
        try:
            class_name = args[0].__class__.__name__
        except IndexError:
            class_name = ""
        msg = "Module={} Class={} Function={}".format(
            module_name, class_name, func_name)
        __logger.debug("BEGIN " + msg)
        data = func(*args, **kwargs)
        __logger.debug("END " + msg)
        return data
    return wrapped

Et maintenant le module de tests :

main.py :

import logger

class Generic():
    @logger.log_decorator
    def do_it(self, arg1):
        logger.log_debug(arg1)

class Specific(Generic):
    @logger.log_decorator
    def do_it(self, arg1):
        super().do_it(arg1)

if __name__ == "__main__":
    logger.init_logger()
    specific = Specific()
    specific.do_it("NOW")

Et le résultat tant attendu :

BEGIN Module=__main__ Class=Specific Function=do_it
BEGIN Module=__main__ Class=Specific Function=do_it
NOW
END Module=__main__ Class=Specific Function=do_it
END Module=__main__ Class=Specific Function=do_it

Et là c’est le drâme, on a perdu la classe Generic ! Mais analysons plutôt l’exécution :

• Appel de la méthode Specific.do_it() vu que l’objet generic est une instance de cette classe.
• Appel de la méthode Generic.do_it() par le biais de l’instruction super().do_it()

Comme prévu, la classe de l’objet self ne change pas que l’on soit dans une méthode de la classe ou de l’une de ses super-classes.

Quatrième étape : autre approche

Ne pouvant déterminer directement la classe d’appartenance de la fonction, essayons de la chercher dans le module.
Pour commencer il nous faut l’objet module alors que nous ne connaissons que son nom.
Le module inspect propose justement ce service grâce à getmodule.
Voici le décorateur modifié :

logger.py :

import inspect

def log_decorator(func):
    if not __DECO_ACTIVATED:
        return func
    module_name = func.__module__
    module_obj = inspect.getmodule(func)
    class_name = "UNKNOWN"
    for key, obj in module_obj.__dict__.items():
        try:
            members = obj.__dict__
            method = members[func.__name__]
            if method == func:
                class_name = key
                break
        except (KeyError, AttributeError):
            pass
    func_name = func.__name__

    @functools.wraps(func)
    def wrapped(*args, **kwargs):
        msg = "Module={} Class={} Function={}".format(
            module_name, class_name, func_name)
        __logger.debug("BEGIN " + msg)
        data = func(*args, **kwargs)
        __logger.debug("END " + msg)
        return data

    return wrapped

Pour rechercher la fonction, le décorateur doit :

• Lister les objets du module.
• Rechercher pour chaque objet le nom de la fonction dans les attributs de celui-ci. Si l’attribut correspond à notre fonction, c’est gagné !

Nous obtenons alors :

BEGIN Module=__main__ Class=UNKNOWN Function=do_it
BEGIN Module=__main__ Class=UNKNOWN Function=do_it
NOW
END Module=__main__ Class=UNKNOWN Function=do_it
END Module=__main__ Class=UNKNOWN Function=do_it

Pas glop ça marche pas !
Regardons le contenu du module avant la recherche :

print(module_obj.__dict__.keys())
dict_keys(['__builtins__', '__name__', '__file__', '__doc__', '__loader__',
           '__cached__', 'logger', '__package__'])

Curieusement les classes n’apparaissent pas, mais c’est tout à fait normal.
Comme vu précédemment, lors de l’exécution du décorateur la classe est en instance de création.
Il faut donc faire cette recherche lors de l’exécution de la fonction wrappée.

Le décorateur devient donc :

logger.py :

def log_decorator(func):
    if not __DECO_ACTIVATED:
        return func
    module_name = func.__module__
    module_obj = inspect.getmodule(func)
    func_name = func.__name__

    @functools.wraps(func)
    def wrapped(*args, **kwargs):
        class_name = "UNKNOWN"
        for key, obj in module_obj.__dict__.items():
            try:
                members = obj.__dict__
                method = members[func.__name__]
                if method == func:
                    class_name = key
                    break
            except (KeyError, AttributeError):
                pass
        msg = "Module={} Class={} Function={}".format(
            module_name, class_name, func_name)
        __logger.debug("BEGIN " + msg)
        data = func(*args, **kwargs)
        __logger.debug("END " + msg)
        return data

    return wrapped

Et le résultat :

BEGIN Module=__main__ Class=UNKNOWN Function=do_it
BEGIN Module=__main__ Class=UNKNOWN Function=do_it
NOW
END Module=__main__ Class=UNKNOWN Function=do_it
END Module=__main__ Class=UNKNOWN Function=do_it

Pas glop 2 le retour !
Faisons appel au débogueur suprême : print

key    = Generic
method = 
func   = 

key    = Specific
method = 
func   = 

Effectivement les références ne correspondent pas, et encore une fois, rien de plus normal.
La fonction d’origine a été wrappée donc celle présente dans le module n’est plus celle d’origine.
Qu’à cela ne tienne, recherchons-là !

Après la déclaration de la fonction wrapped, le décorateur la mémorise dans la variable wrapped_function.
Elle sera utilisée à l’exécution de la fonction.

logger.py :

def log_decorator(func):
    if not __DECO_ACTIVATED:
        return func
    module_name = func.__module__
    module_obj = inspect.getmodule(func)
    func_name = func.__name__

    @functools.wraps(func)
    def wrapped(*args, **kwargs):
        class_name = "UNKNOWN"
        for key, obj in module_obj.__dict__.items():
            try:
                members = obj.__dict__
                method = members[func.__name__]
                if method == wrapped_function:
                    class_name = key
                    break
            except (KeyError, AttributeError):
                pass
        msg = "Module={} Class={} Function={}".format(
            module_name, class_name, func_name)
        __logger.debug("BEGIN " + msg)
        data = func(*args, **kwargs)
        __logger.debug("END " + msg)
        return data

    wrapped_function = wrapped
    return wrapped

Et maintenant le résultat :

BEGIN Module=__main__ Class=Specific Function=do_it
BEGIN Module=__main__ Class=Generic Function=do_it
NOW
END Module=__main__ Class=Generic Function=do_it
END Module=__main__ Class=Specific Function=do_it

Ouf ! Ca marche !

Au menu du prochain épisode : logger la valeur de certains paramètres passés à la fonction décorée.

Xavier O. avec l’aide précieuse de Laurent B.

git log --grep="le truc a chercher"

Comme grep, on peut y adjoindre -i pour le rendre insensible à la casse, et -E pour utiliser des regex PCRE.

Si vous voulez trouver tous les commits dans lequel une chaîne a été retirée ou introduite dans un des fichiers:

git log -S"le truc a chercher"

Et dans ce cas vous voudrez probablement passer aussi -p --color=auto qui va vous permettre d’avoir un diff coloré et mis en contexte pour savoir ce qui a été modifié.

On peut limiter sa recherche dans le temps en utilisant --before et --after. Par exemple, pour chercher dans tous les commits créés après le 1er juillet et jusqu’à il y a 2 semaines:

git log --before="2 weeks ago" --after="2012-07-01" 

Ou alors choisir deux commits et chercher entre ces deux commits:

git log 710f0f..8a5cbc

Ce qui va limiter la recherche à la branche en cours. En parlant de branche, on peut voir les commits qui sont sur une branche et pas l’autre:

git log master..develop

Ici on aura tout ce qui est sur develop qui n’est pas encore mergé dans master. L’inverse est bien sur possible.

Parfois on a besoin de savoir qui est le connard qui a fait ça, et on peut lister les commits d’un utilisateur:

git log --author sam

Ou

git log --author lesametlemax@notremail.com

En fait ça marche même avec une partie du nom.

Les critères ci-dessus peuvent être utilisés en même temps, et les résultats obtenus seront ceux correspondant à au moins un des critères (OU). Mais si vous voulez les commits qui correspondent à tous ces critères (ET), utilisez --all-match.

Tout ça cherche dans l’historique entier, mais si vous êtes plutôt intéressé par certains fichiers en particulier, vous pouvez préciser des paths après --.

git log --author max --before="1 day ago" -- project/settings.py project/settings_local.py

Et oui, ça marche récursivement sur les dossiers.

La plupart du temps les commits juste après les merges ne vous intéresse pas. On peut les ignorer avec –-no-merges.

Enfin si vous avez merdé et que vous pensez avoir perdu quelque chose dans Git, vous pouvez chercher dans le reflog avec --walk-reflogs. Cela vous donnera accès à tous les commits qui ne sont pas sur des branches ou plus accessibles facilement pour une raison ou une autre.

Tout d’abord il faut posséder Firefox. Ensuite téléchargez l’extension Selenium IDE (attention de bien choisir la version IDE, l’autre version étant réservée à un usage orienté serveur).

Une fois tout ça installé ouvrez votre Selenium en allant dans Outils > Selenium IDE. Une boite va apparaitre vous laissant entrer des commandes. En fait Selenium est un automatiseur de tâche, il va simuler vos actions sur le navigateur. L’astuce va donc consister à simuler l’identification de votre profil sur Facebook et de valider.

J’ai fais une copie d’écran pour vous donnez un aperçu de à quoi devra ressembler votre script.

Voyons ces lignes de plus près:

# open ouvre une url
open | http://www.facebook.com 

# waitForVisible va attrendre que l'élément soit afficher avant de continuer
# ici on attend que le bouton Connexion soit affiché avant de remplir le formulaire (on utilise Xpath)
waitForVisible | //input[@value='Connexion']

# type simule l'entrée au clavier dans un champs (input, textarea, etc)
# ici on sélectionne l'élément qui a l'ID pass (le champs mot de passe) et on lui entre la valeur mon_mot_de_passe_facebook
type | id=pass | mon_mot_de_passe_facebook

# type simule l'entrée au clavier dans un champs (input, textarea, etc)
# ici on sélectionne l'élément qui a l'ID email (le champs email) et on lui entre la valeur mon_email_facebook
type | id=email | mon_email_facebook

# submit simule la soumission d'un formulaire
# ici on sélectionne l'élément qui a l'ID login_form (le formulaire dans lequel on rentre ses identifiants Facebook) et on soumet le tout.
submit | id=login_form

# waitForVisible va attrendre que l'élément soit afficher avant de continuer
# ici on attend l'élément qui a l'ID navHome (le bouton accueil) soit affiché, preuve qu'on est bien logué.
waitForVisible | //li[@id='navHome']/a

Vous pouvez télécharger le cas de test ici et l’importer dans votre Selenium: Se loguer sur Facebook avec Selenium

Je n’irais pas plus loin mais sachez que vous pouvez tout faire ou presque avec Selenium en terme d’automation. Pour la connexion à plusieurs comptes facebook vous faites une boucle qui va se connecter aux différents comptes (n’oubliez pas de vous déconnecter) et faire les tâches que vous aurez définis. vous pouvez cliquez sur des likes, ajouter un status, etc. Je vous laisse chercher mais tout est là dans ces quelques lignes, faites marcher vos méninges ;)

Liens utiles:

Attention: Pour faire des boucles vous aurez besoin d’ajouter cette extension à Selenium: https://github.com/darrenderidder/sideflow

La doc Selenium

Il y a beaucoup plus simple, et le plus beau, c’est que Django le propose en natif.

Par default, Django loggue toutes les requêtes SQL dans django.db.backends si DEBUG = True. Il suffit donc de configurer le logger, dans votre settings.py:

import os
import tempfile

LOGGING = {
    'version': 1,
    'disable_existing_loggers': False,
    'formatters': {
        'verbose': {
            'format': '%(levelname)s %(asctime)s %(module)s %(process)d %(thread)d %(message)s'
        },
        'simple': {
            'format': '%(levelname)s %(message)s'
        },
    },
    'handlers': {
        'tempfile': {
            'level': 'DEBUG',
            'class': 'logging.handlers.RotatingFileHandler',
            'formatter': 'verbose',
            'filename': os.path.join(tempfile.gettempdir(), 'django-debug.log'),
        },
        'console':{
            'level':'DEBUG',
            'class':'logging.StreamHandler',
            'formatter': 'simple'
        },
    },
    'loggers': {
        'django.db.backends': {
            'handlers': ['console', 'tempfile'],
            'level': 'DEBUG',
            'propagate': True,
        },
    },
}

Lancez ./manage.py shell:

In [1]: m = Table.objects.filter(title__isnull=False)

In [2]: m
DEBUG (0.018) SELECT "table"."id", "table"."title", "table"."original_title" FROM "table" WHERE "table"."title" IS NOT NULL LIMIT 21; args=()
Out[2]: [< Table object >, < Table object >, < Table object >, < Table object >, < Table object >, < Table object >, < Table object >, < Table object >, < Table object >, < Table object >, < Table object >, < Table object >, < Table object >, < Table object >, < Table object >, < Table object >, < Table object >, < Table object >, < Table object >, < Table object >, '...(remaining elements truncated)...']

Une version plus verbeuse sera aussi logguée dans un fichier temporaire. Par exemple, sous Linux il sera dans /tmp/django-debug.log.

Toutes les requêtes faites par le site Web seront également affichées dans le terminal sur lequel tourne le serveur, et dans le fichier temporaire.

Une fois que vous maitrisez le concept, je vous recommande plutot de mettre le logger django.db.backends dans votre local_settings.py, histoire d’éviter de l’avoir en prod :

LOGGING['loggers'].update({
        'django.db.backends': {
            'handlers': ['console', 'tempfile'],
            'level': 'DEBUG',
            'propagate': True,
        },
    }
)

Autre bénéfice, il suffit de commenter cette partie quand on ne souhaite plus afficher autant d’informations.