(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.
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
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…
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.critical
en fait il ne reste plus que le “p” qui est propre.
Merci les gars! Heureux que ça plaise!
@ kontre et Yohann
Chipoteurs, va. Le “p” propre, c’est déjà ça…
Ben écoute, quand un article est bon, on est bien obligé de se rattraper sur des chipotages…
Merci pour cet article, j’ai besoin de cette fonction en ce moment et ça m’aide beaucoup !
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)
You can carry on in english if you need.
En attendant, je te demande de reformater ton poste selon cette forme :
http://sametmax.com/template-de-demande-daide-en-informatique/
Car je n’ai pas compris le problème.