ultra verbose debug

email_queue.py

@@ -3,9 +3,9 @@ import queue
 import time
 import asyncio
 from datetime import datetime, timedelta
-from typing import Optional
-from tenacity import retry, stop_after_attempt, wait_exponential
 import smtplib
+import ssl
+import socket
 from email.mime.multipart import MIMEMultipart
 from email.mime.text import MIMEText
 from email.mime.application import MIMEApplication
@@ -18,6 +18,21 @@ from io import BytesIO
 
 logger = logging.getLogger(__name__)
 
+ULTRA_DEBUG = True
+
+def debug_log(message: str, level: str = "INFO"):
+    if ULTRA_DEBUG:
+        timestamp = datetime.now().strftime("%H:%M:%S.%f")[:-3]
+        prefix = {
+            "INFO": "🔍",
+            "SUCCESS": "✅", 
+            "ERROR": "❌",
+            "WARN": "⚠️",
+            "STEP": "📍",
+            "DATA": "📦"
+        }.get(level, "•")
+        logger.info(f"{prefix} [{timestamp}] {message}")
+
 
 class EmailQueue:
 
@@ -29,7 +44,6 @@ class EmailQueue:
         self.sage_client = None
 
     def start(self, num_workers: int = 3):
-        """Démarre les workers"""
         if self.running:
             logger.warning("Queue déjà démarrée")
             return
@@ -42,33 +56,35 @@ class EmailQueue:
             worker.start()
             self.workers.append(worker)
 
-        logger.info(f" Queue email démarrée avec {num_workers} worker(s)")
+        logger.info(f"✅ Queue email démarrée avec {num_workers} worker(s)")
 
     def stop(self):
-        """Arrête les workers proprement"""
+        logger.info("🛑 Arrêt de la queue email...")
-        logger.info(" Arrêt de la queue email...")
         self.running = False
 
         try:
             self.queue.join()
-            logger.info(" Queue email arrêtée proprement")
+            logger.info("✅ Queue email arrêtée proprement")
         except:
-            logger.warning(" Timeout lors de l'arrêt de la queue")
+            logger.warning("⚠️ Timeout lors de l'arrêt de la queue")
 
     def enqueue(self, email_log_id: str):
         """Ajoute un email dans la queue"""
         self.queue.put(email_log_id)
-        logger.debug(f" Email {email_log_id} ajouté à la queue")
+        debug_log(f"Email {email_log_id} ajouté à la queue (taille: {self.queue.qsize()})")
 
     def _worker(self):
-        """Worker qui traite les emails dans un thread"""
         loop = asyncio.new_event_loop()
         asyncio.set_event_loop(loop)
+        worker_name = threading.current_thread().name
+
+        debug_log(f"Worker {worker_name} démarré", "SUCCESS")
 
         try:
             while self.running:
                 try:
                     email_log_id = self.queue.get(timeout=1)
+                    debug_log(f"[{worker_name}] Traitement email {email_log_id}", "STEP")
 
                     loop.run_until_complete(self._process_email(email_log_id))
 
@@ -77,21 +93,23 @@ class EmailQueue:
                 except queue.Empty:
                     continue
                 except Exception as e:
-                    logger.error(f" Erreur worker: {e}", exc_info=True)
+                    logger.error(f"❌ Erreur worker {worker_name}: {e}", exc_info=True)
                     try:
                         self.queue.task_done()
                     except:
                         pass
         finally:
             loop.close()
+            debug_log(f"Worker {worker_name} arrêté", "WARN")
 
     async def _process_email(self, email_log_id: str):
-        """Traite un email avec retry automatique"""
         from database import EmailLog, StatutEmail
         from sqlalchemy import select
 
+        debug_log(f"═══ DÉBUT TRAITEMENT EMAIL {email_log_id} ═══", "STEP")
+
         if not self.session_factory:
-            logger.error(" session_factory non configuré")
+            logger.error("❌ session_factory non configuré")
             return
 
         async with self.session_factory() as session:
