Envoi d’un email par logging en cas de plantage d’un script python (ou: comment faire bouffer u”\xe9″ à SMTPHandler) 9


(Ceci est un post invité d’un débutant pour les débutants… sous licence creative common 3.0 unported.)

Il y a peu, je me suis mis à utiliser logging pour debugger mes scripts de débutant.

Si comme moi vous avez l’habitude de mettre des print partout pour trouver l’origine d’un problème, et qu’ensuite vous avez passé de longues longues longues minutes/heures à traquer ces foutus print pour dépolluer la sortie console, jetez un oeil à écrire des logs en python.

Après quelques (minutes/heures/jours) de prise en main (vite, quoi…), on se demande comment on a fait pour s’en passer si longtemps. C’est simple, je n’utilise plus les touches “p”, “r”, “i”, “n” et “t” de mon clavier. Elles sont toutes propres.

En plus, logging m’a ouvert de nouvelles perspectives, parmi lesquelles la possibilité d’envoyer les logs par mail. Pas besoin de tout recevoir par mail, mais si ce foutu script de m%@rde pouvait m’envoyer un email quand il plante avec la source détaillé du problème, ce serait super.

Log post mortem par email

Admettons que vous vouliez vérifier que les pensées qui vous traversent l’esprit sont safe for work. Vous écrivez un script génial qui fait le boulot.

Comme vous commencez à savoir y faire en python, vous avez même écrit votre propre exception à vous tout seul…

class NotSafeForWorkError(Exception):
    """
    Exception soulevée si une pensée est NSFW
    """
    def __init__(self, msg):
        self.msg = u"Danger! %s est NSFW." % msg
 
    def __str__(self):
        return self.msg.encode("utf-8")
 
# liste des pensées proscrites
# (échantillon, elle est beaucoup plus longue que ça en réalité)
NSFW = ["cul", "seins", "sametmax"]
 
# boucle de censure qui soulève une exception si une pensée déconne
for pensee in ["pause", "pipi", "sametmax"]:
    if pensee in NSFW:
        raise NotSafeForWorkError(pensee)
    print u"%s est SFW" % pensee
 
#sortie:
## pause est SFW
## pipi est SFW
## Traceback (most recent call last):
##   File "censure_setm3.py", line 30, in
##     raise NotSafeForWorkError(pensee)
## __main__.NotSafeForWorkError: Danger! sametmax est NSFW.

Ça marche du tonnerre! C’est là que vous vous dites que ce serait bien si le script envoyait le traceback par email à votre psy pour le prévenir que vous avez déconné.

A la maison, vous avez lu l’article de Sam sur les logs post mortem. Ça a l’air facile à faire.

Vous créez d’abord un logger qui enverra les logs de niveau critique par mail:

import logging
from logging.handlers import SMTPHandler
 
nom_loggeur = "test_nsfw"
 
# On crée un logger et on met le niveau à critique:
#  il ne tiendra compte que des logs de ce niveau
logger = logging.getLogger(nom_loggeur)
logger.setLevel(logging.CRITICAL)
 
# On crée le handler en lui passant les paramètres
#  nécessaires à l'envoi d'un email
mail_handler = SMTPHandler(
    # Host et port
    ('SMTP.GMAIL.COM', 587),
    # From
    "MOI@GMAIL.COM",
    # To (liste)
    ["QUELQU.UN@QUELQUE.PART"],
    # Sujet du message
    "Erreur critique dans %s" % nom_loggeur,
    # pour l'authentification
    credentials = ("MONEMAIL@GMAIL.COM", "MONSUPERPASSWORD"),
    secure = ())
 
# On met le handler à "critique".
# Il enverra donc par mail les messages de ce niveau
mail_handler.setLevel(logging.CRITICAL)
 
# On définit un formatter: date, nom du logger, niveau, message
formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
 
