diff --git a/.arclint b/.arclint --- a/.arclint +++ b/.arclint @@ -19,6 +19,7 @@ "E131": "disabled", "E201": "disabled", "E202": "disabled", + "E221": "disabled", "E225": "disabled", "E231": "disabled", "E251": "disabled", diff --git a/pykolab/logger.py b/pykolab/logger.py --- a/pykolab/logger.py +++ b/pykolab/logger.py @@ -35,16 +35,27 @@ self.logger = logger self.log_level = log_level self.linebuf = '' + self.skip_next = False def write(self, buf): - # ugly patch to make smtplib debug logging records appear on one line in log file + # ugly patch to make smtplib and smtpd debug logging records appear on one line in log file # smtplib uses "print>>stderr, var, var" statements for debug logging. These # statements are splited into separate lines on separating whitespace. + for line in buf.rstrip().splitlines(): + if self.skip_next: + self.skip_next = False + continue + if buf != '\n': - if line.startswith('send:') or line.startswith('reply:'): + linestarts = line.split(':')[0] + if linestarts in ['send', 'reply', 'Data', 'recips', 'Peer', 'sender']: self.linebuf = line - return + elif linestarts.startswith('===>'): + # Do not log lines starting with ====> + self.linebuf = '' + self.skip_next = True + continue else: self.logger.log(self.log_level, '%s %s', self.linebuf, line.rstrip()[:150]) self.linebuf = '' @@ -52,6 +63,14 @@ def flush(self): pass +class LoggerAdapter(logging.LoggerAdapter): + """ + Custom LoggingAdapter to log Wallace mail message Queue ID + """ + + def process(self, msg, kwargs): + return '%s %s' % (self.extra['qid'], msg), kwargs + class Logger(logging.Logger): """ The PyKolab version of a logger. diff --git a/wallace/__init__.py b/wallace/__init__.py --- a/wallace/__init__.py +++ b/wallace/__init__.py @@ -26,7 +26,7 @@ import os import pwd import traceback -from smtpd import SMTPChannel +import smtpd import socket import struct import sys @@ -42,6 +42,7 @@ # pylint: disable=invalid-name log = pykolab.getLogger('pykolab.wallace') +sys.stderr = pykolab.logger.StderrToLogger(log) conf = pykolab.getConf() @@ -128,10 +129,15 @@ while True: while not self.finished.is_set(): self.finished.wait(self.interval) + log.debug(_("Timer looping function '%s' every %ss") % ( + self.function.__name__, + self.interval + ), level=8) self.function(*self.args, **self.kwargs) self.finished.set() - + log.debug(_("Timer loop %s") % ('still active','finished')[self.finished.is_set()], level=8) + break class WallaceDaemon: def __init__(self): @@ -176,6 +182,15 @@ help=_("Number of threads to use.") ) + daemon_group.add_option( + "--max-tasks", + dest = "max_tasks", + action = "store", + default = 10, + type = int, + help = _("Number of tasks per process.") + ) + daemon_group.add_option( "-p", "--pid-file", dest="pidfile", @@ -226,7 +241,7 @@ self.parent_pid = os.getpid() if version.StrictVersion(sys.version[:3]) >= version.StrictVersion("2.7"): - self.pool = multiprocessing.Pool(conf.max_threads, worker_process, (), 1) + self.pool = multiprocessing.Pool(conf.max_threads, worker_process, (), conf.max_tasks) else: self.pool = multiprocessing.Pool(conf.max_threads, worker_process, ()) @@ -297,16 +312,25 @@ try: while 1: while self.current_connections >= self.max_connections: - log.debug("Out of connections.") + log.debug(_("Reached limit of max connections of: %s. Sleeping for 0.5s") % self.max_connections, level=6) time.sleep(0.5) pair = s.accept() - log.info(_("Accepted connection")) + log.debug(_("Accepted connection %r with address %r") % (pair if pair is not None else (None, None)), level=8) if pair is not None: self.current_connections += 1 connection, address = pair - SMTPChannel(self, connection, address) + + _smtpd = smtpd + # Set DEBUGSTREAM of smtpd to log to pykolab logger + if conf.debuglevel > 8: + _smtpd.DEBUGSTREAM = pykolab.logger.StderrToLogger(log) + + log.debug(_("Creating SMTPChannel for accepted message"), level=8) + channel = _smtpd.SMTPChannel(self, connection, address) asyncore.loop() + else: + log.error(_("Socket accepted, but (conn, address) tuple is None.")) # pylint: disable=broad-except except Exception: @@ -431,6 +455,7 @@ os.write(fp, data) os.close(fp) + log.debug(_("Started processing accepted message %s") % filename, level=8) self.pool.apply_async(pickup_message, (filename, (self.modules))) self.current_connections -= 1 diff --git a/wallace/module_footer.py b/wallace/module_footer.py --- a/wallace/module_footer.py +++ b/wallace/module_footer.py @@ -29,7 +29,9 @@ from pykolab.translate import _ -log = pykolab.getLogger('pykolab.wallace') +log = pykolab.getLogger('pykolab.wallace/footer') +extra_log_params = {'qid': '-'} +log = pykolab.logger.LoggerAdapter(log, extra_log_params) conf = pykolab.getConf() mybasepath = '/var/spool/pykolab/wallace/footer/' @@ -49,6 +51,13 @@ return True def execute(*args, **kw): + global extra_log_params + + # TODO: Test for correct call. + filepath = args[0] + + extra_log_params['qid'] = os.path.basename(filepath) + if not os.path.isdir(mybasepath): os.makedirs(mybasepath) @@ -56,9 +65,6 @@ if not os.path.isdir(os.path.join(mybasepath, stage)): os.makedirs(os.path.join(mybasepath, stage)) - # TODO: Test for correct call. - filepath = args[0] - if 'stage' in kw: log.debug(_("Issuing callback after processing to stage %s") % (kw['stage']), level=8) log.debug(_("Testing cb_action_%s()") % (kw['stage']), level=8) diff --git a/wallace/module_gpgencrypt.py b/wallace/module_gpgencrypt.py --- a/wallace/module_gpgencrypt.py +++ b/wallace/module_gpgencrypt.py @@ -40,7 +40,9 @@ from pykolab.translate import _ -log = pykolab.getLogger('pykolab.wallace') +log = pykolab.getLogger('pykolab.wallace/gpgencrypt') +extra_log_params = {'qid': '-'} +log = pykolab.logger.LoggerAdapter(log, extra_log_params) conf = pykolab.getConf() mybasepath = '/var/spool/pykolab/wallace/gpgencrypt/' @@ -86,6 +88,13 @@ return msg def execute(*args, **kw): + global extra_log_params + + # TODO: Test for correct call. + filepath = args[0] + + extra_log_params['qid'] = os.path.basename(filepath) + if not os.path.isdir(mybasepath): os.makedirs(mybasepath) @@ -93,9 +102,6 @@ if not os.path.isdir(os.path.join(mybasepath, stage)): os.makedirs(os.path.join(mybasepath, stage)) - # TODO: Test for correct call. - filepath = args[0] - if kw.has_key('stage'): log.debug(_("Issuing callback after processing to stage %s") % (kw['stage']), level=8) log.debug(_("Testing cb_action_%s()") % (kw['stage']), level=8) diff --git a/wallace/module_invitationpolicy.py b/wallace/module_invitationpolicy.py --- a/wallace/module_invitationpolicy.py +++ b/wallace/module_invitationpolicy.py @@ -145,7 +145,10 @@ 'task': COND_TYPE_TASK } -log = pykolab.getLogger('pykolab.wallace') +log = pykolab.getLogger('pykolab.wallace/invitationpolicy') +extra_log_params = {'qid': '-'} +log = pykolab.logger.LoggerAdapter(log, extra_log_params) + conf = pykolab.getConf() mybasepath = '/var/spool/pykolab/wallace/invitationpolicy/' @@ -184,10 +187,12 @@ return """Invitation policy execution module.""" def cleanup(): - global auth, imap, write_locks + global auth, imap, write_locks, extra_log_params log.debug("cleanup(): %r, %r" % (auth, imap), level=8) + extra_log_params['qid'] = '-' + auth.disconnect() del auth @@ -200,7 +205,11 @@ remove_write_lock(key, False) def execute(*args, **kw): - global auth, imap + global auth, imap, extra_log_params + + filepath = args[0] + + extra_log_params['qid'] = os.path.basename(filepath) # (re)set language to default pykolab.translate.setUserLanguage(conf.get('kolab','default_locale')) @@ -217,8 +226,6 @@ auth = Auth() imap = IMAP() - filepath = args[0] - # ignore calls on lock files if '/locks/' in filepath or kw.has_key('stage') and kw['stage'] == 'locks': return False diff --git a/wallace/module_optout.py b/wallace/module_optout.py --- a/wallace/module_optout.py +++ b/wallace/module_optout.py @@ -35,7 +35,7 @@ from pykolab.translate import _ -log = pykolab.getLogger('pykolab.wallace') +log = pykolab.getLogger('pykolab.wallace/optout') conf = pykolab.getConf() mybasepath = '/var/spool/pykolab/wallace/optout/' diff --git a/wallace/module_resources.py b/wallace/module_resources.py --- a/wallace/module_resources.py +++ b/wallace/module_resources.py @@ -66,7 +66,10 @@ 'ACT_ACCEPT_AND_NOTIFY': ACT_ACCEPT_AND_NOTIFY } -log = pykolab.getLogger('pykolab.wallace') +log = pykolab.getLogger('pykolab.wallace/resources') +extra_log_params = {'qid': '-'} +log = pykolab.logger.LoggerAdapter(log, extra_log_params) + conf = pykolab.getConf() mybasepath = '/var/spool/pykolab/wallace/resources/' @@ -93,10 +96,12 @@ return """Resource management module.""" def cleanup(): - global auth, imap + global auth, imap, extra_log_params log.debug("cleanup(): %r, %r" % (auth, imap), level=8) + extra_log_params['qid'] = '-' + auth.disconnect() del auth @@ -105,7 +110,12 @@ del imap def execute(*args, **kw): - global auth, imap + global auth, imap, extra_log_params + + # TODO: Test for correct call. + filepath = args[0] + + extra_log_params['qid'] = os.path.basename(filepath) # (re)set language to default pykolab.translate.setUserLanguage(conf.get('kolab','default_locale')) @@ -122,9 +132,6 @@ auth = Auth() imap = IMAP() - # TODO: Test for correct call. - filepath = args[0] - if kw.has_key('stage'): log.debug( _("Issuing callback after processing to stage %s") % ( diff --git a/wallace/module_signature.py b/wallace/module_signature.py --- a/wallace/module_signature.py +++ b/wallace/module_signature.py @@ -33,7 +33,9 @@ from pykolab.translate import _ # pylint: disable=invalid-name -log = pykolab.getLogger('pykolab.wallace') +log = pykolab.getLogger('pykolab.wallace/signature') +extra_log_params = {'qid': '-'} +log = pykolab.logger.LoggerAdapter(log, extra_log_params) conf = pykolab.getConf() mybasepath = '/var/spool/pykolab/wallace/signature/' @@ -78,6 +80,13 @@ # pylint: disable=too-many-branches,too-many-locals,too-many-statements def execute(*args, **kw): # noqa: C901 + global extra_log_params + + # TODO: Test for correct call. + filepath = args[0] + + extra_log_params['qid'] = os.path.basename(filepath) + if not os.path.isdir(mybasepath): os.makedirs(mybasepath) @@ -85,9 +94,6 @@ if not os.path.isdir(os.path.join(mybasepath, stage)): os.makedirs(os.path.join(mybasepath, stage)) - # TODO: Test for correct call. - filepath = args[0] - if 'stage' in kw: log.debug(_("Issuing callback after processing to stage %s") % (kw['stage']), level=8) log.debug(_("Testing cb_action_%s()") % (kw['stage']), level=8) diff --git a/wallace/modules.py b/wallace/modules.py --- a/wallace/modules.py +++ b/wallace/modules.py @@ -42,7 +42,10 @@ from pykolab import constants from pykolab.translate import _ -log = pykolab.getLogger('pykolab.wallace') +log = pykolab.getLogger('pykolab.wallace/modules') +extra_log_params = {'qid': '-'} +log = pykolab.logger.LoggerAdapter(log, extra_log_params) + conf = pykolab.getConf() modules = {} @@ -204,9 +207,17 @@ return success def cb_action_HOLD(module, filepath): + global extra_log_params + + extra_log_params['qid'] = os.path.basename(filepath) + log.info(_("Holding message in queue for manual review (%s by %s)") % (filepath, module)) def cb_action_DEFER(module, filepath): + global extra_log_params + + extra_log_params['qid'] = os.path.basename(filepath) + log.info(_("Deferring message in %s (by module %s)") % (filepath, module)) # parse message headers @@ -250,6 +261,10 @@ #os.unlink(filepath) def cb_action_REJECT(module, filepath): + global extra_log_params + + extra_log_params['qid'] = os.path.basename(filepath) + log.info(_("Rejecting message in %s (by module %s)") % (filepath, module)) log.debug(_("Rejecting message in: %r") %(filepath), level=8) @@ -336,6 +351,10 @@ def cb_action_ACCEPT(module, filepath): + global extra_log_params + + extra_log_params['qid'] = os.path.basename(filepath) + log.info(_("Accepting message in %s (by module %s)") % (filepath, module)) log.debug(_("Accepting message in: %r") %(filepath), level=8)