@@ -101,9 +119,15 @@ class EmailQueue:
             email_log = result.scalar_one_or_none()
 
             if not email_log:
-                logger.error(f" Email log {email_log_id} introuvable")
+                logger.error(f"❌ Email log {email_log_id} introuvable en DB")
                 return
 
+            debug_log(f"Email trouvé en DB:", "DATA")
+            debug_log(f"  → Destinataire: {email_log.destinataire}")
+            debug_log(f"  → Sujet: {email_log.sujet[:50]}...")
+            debug_log(f"  → Tentative: {email_log.nb_tentatives + 1}")
+            debug_log(f"  → Documents: {email_log.document_ids}")
+
             email_log.statut = StatutEmail.EN_COURS
             email_log.nb_tentatives += 1
             await session.commit()
@@ -114,11 +138,14 @@ class EmailQueue:
                 email_log.statut = StatutEmail.ENVOYE
                 email_log.date_envoi = datetime.now()
                 email_log.derniere_erreur = None
-                logger.info(f" Email envoyé: {email_log.destinataire}")
+                debug_log(f"Email envoyé avec succès: {email_log.destinataire}", "SUCCESS")
 
             except Exception as e:
+                error_msg = str(e)
+                debug_log(f"ÉCHEC ENVOI: {error_msg}", "ERROR")
+                
                 email_log.statut = StatutEmail.ERREUR
-                email_log.derniere_erreur = str(e)[:1000]  # Limiter la taille
+                email_log.derniere_erreur = error_msg[:1000]
 
                 if email_log.nb_tentatives < settings.max_retry_attempts:
                     delay = settings.retry_delay_seconds * (
@@ -130,36 +157,44 @@ class EmailQueue:
                     timer.daemon = True
                     timer.start()
 
-                    logger.warning(
+                    debug_log(f"Retry #{email_log.nb_tentatives + 1} planifié dans {delay}s", "WARN")
-                        f" Retry prévu dans {delay}s pour {email_log.destinataire}"
-                    )
                 else:
-                    logger.error(f" Échec définitif: {email_log.destinataire} - {e}")
+                    debug_log(f"ÉCHEC DÉFINITIF après {email_log.nb_tentatives} tentatives", "ERROR")
 
             await session.commit()
+            debug_log(f"═══ FIN TRAITEMENT EMAIL {email_log_id} ═══", "STEP")
 
-    @retry(
-        stop=stop_after_attempt(3), wait=wait_exponential(multiplier=1, min=4, max=10)
-    )
     async def _send_with_retry(self, email_log):
-        """Envoi SMTP avec retry Tenacity + génération PDF"""
+        
+        debug_log("Construction du message MIME...", "STEP")
+        
         msg = MIMEMultipart()
         msg["From"] = settings.smtp_from
         msg["To"] = email_log.destinataire
         msg["Subject"] = email_log.sujet
 
-        msg.attach(MIMEText(email_log.corps_html, "html"))
+        debug_log(f"Headers configurés:", "DATA")
+        debug_log(f"  → From: {settings.smtp_from}")
+        debug_log(f"  → To: {email_log.destinataire}")
+        debug_log(f"  → Subject: {email_log.sujet}")
 
+        msg.attach(MIMEText(email_log.corps_html, "html"))
+        debug_log(f"Corps HTML attaché ({len(email_log.corps_html)} chars)")
+
+        # Attachement des PDFs
         if email_log.document_ids:
             document_ids = email_log.document_ids.split(",")
             type_doc = email_log.type_document
 
+            debug_log(f"Documents à attacher: {document_ids}")
+
             for doc_id in document_ids:
                 doc_id = doc_id.strip()
                 if not doc_id:
                     continue
 
                 try:
+                    debug_log(f"Génération PDF pour {doc_id}...")
                     pdf_bytes = await asyncio.to_thread(
                         self._generate_pdf, doc_id, type_doc
                     )
@@ -170,13 +205,199 @@ class EmailQueue:
                             f'attachment; filename="{doc_id}.pdf"'
                         )
                         msg.attach(part)