# On associe le formatter au handler:
#  c'est lui qui formatera les logs de ce handler
mail_handler.setFormatter(formatter)
 
# ... et on associe le handler au logger:
#  il utilisera ce handler, qui émettra les logs critiques
logger.addHandler(mail_handler)

Ensuite vous redéfinissez sys.excepthook de manière à ce que l’exception soit logguée. La fonction convertit le traceback en string, la loggue au niveau critique et laisse l’exception continuer son chemin.

import sys
 
# la fonction qui remplacera sys.excepthook
def en_cas_de_plantage(type_except, value, tb):
 
    # Traceback permettra de formater l'exception.
    import traceback
 
    # Mise en forme de l'exception. Retourne la trace
    #  sous forme de str avec numéros de lignes et tout
    trace = "".join(traceback.format_exception(type_except, value, tb))
 
    # On loggue l'exception au niveau "critique",
    #  elle sera donc envoyée par email
    logger.critical(u"Erreur inattendue:\n%s", trace)
 
    # ... et on laisse le script se planter...
    sys.__excepthook__(type_except, value, tb)
 
    # on remplace sys.excepthook, et le tour est joué
    sys.excepthook = en_cas_de_plantage

Et voilà. Vous lancez le script, il se casse la gueule dès qu’il rencontre “sametmax”, votre psy reçoit un email avec le traceback, c’est cool.

Sauf que…

SMTPHandler ne gère pas unicode

Si au moment de la création de mail_handler, vous passez comme sujet à SMTPHandler:

u"%s s'est planté" % nom_loggeur

ou que dans votre fonction “en_cas_de_plantage” vous mettez:

logger.critical(u"Bébé a encore glissé dans son caca:\n%s", trace)

… autrement dit si vous avez une chaîne unicode qui ne peut pas être encodée en ascii, ça va pas marcher:

Traceback (most recent call last):
  File "envoie_mail_on_crash.py", line 84, in emit
    smtp.sendmail(self.fromaddr, self.toaddrs, msg)
  File "/Library/Frameworks/Python.framework/Versions/2.7/lib/python2.7/smtplib.py", line 734, in sendmail
    (code, resp) = self.data(msg)
  File "/Library/Frameworks/Python.framework/Versions/2.7/lib/python2.7/smtplib.py", line 501, in data
    self.send(q)
  File "/Library/Frameworks/Python.framework/Versions/2.7/lib/python2.7/smtplib.py", line 321, in send
    self.sock.sendall(str)
  File "/Library/Frameworks/Python.framework/Versions/2.7/lib/python2.7/ssl.py", line 229, in sendall
    v = self.send(data[count:])
  File "/Library/Frameworks/Python.framework/Versions/2.7/lib/python2.7/ssl.py", line 198, in send
    v = self._sslobj.write(data)
UnicodeEncodeError: 'ascii' codec can't encode character u'\xe9' in position 62: ordinal not in range(128)
Logged from file envoie_mail_on_crash.py, line 163

D’où l’on déduit qu’il y a une tentative foirée d’encodage d’une chaîne unicode en ascii par la méthode “write” de ce mystérieux _sslobj, et que c’est une méthode “emit” quelque part dans handlers.py qui lui a passé la chaîne.

Fuck! Investiguons. Et essayons de régler ça par le haut de la pile.

Toi, là au fond! Oui, toi!

C’est la methode emit de SMTPHandler qui est responsable. Elle fait quoi cette méthode? Elle formate le “record”, crée un message et l’envoie à l’adresse mail spécifiée. Voilà le code:

