From 579a9ab735f05003906ead1f45acfe6ca21e4d77 Mon Sep 17 00:00:00 2001 From: Iacopo Spalletti Date: Wed, 19 Oct 2016 20:13:17 +0200 Subject: [PATCH] Aggiungi log verboso. Di defaul attivo per il momento --- .gitignore | 1 + config/email.cnf.sample | 3 + jorvik/settings.py | 21 ++++ log/.directory | 0 posta/cron.py | 2 +- posta/models.py | 207 ++++++++++++++++++++++++---------------- 6 files changed, 149 insertions(+), 85 deletions(-) create mode 100644 log/.directory diff --git a/.gitignore b/.gitignore index b758f31b5..ab10dc3b0 100755 --- a/.gitignore +++ b/.gitignore @@ -11,3 +11,4 @@ assets/ /*.sql .sass-cache .venv +/log/debug.log diff --git a/config/email.cnf.sample b/config/email.cnf.sample index 37b1d3eb4..4b1ac203e 100755 --- a/config/email.cnf.sample +++ b/config/email.cnf.sample @@ -11,6 +11,9 @@ backend = django.core.mail.backends.filebased.EmailBackend # Configurazione +# Attivare il log di debug +log_debug = 1 + ## FILE file_path = /tmp/mail/ diff --git a/jorvik/settings.py b/jorvik/settings.py index c369d3f1d..63743a7ba 100755 --- a/jorvik/settings.py +++ b/jorvik/settings.py @@ -158,13 +158,32 @@ 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': { 'console': { 'level': 'DEBUG', 'class': 'logging.StreamHandler', + 'formatter': 'simple' + }, + 'file': { + 'level': 'DEBUG', + 'class': 'logging.FileHandler', + 'filename': os.path.join(BASE_DIR, 'log/debug.log'), }, }, 'loggers': { + 'posta.models': { + 'handlers': ['file'], + 'level': 'DEBUG', + 'propagate': True, + }, 'two_factor': { 'handlers': ['console'], 'level': 'INFO', @@ -214,6 +233,8 @@ EMAIL_SSL_KEYFILE = EMAIL_CONF.get('email', 'ssl_keyfile') EMAIL_SSL_CERTFILE = EMAIL_CONF.get('email', 'ssl_certfile') +POSTA_LOG_DEBUG = EMAIL_CONF.getboolean('email', 'log_debug', fallback=True) + DEFAULT_FROM_EMAIL = 'Gaia ' GRAVATAR_DEFAULT_IMAGE = 'identicon' diff --git a/log/.directory b/log/.directory new file mode 100644 index 000000000..e69de29bb diff --git a/posta/cron.py b/posta/cron.py index 2c03d271e..dd7e52a0c 100644 --- a/posta/cron.py +++ b/posta/cron.py @@ -5,7 +5,7 @@ class CronSmaltisciCodaPosta(CronJobBase): - RUN_EVERY_MINS = 5 + RUN_EVERY_MINS = 1 schedule = Schedule(run_every_mins=RUN_EVERY_MINS) code = 'posta.smaltisci' diff --git a/posta/models.py b/posta/models.py index 44f97a280..3286a9f91 100755 --- a/posta/models.py +++ b/posta/models.py @@ -1,11 +1,15 @@ """ Questo modulo definisce i modelli del modulo di Posta di Gaia. """ +import logging + from smtplib import SMTPException, SMTPResponseException, SMTPServerDisconnected, SMTPRecipientsRefused from django.core.mail import send_mail, EmailMessage, EmailMultiAlternatives, get_connection from django.db.models import QuerySet +from django.db.transaction import atomic from django.template import Context from django.template.loader import get_template +from django.utils.encoding import force_text from django.utils.html import strip_tags from base.models import * @@ -13,9 +17,13 @@ from social.models import ConGiudizio from lxml import html +logger = logging.getLogger(__name__) + class Messaggio(ModelloSemplice, ConMarcaTemporale, ConGiudizio, ConAllegati): + logging = getattr(settings, 'POSTA_LOG_DEBUG', False) + SUPPORTO_EMAIL = 'supporto@gaia.cri.it' SUPPORTO_NOME = 'Supporto Gaia' NOREPLY_EMAIL = 'noreply@gaia.cri.it' @@ -134,6 +142,8 @@ def invia(self, connection=None, utenza=False): plain_text = strip_tags(self.corpo) successo = True + if self.logging: + logger.debug('[POSTA] MSG %s: Inizio' % (self.pk,)) # E-mail al supporto if not self.oggetti_destinatario.all().exists(): try: @@ -148,109 +158,133 @@ def invia(self, connection=None, utenza=False): ) msg.attach_alternative(self.corpo, "text/html") msg.send() - except SMTPException: + except SMTPException as e: + if self.logging: + logger.debug('[POSTA] MSG %s: errore grave %s' % (self.pk, e)) successo = False # E-mail a delle persone + if self.logging: + logger.debug('[POSTA] MSG %s: Destinatari=%d' % (self.pk, self.oggetti_destinatario.filter(inviato=False).count())) for d in self.oggetti_destinatario.filter(inviato=False): - destinatari = [] - if hasattr(d, 'persona') and d.persona and d.persona.email: - destinatari.append(d.persona.email) - if hasattr(d.persona, 'utenza') and d.persona.utenza and d.persona.utenza.email: - if utenza and d.persona.utenza.email != d.persona.email: - destinatari.append(d.persona.utenza.email) - - # Non diamo per scontato che esistano destinatari - if destinatari: - # Assicurati che la connessione sia aperta - connection.open() - - # Evita duplicati in invii lunghi (se ci sono problemi con lock)... - d.refresh_from_db() - if d.inviato: - print("%s (*) msg=%d, dest=%d, protezione invio duplicato" % ( - datetime.now().isoformat(' '), - self.pk, - d.pk, - )) - continue - - try: - msg = EmailMultiAlternatives( - subject=self.oggetto, - body=plain_text, - from_email=mittente, - reply_to=[reply_to], - to=destinatari, - attachments=self.allegati_pronti(), - connection=connection, - ) - msg.attach_alternative(self.corpo, "text/html") - msg.send() - d.inviato = True - - except SMTPException as e: - - if isinstance(e, SMTPRecipientsRefused): - try: - if any([code == 250 for email, code in e.recipients.items()]): - # Almeno un'email è partita, il messaggio si considera inviato - d.inviato = True - successo = True - else: + with atomic(): + destinatari = [] + if hasattr(d, 'persona') and d.persona and d.persona.email: + destinatari.append(d.persona.email) + if hasattr(d.persona, 'utenza') and d.persona.utenza and d.persona.utenza.email: + if utenza and d.persona.utenza.email != d.persona.email: + destinatari.append(d.persona.utenza.email) + + if self.logging: + logger.debug('[POSTA]: MSG %s: Num=%d Destinatari=%s' % (self.pk, len(destinatari), d.pk)) + # Non diamo per scontato che esistano destinatari + if destinatari: + # Assicurati che la connessione sia aperta + connection.open() + + # Evita duplicati in invii lunghi (se ci sono problemi con lock)... + d.refresh_from_db() + if d.inviato: + if self.logging: + logger.debug('[POSTA]: MSG %s: destinatario duplicato: msg=%s, dest=%s' % (self.pk, self.oggetto, ','.join(destinatari))) + print("%s (*) msg=%d, dest=%d, protezione invio duplicato" % ( + datetime.now().isoformat(' '), + self.pk, + d.pk, + )) + continue + + try: + msg = EmailMultiAlternatives( + subject=self.oggetto, + body=plain_text, + from_email=mittente, + reply_to=[reply_to], + to=destinatari, + attachments=self.allegati_pronti(), + connection=connection, + ) + msg.attach_alternative(self.corpo, "text/html") + msg.send() + d.inviato = True + + except SMTPException as e: + if self.logging: + logger.debug('[POSTA]: MSG %s: eccezione %s' % (self.pk, e,)) + + if isinstance(e, SMTPRecipientsRefused): + try: + if any([code == 250 for email, code in e.recipients.items()]): + # Almeno un'email è partita, il messaggio si considera inviato + d.inviato = True + successo = True + else: + # E-mail di destinazione rotta: ignora. + d.inviato = True + d.invalido = True + except AttributeError: # E-mail di destinazione rotta: ignora. d.inviato = True d.invalido = True - except AttributeError: + + elif isinstance(e, SMTPResponseException) and e.smtp_code == 501: # E-mail di destinazione rotta: ignora. d.inviato = True d.invalido = True - elif isinstance(e, SMTPResponseException) and e.smtp_code == 501: - # E-mail di destinazione rotta: ignora. + elif isinstance(e, SMTPServerDisconnected): + # Se il server si e' disconnesso, riconnetti. + successo = False # Questo messaggio verra' inviato al prossimo tentativo. + connection.close() # Chiudi handle alla connessione + connection.open() # Riconnettiti + + else: + successo = False # Altro errore... riprova piu' tardi. + + d.errore = str(e) + + except TypeError as e: + if self.logging: + logger.debug('[POSTA]: MSG %s: eccezione %s' % (self.pk, e,)) d.inviato = True d.invalido = True + d.errore = "Nessun indirizzo e-mail. Saltato" - elif isinstance(e, SMTPServerDisconnected): - # Se il server si e' disconnesso, riconnetti. - successo = False # Questo messaggio verra' inviato al prossimo tentativo. - connection.close() # Chiudi handle alla connessione - connection.open() # Riconnettiti - - else: - successo = False # Altro errore... riprova piu' tardi. - - d.errore = str(e) - - except TypeError as e: - d.inviato = True - d.invalido = True - d.errore = "Nessun indirizzo e-mail. Saltato" - - except AttributeError as e: - d.inviato = True - d.invalido = True - d.errore = "Destinatario non valido. Saltato" - - except UnicodeEncodeError as e: - d.inviato = True - d.invalido = True - d.errore = "Indirizzo e-mail non valido. Saltato." - - if not d.inviato or d.invalido: - print("%s (!) errore invio id=%d, destinatario=%d, errore=%s" % ( - datetime.now().isoformat(' '), - self.pk, - d.pk, - d.errore, - )) - d.tentativo = datetime.now() - d.save() + except AttributeError as e: + if self.logging: + logger.debug('[POSTA]: MSG %s: eccezione %s' % (self.pk, e,)) + d.inviato = True + d.invalido = True + d.errore = "Destinatario non valido. Saltato" + + except UnicodeEncodeError as e: + if self.logging: + logger.debug('[POSTA]: MSG %s: eccezione %s' % (self.pk, e,)) + d.inviato = True + d.invalido = True + d.errore = "Indirizzo e-mail non valido. Saltato." + + if not d.inviato or d.invalido: + if self.logging: + logger.debug('[POSTA]: MSG %s: errore invio destinatario=%s, errore=%s' % (self.pk, d.pk, d.errore)) + print("%s (!) errore invio id=%d, destinatario=%d, errore=%s" % ( + datetime.now().isoformat(' '), + self.pk, + d.pk, + d.errore, + )) + d.tentativo = datetime.now() + d.save() + if self.logging: + logger.debug('[POSTA]: MSG %s: salvataggio destinatario=%s' % (self.pk, d.pk)) if successo: self.terminato = datetime.now() self.ultimo_tentativo = datetime.now() + if self.logging: + logger.debug('[POSTA]: MSG %s: termine invio successo=%s, inviato=%s invalido=%s errore=%s' % (self.pk, successo, d.inviato, d.invalido, d.errore)) + logger.debug('[POSTA]: MSG %s: salvataggio terminato=%s ultimo_tentativo=%s' % (self.pk, self.terminato, self.ultimo_tentativo)) self.save() def aggiungi_destinatario(self, persona): @@ -309,6 +343,11 @@ def smaltisci_coda(cls, dimensione_massima=50): connection = get_connection() for messaggio in da_smaltire: totale += 1 + if cls.logging: + logger.debug('[POSTA]: MSG %s: pickup destinatari=(totale=%d, in_attesa=%d)' % ( + messaggio.pk, messaggio.oggetti_destinatario.all().count(), + messaggio.oggetti_destinatario.filter(inviato=False).count(), + )) print("%s invio messaggio id=%d, destinatari=(totale=%d, in_attesa=%d)" % ( datetime.now().isoformat(' '), messaggio.pk,