-                        logger.info(f"📎 PDF attaché: {doc_id}.pdf")
+                        debug_log(f"PDF attaché: {doc_id}.pdf ({len(pdf_bytes)} bytes)", "SUCCESS")
 
                 except Exception as e:
-                    logger.error(f" Erreur génération PDF {doc_id}: {e}")
+                    debug_log(f"Erreur génération PDF {doc_id}: {e}", "ERROR")
 
+        # Envoi SMTP
+        debug_log("Lancement envoi SMTP...", "STEP")
         await asyncio.to_thread(self._send_smtp, msg)
 
+    def _send_smtp(self, msg):
+        debug_log("═══════════════════════════════════════════", "STEP")
+        debug_log("     DÉBUT ENVOI SMTP ULTRA DEBUG", "STEP")
+        debug_log("═══════════════════════════════════════════", "STEP")
+        
+        # ═══ CONFIGURATION ═══
+        debug_log("CONFIGURATION SMTP:", "DATA")
+        debug_log(f"  → Host: {settings.smtp_host}")
+        debug_log(f"  → Port: {settings.smtp_port}")
+        debug_log(f"  → User: {settings.smtp_user}")
+        debug_log(f"  → Password: {'*' * len(settings.smtp_password) if settings.smtp_password else 'NON DÉFINI'}")
+        debug_log(f"  → From: {settings.smtp_from}")
+        debug_log(f"  → TLS: {settings.smtp_use_tls}")
+        debug_log(f"  → To: {msg['To']}")
+        
+        server = None
+        
+        try:
+            # ═══ ÉTAPE 1: RÉSOLUTION DNS ═══
+            debug_log("ÉTAPE 1/7: Résolution DNS...", "STEP")
+            try:
+                ip_addresses = socket.getaddrinfo(settings.smtp_host, settings.smtp_port)
+                debug_log(f"  → DNS résolu: {ip_addresses[0][4]}", "SUCCESS")
+            except socket.gaierror as e:
+                debug_log(f"  → ÉCHEC DNS: {e}", "ERROR")
+                raise Exception(f"Résolution DNS échouée pour {settings.smtp_host}: {e}")
+
+            # ═══ ÉTAPE 2: CONNEXION TCP ═══
+            debug_log("ÉTAPE 2/7: Connexion TCP...", "STEP")
+            start_time = time.time()
+            
+            try:
+                server = smtplib.SMTP(
+                    settings.smtp_host, 
+                    settings.smtp_port, 
+                    timeout=30
+                )
+                server.set_debuglevel(2 if ULTRA_DEBUG else 0)  # Active le debug SMTP natif
+                
+                connect_time = time.time() - start_time
+                debug_log(f"  → Connexion établie en {connect_time:.2f}s", "SUCCESS")
+                
+            except socket.timeout:
+                debug_log(f"  → TIMEOUT connexion (>30s)", "ERROR")
+                raise Exception(f"Timeout connexion TCP vers {settings.smtp_host}:{settings.smtp_port}")
+            except ConnectionRefusedError:
+                debug_log(f"  → CONNEXION REFUSÉE", "ERROR")
+                raise Exception(f"Connexion refusée par {settings.smtp_host}:{settings.smtp_port}")
+            except Exception as e:
+                debug_log(f"  → ERREUR CONNEXION: {type(e).__name__}: {e}", "ERROR")
+                raise
+
+            # ═══ ÉTAPE 3: EHLO ═══
+            debug_log("ÉTAPE 3/7: Envoi EHLO...", "STEP")
+            try:
+                ehlo_code, ehlo_msg = server.ehlo()
+                debug_log(f"  → EHLO Response: {ehlo_code}", "SUCCESS")
+                debug_log(f"  → Capabilities: {ehlo_msg.decode()[:200]}...")
+            except Exception as e:
+                debug_log(f"  → ÉCHEC EHLO: {e}", "ERROR")
+                raise
+
+            # ═══ ÉTAPE 4: STARTTLS ═══
+            if settings.smtp_use_tls:
+                debug_log("ÉTAPE 4/7: Négociation STARTTLS...", "STEP")
+                try:
+                    # Vérifier si le serveur supporte STARTTLS
+                    if server.has_extn('STARTTLS'):
+                        debug_log("  → Serveur supporte STARTTLS", "SUCCESS")
+                        
+                        # Créer un contexte SSL
+                        context = ssl.create_default_context()
+                        debug_log(f"  → Contexte SSL créé (protocole: {context.protocol})")
+                        
+                        tls_code, tls_msg = server.starttls(context=context)
+                        debug_log(f"  → STARTTLS Response: {tls_code} - {tls_msg}", "SUCCESS")
+                        
+                        # Re-EHLO après STARTTLS
+                        server.ehlo()
+                        debug_log("  → Re-EHLO après TLS: OK", "SUCCESS")
+                    else:
+                        debug_log("  → Serveur ne supporte PAS STARTTLS!", "WARN")
+                        
+                except smtplib.SMTPNotSupportedError:
+                    debug_log("  → STARTTLS non supporté par le serveur", "WARN")
+                except ssl.SSLError as e:
+                    debug_log(f"  → ERREUR SSL: {e}", "ERROR")
+                    raise Exception(f"Erreur SSL/TLS: {e}")
+                except Exception as e:
+                    debug_log(f"  → ÉCHEC STARTTLS: {type(e).__name__}: {e}", "ERROR")
+                    raise
+            else:
+                debug_log("ÉTAPE 4/7: STARTTLS désactivé (smtp_use_tls=False)", "WARN")
+
+            # ═══ ÉTAPE 5: AUTHENTIFICATION ═══
+            debug_log("ÉTAPE 5/7: Authentification...", "STEP")
+            if settings.smtp_user and settings.smtp_password:
+                debug_log(f"  → Tentative login avec: {settings.smtp_user}")
+                
+                try:
+                    # Lister les méthodes d'auth supportées
+                    if server.has_extn('AUTH'):
+                        auth_methods = server.esmtp_features.get('auth', '')
+                        debug_log(f"  → Méthodes AUTH supportées: {auth_methods}")
+                    
+                    server.login(settings.smtp_user, settings.smtp_password)
+                    debug_log("  → Authentification RÉUSSIE", "SUCCESS")
+                    
+                except smtplib.SMTPAuthenticationError as e:
+                    debug_log(f"  → ÉCHEC AUTHENTIFICATION: {e.smtp_code} - {e.smtp_error}", "ERROR")
+                    debug_log(f"  → Code: {e.smtp_code}", "ERROR")
+                    debug_log(f"  → Message: {e.smtp_error.decode() if isinstance(e.smtp_error, bytes) else e.smtp_error}", "ERROR")
+                    
+                    # Diagnostic spécifique selon le code d'erreur
+                    if e.smtp_code == 535:
+                        debug_log("  → 535 = Identifiants incorrects ou app password requis", "ERROR")
+                    elif e.smtp_code == 534:
+                        debug_log("  → 534 = 2FA requis, utiliser un App Password", "ERROR")
+                    elif e.smtp_code == 530:
+                        debug_log("  → 530 = Authentification requise mais échouée", "ERROR")
+                    
+                    raise Exception(f"Authentification SMTP échouée: {e.smtp_code} - {e.smtp_error}")
+                    
+                except smtplib.SMTPException as e:
+                    debug_log(f"  → ERREUR SMTP AUTH: {e}", "ERROR")
+                    raise
+            else:
+                debug_log("  → Pas d'authentification configurée", "WARN")
+
+            # ═══ ÉTAPE 6: ENVOI DU MESSAGE ═══
+            debug_log("ÉTAPE 6/7: Envoi du message...", "STEP")
+            debug_log(f"  → From: {msg['From']}")
+            debug_log(f"  → To: {msg['To']}")
+            debug_log(f"  → Subject: {msg['Subject']}")
+            debug_log(f"  → Taille message: {len(msg.as_string())} bytes")
+            
+            try:
+                # send_message retourne un dict des destinataires refusés
+                refused = server.send_message(msg)
+                
+                if refused:
+                    debug_log(f"  → DESTINATAIRES REFUSÉS: {refused}", "ERROR")
+                    raise Exception(f"Destinataires refusés: {refused}")
+                else:
+                    debug_log("  → Message envoyé avec succès!", "SUCCESS")
+                    
+            except smtplib.SMTPRecipientsRefused as e:
+                debug_log(f"  → DESTINATAIRE REFUSÉ: {e.recipients}", "ERROR")
+                raise Exception(f"Destinataire refusé: {e.recipients}")
+            except smtplib.SMTPSenderRefused as e:
+                debug_log(f"  → EXPÉDITEUR REFUSÉ: {e.smtp_code} - {e.smtp_error}", "ERROR")
+                debug_log(f"  → L'adresse '{msg['From']}' n'est pas autorisée à envoyer", "ERROR")
+                raise Exception(f"Expéditeur refusé: {e.smtp_code} - {e.smtp_error}")
+            except smtplib.SMTPDataError as e:
+                debug_log(f"  → ERREUR DATA: {e.smtp_code} - {e.smtp_error}", "ERROR")
+                raise Exception(f"Erreur DATA SMTP: {e.smtp_code} - {e.smtp_error}")
+
+            # ═══ ÉTAPE 7: QUIT ═══
+            debug_log("ÉTAPE 7/7: Fermeture connexion...", "STEP")
+            try:
+                server.quit()
+                debug_log("  → Connexion fermée proprement", "SUCCESS")
+            except:
+                pass
+
+            debug_log("═══════════════════════════════════════════", "SUCCESS")
+            debug_log("     ENVOI SMTP TERMINÉ AVEC SUCCÈS", "SUCCESS")
+            debug_log("═══════════════════════════════════════════", "SUCCESS")
+
+        except Exception as e:
+            debug_log("═══════════════════════════════════════════", "ERROR")
+            debug_log(f"     ÉCHEC ENVOI SMTP: {type(e).__name__}", "ERROR")
+            debug_log(f"     Message: {str(e)}", "ERROR")
+            debug_log("═══════════════════════════════════════════", "ERROR")
+            
+            # Fermer la connexion si elle existe
+            if server:
+                try:
+                    server.quit()
+                except:
+                    pass
+            
+            raise Exception(f"Erreur SMTP: {str(e)}")
+
     def _generate_pdf(self, doc_id: str, type_doc: int) -> bytes:
 
         if not self.sage_client:
@@ -247,6 +468,7 @@ class EmailQueue:
                 y = height - 3 * cm
                 pdf.setFont("Helvetica", 9)
 
+            # ✅ FIX: Gérer les valeurs None correctement
             designation = (
                 ligne.get("designation") 
                 or ligne.get("designation_article") 
@@ -294,23 +516,4 @@ class EmailQueue:
         return buffer.read()
 
 
-    def _send_smtp(self, msg):
-        try:
-            with smtplib.SMTP(
-                settings.smtp_host, settings.smtp_port, timeout=30
-            ) as server:
-                if settings.smtp_use_tls:
-                    server.starttls()
-
-                if settings.smtp_user and settings.smtp_password:
-                    server.login(settings.smtp_user, settings.smtp_password)
-
-                server.send_message(msg)
-
-        except smtplib.SMTPException as e:
-            raise Exception(f"Erreur SMTP: {str(e)}")
-        except Exception as e:
-            raise Exception(f"Erreur envoi: {str(e)}")
-
-
 email_queue = EmailQueue()