def emit(self, record):
    """
    Emit a record.
 
    Format the record and send it to the specified addressees.
    """
    try:
        import smtplib
        from email.utils import formatdate
        port = self.mailport
        if not port:
            port = smtplib.SMTP_PORT
        smtp = smtplib.SMTP(self.mailhost, port)
 
        # C'est ici l'objet "record" est formatté
        msg = self.format(record)
 
        # Le message est construit ici. Il sera ensuite envoyé par smtp.sendmail
        # C'est là que le bât blesse
        msg = "From: %s\r\nTo: %s\r\nSubject: %s\r\nDate: %s\r\n\r\n%s" % (
                        self.fromaddr,
                        ",".join(self.toaddrs),
                        # Notons ce getSubject(record). La méthode renvoie
                        #  le sujet du message, passé à la création
                        #  de mail_handler
                        self.getSubject(record),
                        formatdate(),
                        # le record formaté
                        msg)
 
        if self.username:
            if self.secure is not None:
                smtp.ehlo()
                smtp.starttls(*self.secure)
                smtp.ehlo()
            smtp.login(self.username, self.password)
 
        # Le mail et envoyé
        smtp.sendmail(self.fromaddr, self.toaddrs, msg)
 
        smtp.quit()
    except (KeyboardInterrupt, SystemExit):
        raise
    except:
        self.handleError(record)

Qu’est-ce qu’il se passe?

Après quelques tests genre:

    msg = self.format(record)
    # C'est pratique parfois un petit print
    print type(msg)
 
##

… on voit que la méthode format (qui structure votre log selon la forme passée à logging.Formatter) retourne un objet de type unicode si le message que vous avez loggué (logger.critical(u"% foiré!", trace)) contient de l’unicode.

Idem pour getSubject(record) qui, en l’état, ne fait que retourner le sujet du email tel que vous l’avez passé à l’instanciation de SMTPHandler.

Donc, quand msg est formaté, si le log ou le message sont en unicode, msg sera en unicode.

WTF!?

J’ai été surpris quand j’ai fini par piger comment ça fonctionne. Même pour un débutant comme moi ça a l’air bête.

J’y connais rien en email, mais il ne m’a pas fallu longtemps pour comprendre que, dans sa forme basique, un email c’est du ascii, point. Et que si on veut envoyer autre chose que du ascii, qui soit décodable de l’autre côté, il faut qu’il y ait les headers appropriés, que le contenu soit encodé, que sais-je encore…

Peut-être un truc programmé par des gars qui ne manipulent jamais autre chose que de l’anglais? Ils auraient essayé d’envoyer un mail en russes ou en suédois, ça se serait planté au premier test. Oui, oui, Sam, la lingua franca, tout ça…

Ou alors c’est pour des questions de compatibilité avec des versions antérieures de python qui ne contiendraient pas les ressources nécessaires pour formater correctement un mail? Aucune idée…

Comment régler ça?

Il mangea u”\xe9″ et il en redemanda

Le module email de la lib standard permet de créer des emails. On trouve dans email.mime une classe MIMEText qui nous conviendra parfaitement. On va donc subclasser SMTPHandler et réécrire la méthode emit pour qu’elle construise un message “RFC-compliant”, comme ils disent dans la doc.

class SMTPHandler_unicode(SMTPHandler):
 
    def emit(self, record):
        try:
            import smtplib
            from email.utils import formatdate
 
            # On importe MIMEText
            from email.mime.text import MIMEText
 
            port = self.mailport
            if not port:
                port = smtplib.SMTP_PORT # 25
            smtp = smtplib.SMTP(self.mailhost, port)
 
            msg = self.format(record)
 
            # Au moment de la création de l'objet par MIMEText,
            #  si msg est de type unicode, il sera encodé
            #  selon _charset, sinon il sera laissé tel quel
            message = MIMEText(msg, _charset = "utf-8")
 
            # On ajoute les headers nécessaires. S'il sont de type unicode,
            #  ils seront encodés selon _charset
            message.add_header("Subject", self.getSubject(record))
            message.add_header("From", self.fromaddr)
            message.add_header("To", ",".join(self.toaddrs))
            message.add_header("Date", formatdate())
 
            if self.username:
                if self.secure is not None:
                    smtp.ehlo()
                    smtp.starttls(*self.secure)
                    smtp.ehlo()
                smtp.login(self.username, self.password)
 
            # Envoi du message proprement encodé
            smtp.sendmail(self.fromaddr, self.toaddrs, message.as_string())
 
            smtp.quit()
        except (KeyboardInterrupt, SystemExit):
            raise
        except:
            self.handleError(record)

