nother attempt to add more logging and fix wallace messages not being delivered and staying in spool directory

Summary: Adding more logs that should show why _sendmail function does not start a "while" delivery loop and unliking file does not happen. Also some code polishing.

Test Plan: none

Reviewers: machniak, vanmeeuwen

Reviewed By: machniak

Subscribers: petersen

Differential Revision: https://git.kolab.org/D599

3 files changed, 25 insertions, 11 deletions

diff --git a/wallace/module_invitationpolicy.py b/wallace/module_invitationpolicy.py
index 602326d..a2a37fe 100644
--- a/wallace/module_invitationpolicy.py
+++ b/wallace/module_invitationpolicy.py
@@ -1283,8 +1283,8 @@ def send_update_notification(object, receiving_user, old=None, reply=True, sende
     msg['From'] = Header(utils.str2unicode('%s' % orgname) if orgname else '')
     msg['From'].append("<%s>" % orgemail)
 
-    success = modules._sendmail(orgemail, receiving_user['mail'], msg.as_string())
-    log.debug(_("Sent update notification to %r: %r") % (receiving_user['mail'], success), level=8)
+    result = modules._sendmail(orgemail, receiving_user['mail'], msg.as_string())
+    log.debug(_("Sent update notification to %r: %r") % (receiving_user['mail'], result), level=8)
 
 def send_cancel_notification(object, receiving_user, deleted=False, sender=None, comment=None):
     """
@@ -1344,8 +1344,8 @@ def send_cancel_notification(object, receiving_user, deleted=False, sender=None,
     msg['From'] = Header(utils.str2unicode('%s' % orgname) if orgname else '')
     msg['From'].append("<%s>" % orgemail)
 
-    success = modules._sendmail(orgemail, receiving_user['mail'], msg.as_string())
-    log.debug(_("Sent cancel notification to %r: %r") % (receiving_user['mail'], success), level=8)
+    result = modules._sendmail(orgemail, receiving_user['mail'], msg.as_string())
+    log.debug(_("Sent cancel notification to %r: %r") % (receiving_user['mail'], result), level=8)
 
 def is_auto_reply(user, sender_email, type):
     accept_available = False
diff --git a/wallace/module_resources.py b/wallace/module_resources.py
index f5f8382..962e11a 100644
--- a/wallace/module_resources.py
+++ b/wallace/module_resources.py
@@ -1355,7 +1355,8 @@ def send_owner_notification(resource, owner, itip_event, success=True):
             resource['cn'], participant_status_label(status) if success else _('failed')
         ))
 
-        modules._sendmail(resource['mail'], owner['mail'], msg.as_string())
+        result = modules._sendmail(resource['mail'], owner['mail'], msg.as_string())
+        log.debug(_("Owner notification was sent successfully: %r") % result, level=8)
 
 def owner_notification_text(resource, owner, event, success):
     organizer = event.get_organizer()
diff --git a/wallace/modules.py b/wallace/modules.py
index 1d25b1c..966a3b9 100644
--- a/wallace/modules.py
+++ b/wallace/modules.py
@@ -132,17 +132,17 @@ def _sendmail(sender, recipients, msg):
     sl = pykolab.logger.StderrToLogger(log)
     smtplib.stderr = sl
 
-    smtp = smtplib.SMTP(timeout=5)
+    smtp = smtplib.SMTP(timeout=15)
 
     if conf.debuglevel > 8:
         smtp.set_debuglevel(1)
 
     success = False
-    retries = 5
+    attempt = 1
 
-    while not success and retries > 0:
+    while not success and attempt <= 5:
         try:
-            log.debug(_("Trying to send email via smtplib from %r, to %r") % (sender, recipients), level=8)
+            log.debug(_("Sending email via smtplib from %r, to %r (Attempt %r)") % (sender, recipients, attempt), level=8)
             smtp.connect("127.0.0.1", 10027)
             _response = smtp.sendmail(sender, recipients, msg)
 
@@ -182,9 +182,13 @@ def _sendmail(sender, recipients, msg):
         except Exception, errmsg:
             log.exception(_("smtplib - Unknown error occurred: %r") % (errmsg))
 
-        smtp.quit()
+        try:
+            smtp.quit()
+        except Exception, errmsg:
+            log.error("smtplib quit() error - %r" % errmsg)
+
         time.sleep(10)
-        retries -= 1
+        attempt += 1
 
     return success
 
@@ -237,6 +241,8 @@ def cb_action_DEFER(module, filepath):
 def cb_action_REJECT(module, filepath):
     log.info(_("Rejecting message in %s (by module %s)") % (filepath, module))
 
+    log.debug(_("Rejecting message in: %r") %(filepath), level=8)
+
     # parse message headers
     message = Parser().parse(open(filepath, 'r'), True)
 
@@ -311,8 +317,12 @@ X-Wallace-Result: REJECT
             msg.as_string()
         )
 
+    log.debug(_("Rejection message was sent successfully: %r") % result)
     if result:
         os.unlink(filepath)
+    else:
+        log.debug(_("Message %r was not removed from spool") % filepath)
+
 
 def cb_action_ACCEPT(module, filepath):
     log.info(_("Accepting message in %s (by module %s)") % (filepath, module))
@@ -342,8 +352,11 @@ def cb_action_ACCEPT(module, filepath):
             message.as_string()
         )
 
+    log.debug(_("Message was sent successfully: %r") % result)
     if result:
         os.unlink(filepath)
+    else:
+        log.debug(_("Message %r was not removed from spool") % filepath)
 
 def register_group(dirname, module):
     modules_base_path = os.path.join(os.path.dirname(__file__), module)