Ce qui est intéressant avec MIMEText c’est que si vous déclarez un encodage (_charset = "utf-8"), et que vous passez une chaîne unicode a l’instanciation, il l’encodera selon _charset.

Idem si vous ajoutez un header en appelant add_header, ce qui permet dans notre cas de traiter correctement le sujet du mail.

L’appel à la méthode to_string retournera le message proprement encodé (en base64) pour le transfert, et les headers appropriés seront inclus.

Voilà, il ne reste plus qu’à utiliser cette classe pour créer mail_handler, et le tour est joué.

mail_handler = SMTPHandler_unicode(
    # host et port
    ('SMTP.GMAIL.COM', 587),
    # From
    "MOI@GMAIL.COM",
    # To (liste)s
    ["QUELQU.UN@QUELQUE.PART"],
    # sujet du message
    u"Bonjour Mr Freud. %s a encore repéré des pensées génantes" % nom_loggeur,
    # pour l'authentification
    credentials = ("MONEMAIL@GMAIL.COM", "MONSUPERPASSWORD"),
    secure = () )

Bilan de l’histoire: c’est en débutant qu’on devient débutant…


Télécharger le code de l’article.

9 thoughts on “Envoi d’un email par logging en cas de plantage d’un script python (ou: comment faire bouffer u”\xe9″ à SMTPHandler)

  • YvesD

    Brillant, clair, lumineux.
    Voici mon sunshine de la journée moi qui croule sous la neige
    Yv – un peu moins débutant que ce matin

  • kontre

    Y’a du niveau chez les débutants ici !

    Il me vient tout de me une remarque constructive : comment tu écris “logging” sans les lettres “p”, “r”, “i”, “n” et “t” de ton clavier ? Tu fais des copier-coller des “i” et des “n” ?

    Plus sérieusement, je me tâte à utiliser ça pour faire des rapports d’erreur automatiques. J’ai des collègues qui ne disent jamais quand un programme ne marche pas…

  • Yohann

    merci pour la stuce. Je suis justement en train de transformer mes print en log.

    pour préciser le commentaire du dessus:

    logging.debug
    logging.info
    logging.warning
    logging.error
    logging.c
    ritical

    en fait il ne reste plus que le “p” qui est propre.

  • jalabop

    Merci pour votre article. J’ai trouvé votre article très utile, mais j’ai quelques problèmes avec le sujet du mail. Si j’utilise un fichier externe (par exemple logging.config.fileConfig (‘logging.ini’)) le texte du sujet c’est “Bonjour M. Freud.a Encore tutorat Rà © © © Décembre pense qu’il gà © nantes

    C’est le handler du mon logging.ini:


    [Handler_mail]
    class = handlers.SMTPHandler_unicode
    level = DEBUG
    formatter = form01
    args = (("smtp.server ', 587"), "moi@server.com'
    [QUELQU.UN @ QUELQUE.PART '] u'Bonjour M. Freud.a Encore repéré génantes Décembre Pensées »(« MONEMAIL@GMAIL.COM, «MONSUPERPASSWORD'))

    Si j’utilise votre méthode directement dans un module fonctionne parfaitement. Pourquoi? idée?

    Excusez mon niveau de français. Je l’avais étudié au lycée mais je l’ai oublie completement (merci Google Translator)

Leave a comment

Your email address will not be published. Required fields are marked *

Utilisez <pre lang='python'>VOTRE CODE</pre> pour insérer un block de code coloré

Des questions Python sans rapport avec l'article ? Posez-les sur IndexError.