def __init__(self, message_queue):
threading.Thread.__init__(self)
self.name = "Process Message Listener"
self.message_queue = message_queue
self.stayalive = True
self.statskeeper = Statskeeper()
self.daemon = True
def __init__(self, protohandler, config, prependers, plugins, appenders):
self.logger = logging.getLogger("fuglu.SessionHandler")
self.action = DUNNO
self.config = config
self.prependers = prependers
self.plugins = plugins
self.appenders = appenders
self.stats = Statskeeper()
self.worker = None
self.message = None
self.protohandler = protohandler
def __init__(self, message_queue):
threading.Thread.__init__(self)
self.name = "Process Message Listener"
self.message_queue = message_queue
self.stayalive = True
self.statskeeper = Statskeeper()
self.daemon = True
def fuglu_process_worker(queue, config, shared_state,child_to_server_messages, logQueue):
signal.signal(signal.SIGHUP, signal.SIG_IGN)
logtools.client_configurer(logQueue)
logging.basicConfig(level=logging.DEBUG)
workerstate = WorkerStateWrapper(shared_state,'loading configuration')
logger = logging.getLogger('fuglu.process')
logger.debug("New worker: %s" % logtools.createPIDinfo())
# load config and plugins
controller = fuglu.core.MainController(config,logQueue)
controller.load_extensions()
controller.load_plugins()
prependers = controller.prependers
plugins = controller.plugins
appenders = controller.appenders
# forward statistics counters to parent process
stats = Statskeeper()
stats.stat_listener_callback.append(lambda event: child_to_server_messages.put(event.as_message()))
logger.debug("%s: Enter service loop..." % logtools.createPIDinfo())
try:
while True:
workerstate.workerstate = 'waiting for task'
logger.debug("%s: Child process waiting for task" % logtools.createPIDinfo())
task = queue.get()
if task is None: # poison pill
logger.debug("%s: Child process received poison pill - shut down" % logtools.createPIDinfo())
try:
# it might be possible it does not work to properly set the workerstate
# since this is a shared variable -> prevent exceptions
workerstate.workerstate = 'ended'
except Exception as e:
pass
finally:
return
workerstate.workerstate = 'starting scan session'
logger.debug("%s: Child process starting scan session" % logtools.createPIDinfo())
sock, handler_modulename, handler_classname = fuglu_process_unpack(task)
handler_class = getattr(importlib.import_module(handler_modulename), handler_classname)
handler_instance = handler_class(sock, config)
handler = SessionHandler(handler_instance, config,prependers, plugins, appenders)
handler.handlesession(workerstate)
except KeyboardInterrupt:
workerstate.workerstate = 'ended'
except:
trb = traceback.format_exc()
logger.error("Exception in child process: %s"%trb)
print(trb)
workerstate.workerstate = 'crashed'
finally:
controller.shutdown()
class MessageListener(threading.Thread):
def __init__(self, message_queue):
threading.Thread.__init__(self)
self.name = "Process Message Listener"
self.message_queue = message_queue
self.stayalive = True
self.statskeeper = Statskeeper()
self.daemon = True
def run(self):
while self.stayalive:
message = self.message_queue.get()
event_type = message['event_type']
if event_type == 'statsdelta': # increase statistics counters
try:
delta = StatDelta(**message)
self.statskeeper.increase_counter_values(delta)
except:
print(traceback.format_exc())
def __init__(self, protohandler, config, prependers, plugins, appenders):
self.logger = logging.getLogger("fuglu.SessionHandler")
self.action = DUNNO
self.config = config
self.prependers = prependers
self.plugins = plugins
self.appenders = appenders
self.stats = Statskeeper()
self.workerthread = None
self.message = None
self.protohandler = protohandler
class MessageListener(threading.Thread):
def __init__(self, message_queue):
threading.Thread.__init__(self)
self.name = "Process Message Listener"
self.message_queue = message_queue
self.stayalive = True
self.statskeeper = Statskeeper()
self.daemon = True
def run(self):
while self.stayalive:
message = self.message_queue.get()
event_type = message['event_type']
if event_type == 'statsdelta': # increase statistics counters
try:
delta = StatDelta(**message)
self.statskeeper.increase_counter_values(delta)
except:
print(traceback.format_exc())
def fuglu_process_worker(queue, config, shared_state,
child_to_server_messages):
logging.basicConfig(level=logging.DEBUG)
workerstate = WorkerStateWrapper(shared_state, 'loading configuration')
logger = logging.getLogger('fuglu.process')
# load config and plugins
controller = fuglu.core.MainController(config)
controller.load_extensions()
controller.load_plugins()
prependers = controller.prependers
plugins = controller.plugins
appenders = controller.appenders
# forward statistics counters to parent process
stats = Statskeeper()
stats.stat_listener_callback.append(
lambda event: child_to_server_messages.put(event.as_message()))
try:
while True:
workerstate.workerstate = 'waiting for task'
task = queue.get()
if task is None: # poison pill
logger.debug("Child process received poison pill - shut down")
workerstate.workerstate = 'ended'
return
workerstate.workerstate = 'starting scan session'
pickled_socket, handler_modulename, handler_classname = task
sock = pickle.loads(pickled_socket)
handler_class = getattr(
importlib.import_module(handler_modulename), handler_classname)
handler_instance = handler_class(sock, config)
handler = SessionHandler(handler_instance, config, prependers,
plugins, appenders)
handler.handlesession(workerstate)
except KeyboardInterrupt:
workerstate.workerstate = 'ended'
except:
trb = traceback.format_exc()
logger.error("Exception in child process: %s" % trb)
print(trb)
workerstate.workerstate = 'crashed'
class SessionHandler(object):
"""thread handling one message"""
def __init__(self, protohandler, config, prependers, plugins, appenders):
self.logger = logging.getLogger("fuglu.SessionHandler")
self.action = DUNNO
self.config = config
self.prependers = prependers
self.plugins = plugins
self.appenders = appenders
self.stats = Statskeeper()
self.worker = None
self.message = None
self.protohandler = protohandler
def set_workerstate(self, status):
if self.worker is not None:
self.worker.workerstate = status
def handlesession(self, worker=None):
self.worker = worker
#--
# setup compliance checker if not already set up
#--
#
# Mail Address compliance check is global, make sure it is updated when config is changed
try:
addComCheck = self.config.get('main', 'address_compliance_checker')
except Exception as e:
# might happen for some tests which do not propagate defaults
addComCheck = Default
if addComCheck == "Default" and not isinstance(
Suspect.addrIsLegitimate, Default):
Suspect.addrIsLegitimate = Default()
elif addComCheck == "LazyQuotedLocalPart" and not isinstance(
Suspect.addrIsLegitimate, LazyQuotedLocalPart):
Suspect.addrIsLegitimate = LazyQuotedLocalPart()
else:
self.logger.error(
'Address Compliance Checker not recognized -> use Default')
Suspect.addrIsLegitimate = Default()
prependheader = self.config.get('main', 'prependaddedheaders')
try:
suspect = None
self.set_workerstate('receiving message')
suspect = self.protohandler.get_suspect()
if suspect is None:
self.logger.error('No Suspect retrieved, ending session')
return
self.stats.increase_counter_values(StatDelta(in_=1))
if len(suspect.recipients) != 1:
self.logger.warning(
'Notice: Message from %s has %s recipients. Plugins supporting only one recipient will see: %s'
% (suspect.from_address, len(
suspect.recipients), suspect.to_address))
self.logger.debug("Message from %s to %s: %s bytes stored to %s" %
(suspect.from_address, suspect.to_address,
suspect.size, suspect.tempfile))
self.set_workerstate("Handling message %s" % suspect)
# store incoming port to tag, could be used to disable plugins
# based on port
try:
port = self.protohandler.socket.getsockname()[1]
if port is not None:
suspect.tags['incomingport'] = port
except Exception as e:
self.logger.warning('Could not get incoming port: %s' % str(e))
pluglist = self.run_prependers(suspect)
starttime = time.time()
self.run_plugins(suspect, pluglist)
# Set fuglu spam status if wanted
if self.config.getboolean('main', 'spamstatusheader'):
if suspect.is_spam():
suspect.addheader("%sSpamstatus" % prependheader, 'YES')
else:
suspect.addheader("%sSpamstatus" % prependheader, 'NO')
# how long did it all take?
difftime = time.time() - starttime
suspect.tags['fuglu.scantime'] = "%.4f" % difftime
# Debug info to mail
if self.config.getboolean('main', 'debuginfoheader'):
debuginfo = str(suspect)
suspect.addheader("%sDebuginfo" % prependheader, debuginfo)
# add suspect id for tracking
if self.config.getboolean('main', 'suspectidheader'):
suspect.addheader('%sSuspect' % prependheader, suspect.id)
# checks done.. print out suspect status
logformat = self.config.get('main', 'logtemplate')
if logformat.strip() != '':
self.logger.info(suspect.log_format(logformat))
suspect.debug(suspect)
# check if one of the plugins made a decision
result = self.action
self.set_workerstate("Finishing message %s" % suspect)
message_is_deferred = False
if result == ACCEPT or result == DUNNO:
try:
self.protohandler.commitback(suspect)
self.stats.increase_counter_values(StatDelta(out=1))
except KeyboardInterrupt:
sys.exit()
except Exception:
message_is_deferred = True
trb = traceback.format_exc()
self.logger.error("Could not commit message. Error: %s" %
trb)
self._defer()
elif result == DELETE:
self.logger.info("MESSAGE DELETED: %s" % suspect.id)
retmesg = 'OK: (%s)' % suspect.id
if self.message is not None:
retmesg = self.message
self.protohandler.discard(retmesg)
elif result == REJECT:
retmesg = "Rejected by content scanner"
if self.message is not None:
retmesg = self.message
self.protohandler.reject(retmesg)
elif result == DEFER:
message_is_deferred = True
self._defer(self.message)
else:
self.logger.error(
'Invalid Message action Code: %s. Using DEFER' % result)
message_is_deferred = True
self._defer()
# run appenders (stats plugin etc) unless msg is deferred
if not message_is_deferred:
self.stats.increasecounters(suspect)
self.run_appenders(suspect, result)
else:
self.logger.warning("DEFERRED %s" % suspect.id)
# clean up
try:
os.remove(suspect.tempfile)
self.logger.debug('Removed tempfile %s' % suspect.tempfile)
suspect.tempfile = None
except OSError:
self.logger.warning('Could not remove tempfile %s' %
suspect.tempfile)
except KeyboardInterrupt:
sys.exit(0)
except ValueError:
# Error in envelope send/receive address
try:
address_compliance_fail_action = self.config.get(
'main', 'address_compliance_fail_action').lower()
except Exception:
address_compliance_fail_action = "defer"
try:
message = self.config.get('main',
'address_compliance_fail_message')
except Exception:
message = "invalid sender or recipient address"
if address_compliance_fail_action == "defer":
self._defer(message)
elif address_compliance_fail_action == "reject":
self._reject(message)
elif address_compliance_fail_action == "discard":
self._discard(message)
else:
self._defer(message)
except Exception as e:
exc = traceback.format_exc()
self.logger.error('Exception %s: %s' % (e, exc))
self._defer()
finally:
# finally is also executed if there's a return statement somewhere in try-except
if suspect is None:
# if there was an error creating the suspect, check if the filename can be
# extracted from the protohandler
tmpfilename = self.protohandler.get_tmpfile()
if tmpfilename is None:
tmpfilename = ""
if self.config.getboolean('main', 'remove_tmpfiles_on_error'):
self.logger.debug('Remove tmpfile: %s for failed message' %
tmpfilename)
self.protohandler.remove_tmpfile()
else:
self.logger.warning('Keep tmpfile: %s for failed message' %
tmpfilename)
elif suspect.tempfile is not None:
# suspect was created but not stopped cleanly
if self.config.getboolean('main', 'remove_tmpfiles_on_error'):
try:
os.remove(suspect.tempfile)
self.logger.debug('Removed tempfile %s' %
suspect.tempfile)
except OSError:
self.logger.warning('Could not remove tempfile %s' %
suspect.tempfile)
else:
self.logger.warning('Keep tempfile %s for failed message' %
suspect.tempfile)
self.logger.debug('Session finished')
def _discard(self, message=None):
if message is None:
message = "internal problem - discard"
# try to end the session gracefully, but this might cause the same exception again,
# in case of a broken pipe for example
try:
self.protohandler.discard(message)
except Exception:
pass
def _reject(self, message=None):
if message is None:
message = "internal problem - reject"
# try to end the session gracefully, but this might cause the same exception again,
# in case of a broken pipe for example
try:
self.protohandler.reject(message)
except Exception:
pass
def _defer(self, message=None):
if message is None:
message = "internal problem - message deferred"
# try to end the session gracefully, but this might cause the same exception again,
# in case of a broken pipe for example
try:
self.protohandler.defer(message)
except Exception:
pass
def trash(self, suspect, killerplugin=None):
"""copy suspect to trash if this is enabled"""
trashdir = self.config.get('main', 'trashdir').strip()
if trashdir == "":
return
if not os.path.isdir(trashdir):
try:
os.makedirs(trashdir)
except:
self.logger.error(
"Trashdir %s does not exist and could not be created" %
trashdir)
return
self.logger.info('Created trashdir %s' % trashdir)
trashfilename = ''
try:
handle, trashfilename = tempfile.mkstemp(prefix=suspect.id,
dir=self.config.get(
'main', 'trashdir'))
with os.fdopen(handle, 'w+b') as trashfile:
trashfile.write(suspect.get_source())
self.logger.debug('Message stored to trash: %s' % trashfilename)
except Exception as e:
self.logger.error("could not create file %s: %s" %
(trashfilename, e))
# TODO: document main.trashlog
if self.config.has_option('main',
'trashlog') and self.config.getboolean(
'main', 'trashlog'):
try:
with open(
'%s/00-fuglutrash.log' %
self.config.get('main', 'trashdir'), 'a') as handle:
# <date> <time> <from address> <to address> <plugin that said "DELETE"> <filename>
now = datetime.datetime.now().strftime("%Y-%m-%d %H:%M:%S")
handle.write(
"%s %s %s %s %s" %
(now, suspect.from_address, suspect.to_address,
killerplugin, trashfilename))
handle.write("\n")
except Exception as e:
self.logger.error("Could not update trash log: %s" % e)
def run_plugins(self, suspect, pluglist):
"""Run scannerplugins on suspect"""
suspect.debug('Will run plugins: %s' % pluglist)
for plugin in pluglist:
try:
self.logger.debug('Running plugin %s' % plugin)
self.set_workerstate("%s : Running Plugin %s" %
(suspect, plugin))
suspect.debug('Running plugin %s' % str(plugin))
starttime = time.time()
ans = plugin.examine(suspect)
plugintime = time.time() - starttime
suspect.tags['scantimes'].append((plugin.section, plugintime))
message = None
if type(ans) is tuple:
result, message = ans
else:
result = ans
if result is None:
result = DUNNO
suspect.tags['decisions'].append((plugin.section, result))
if result == DUNNO:
suspect.debug('Plugin makes no final decision')
elif result == ACCEPT:
suspect.debug(
'Plugin accepts the message - skipping all further tests'
)
self.logger.debug(
'Plugin says: ACCEPT. Skipping all other tests')
self.action = ACCEPT
break
elif result == DELETE:
suspect.debug(
'Plugin DELETES this message - no further tests')
self.logger.debug(
'Plugin says: DELETE. Skipping all other tests')
self.action = DELETE
self.message = message
self.trash(suspect, str(plugin))
break
elif result == REJECT:
suspect.debug(
'Plugin REJECTS this message - no further tests')
self.logger.debug(
'Plugin says: REJECT. Skipping all other tests')
self.action = REJECT
self.message = message
break
elif result == DEFER:
suspect.debug(
'Plugin DEFERS this message - no further tests')
self.logger.debug(
'Plugin says: DEFER. Skipping all other tests')
self.action = DEFER
self.message = message
break
else:
self.logger.error(
'Invalid Message action Code: %s. Using DUNNO' %
result)
except Exception as e:
CrashStore.store_exception()
exc = traceback.format_exc()
self.logger.error('Plugin %s failed: %s' % (str(plugin), exc))
suspect.debug(
'Plugin failed : %s . Please check fuglu log for more details'
% e)
def run_prependers(self, suspect):
"""Run prependers on suspect"""
plugcopy = self.plugins[:]
for plugin in self.prependers:
try:
self.logger.debug('Running prepender %s' % plugin)
self.set_workerstate("%s : Running Prepender %s" %
(suspect, plugin))
starttime = time.time()
result = plugin.pluginlist(suspect, plugcopy)
plugintime = time.time() - starttime
suspect.tags['scantimes'].append((plugin.section, plugintime))
if result is not None:
plugcopyset = set(plugcopy)
resultset = set(result)
removed = list(plugcopyset - resultset)
added = list(resultset - plugcopyset)
if len(removed) > 0:
self.logger.debug('Prepender %s removed plugins: %s' %
(plugin, list(map(str, removed))))
if len(added) > 0:
self.logger.debug('Prepender %s added plugins: %s' %
(plugin, list(map(str, added))))
plugcopy = result
except Exception:
CrashStore.store_exception()
exc = traceback.format_exc()
self.logger.error('Prepender plugin %s failed: %s' %
(str(plugin), exc))
return plugcopy
def run_appenders(self, suspect, finaldecision):
"""Run appenders on suspect"""
if suspect.get_tag('noappenders'):
return
for plugin in self.appenders:
try:
self.logger.debug('Running appender %s' % plugin)
suspect.debug('Running appender %s' % plugin)
self.set_workerstate("%s : Running appender %s" %
(suspect, plugin))
starttime = time.time()
plugin.process(suspect, finaldecision)
plugintime = time.time() - starttime
suspect.tags['scantimes'].append((plugin.section, plugintime))
except Exception:
CrashStore.store_exception()
exc = traceback.format_exc()
self.logger.error('Appender plugin %s failed: %s' %
(str(plugin), exc))
class SessionHandler(object):
"""thread handling one message"""
def __init__(self, protohandler, config, prependers, plugins, appenders):
self.logger = logging.getLogger("fuglu.SessionHandler")
self.action = DUNNO
self.config = config
self.prependers = prependers
self.plugins = plugins
self.appenders = appenders
self.stats = Statskeeper()
self.workerthread = None
self.message = None
self.protohandler = protohandler
def set_threadinfo(self, status):
if self.workerthread != None:
self.workerthread.threadinfo = status
def handlesession(self, workerthread=None):
self.workerthread = workerthread
starttime = time.time()
prependheader = self.config.get('main', 'prependaddedheaders')
try:
self.set_threadinfo('receiving message')
self.stats.incount += 1
suspect = self.protohandler.get_suspect()
if suspect == None:
self.logger.error('No Suspect retrieved, ending session')
return
if len(suspect.recipients) != 1:
self.logger.warning('Notice: Message from %s has %s recipients. Plugins supporting only one recipient will see: %s' % (
suspect.from_address, len(suspect.recipients), suspect.to_address))
self.logger.debug("Message from %s to %s: %s bytes stored to %s" % (
suspect.from_address, suspect.to_address, suspect.size, suspect.tempfile))
self.set_threadinfo("Handling message %s" % suspect)
# store incoming port to tag, could be used to disable plugins
# based on port
try:
port = self.protohandler.socket.getsockname()[1]
if port is not None:
suspect.tags['incomingport'] = port
except Exception as e:
self.logger.warning('Could not get incoming port: %s' % str(e))
pluglist = self.run_prependers(suspect)
starttime = time.time()
self.run_plugins(suspect, pluglist)
# Set fuglu spam status if wanted
if self.config.getboolean('main', 'spamstatusheader'):
if suspect.is_spam():
suspect.addheader("%sSpamstatus" % prependheader, 'YES')
else:
suspect.addheader("%sSpamstatus" % prependheader, 'NO')
# how long did it all take?
difftime = time.time() - starttime
suspect.tags['fuglu.scantime'] = "%.4f" % difftime
# Debug info to mail
if self.config.getboolean('main', 'debuginfoheader'):
debuginfo = str(suspect)
suspect.addheader("%sDebuginfo" % prependheader, debuginfo)
# add suspect id for tracking
if self.config.getboolean('main', 'suspectidheader'):
suspect.addheader('%sSuspect' % prependheader, suspect.id)
# checks done.. print out suspect status
logformat = self.config.get('main', 'logtemplate')
if logformat.strip() != '':
self.logger.info(suspect.log_format(logformat))
suspect.debug(suspect)
# check if one of the plugins made a decision
result = self.action
self.set_threadinfo("Finishing message %s" % suspect)
message_is_deferred = False
if result == ACCEPT or result == DUNNO:
try:
self.protohandler.commitback(suspect)
self.stats.outcount += 1
except KeyboardInterrupt:
sys.exit()
except Exception as e:
message_is_deferred = True
self.logger.error(
"Could not commit message. Error: %s" % e)
traceback.print_exc(file=sys.stdout)
self.protohandler.defer('Internal error trying to commit.')
elif result == DELETE:
self.logger.info("MESSAGE DELETED: %s" % suspect.id)
retmesg = 'OK: (%s)' % suspect.id
if self.message != None:
retmesg = self.message
self.protohandler.discard(retmesg)
elif result == REJECT:
retmesg = "Rejected by content scanner"
if self.message != None:
retmesg = self.message
self.protohandler.reject(retmesg)
elif result == DEFER:
message_is_deferred = True
retmesg = 'Internal problem - message deferred'
if self.message != None:
retmesg = self.message
self.protohandler.defer(retmesg)
else:
self.logger.error(
'Invalid Message action Code: %s. Using DEFER' % result)
message_is_deferred = True
self.protohandler.defer('Internal problem - message deferred')
# run appenders (stats plugin etc) unless msg is deferred
if not message_is_deferred:
self.stats.increasecounters(suspect)
self.run_appenders(suspect, result)
else:
self.logger.warning("DEFERRED %s" % suspect.id)
# clean up
try:
os.remove(suspect.tempfile)
self.logger.debug('Removed tempfile %s' % suspect.tempfile)
except:
self.logger.warning(
'Could not remove tempfile %s' % suspect.tempfile)
except KeyboardInterrupt:
sys.exit(0)
except Exception as e:
exc = traceback.format_exc()
self.logger.error('Exception %s: %s' % (e, exc))
#try to end the session gracefully, but this might cause the same exception again,
#in case of a broken pipe for example
try:
self.protohandler.defer("internal problem - message deferred")
except:
pass
self.logger.debug('Session finished')
def trash(self, suspect, killerplugin=None):
"""copy suspect to trash if this is enabled"""
trashdir = self.config.get('main', 'trashdir').strip()
if trashdir == "":
return
if not os.path.isdir(trashdir):
try:
os.makedirs(trashdir)
except:
self.logger.error(
"Trashdir %s does not exist and could not be created" % trashdir)
return
self.logger.info('Created trashdir %s' % trashdir)
try:
(handle, trashfilename) = tempfile.mkstemp(
prefix=suspect.id, dir=self.config.get('main', 'trashdir'))
trashfile = os.fdopen(handle, 'w+b')
trashfile.write(suspect.get_source())
trashfile.close()
self.logger.debug('Message stored to trash: %s' % trashfilename)
except Exception as e:
self.logger.error(
"could not create file %s: %s" % (trashfilename, e))
# TODO: document main.trashlog
if self.config.has_option('main', 'trashlog') and self.config.getboolean('main', 'trashlog'):
try:
handle = open('%s/00-fuglutrash.log' %
self.config.get('main', 'trashdir'), 'a')
# <date> <time> <from address> <to address> <plugin that said "DELETE"> <filename>
time = datetime.datetime.now().strftime("%Y-%m-%d %H:%M:%S")
handle.write("%s %s %s %s %s" % (
time, suspect.from_address, suspect.to_address, killerplugin, trashfilename))
handle.write("\n")
handle.close()
except Exception as e:
self.logger.error("Could not update trash log: %s" % e)
def run_plugins(self, suspect, pluglist):
"""Run scannerplugins on suspect"""
suspect.debug('Will run plugins: %s' % pluglist)
for plugin in pluglist:
try:
self.logger.debug('Running plugin %s' % plugin)
self.set_threadinfo(
"%s : Running Plugin %s" % (suspect, plugin))
suspect.debug('Running plugin %s' % str(plugin))
starttime = time.time()
ans = plugin.examine(suspect)
plugintime = time.time() - starttime
suspect.tags['scantimes'].append((plugin.section, plugintime))
message = None
if type(ans) is tuple:
result, message = ans
else:
result = ans
if result == None:
result = DUNNO
suspect.tags['decisions'].append((plugin.section, result))
if result == DUNNO:
suspect.debug('Plugin makes no final decision')
elif result == ACCEPT:
suspect.debug(
'Plugin accepts the message - skipping all further tests')
self.logger.debug(
'Plugin says: ACCEPT. Skipping all other tests')
self.action = ACCEPT
break
elif result == DELETE:
suspect.debug(
'Plugin DELETES this message - no further tests')
self.logger.debug(
'Plugin says: DELETE. Skipping all other tests')
self.action = DELETE
self.message = message
self.trash(suspect, str(plugin))
break
elif result == REJECT:
suspect.debug(
'Plugin REJECTS this message - no further tests')
self.logger.debug(
'Plugin says: REJECT. Skipping all other tests')
self.action = REJECT
self.message = message
break
elif result == DEFER:
suspect.debug(
'Plugin DEFERS this message - no further tests')
self.logger.debug(
'Plugin says: DEFER. Skipping all other tests')
self.action = DEFER
self.message = message
break
else:
self.logger.error(
'Invalid Message action Code: %s. Using DUNNO' % result)
except Exception as e:
CrashStore.store_exception()
exc = traceback.format_exc()
self.logger.error('Plugin %s failed: %s' % (str(plugin), exc))
suspect.debug(
'Plugin failed : %s . Please check fuglu log for more details' % e)
def run_prependers(self, suspect):
"""Run prependers on suspect"""
plugcopy = self.plugins[:]
for plugin in self.prependers:
try:
self.logger.debug('Running prepender %s' % plugin)
self.set_threadinfo(
"%s : Running Prepender %s" % (suspect, plugin))
starttime = time.time()
result = plugin.pluginlist(suspect, plugcopy)
plugintime = time.time() - starttime
suspect.tags['scantimes'].append((plugin.section, plugintime))
if result != None:
plugcopyset = set(plugcopy)
resultset = set(result)
removed = list(plugcopyset - resultset)
added = list(resultset - plugcopyset)
if len(removed) > 0:
self.logger.debug(
'Prepender %s removed plugins: %s' % (plugin, list(map(str, removed))))
if len(added) > 0:
self.logger.debug(
'Prepender %s added plugins: %s' % (plugin, list(map(str, added))))
plugcopy = result
except Exception:
CrashStore.store_exception()
exc = traceback.format_exc()
self.logger.error(
'Prepender plugin %s failed: %s' % (str(plugin), exc))
return plugcopy
def run_appenders(self, suspect, finaldecision):
"""Run appenders on suspect"""
if suspect.get_tag('noappenders'):
return
for plugin in self.appenders:
try:
self.logger.debug('Running appender %s' % plugin)
suspect.debug('Running appender %s' % plugin)
self.set_threadinfo(
"%s : Running appender %s" % (suspect, plugin))
starttime = time.time()
plugin.process(suspect, finaldecision)
plugintime = time.time() - starttime
suspect.tags['scantimes'].append((plugin.section, plugintime))
except Exception:
CrashStore.store_exception()
exc = traceback.format_exc()
self.logger.error(
'Appender plugin %s failed: %s' % (str(plugin), exc))
class SessionHandler(object):
"""thread handling one message"""
def __init__(self, protohandler, config, prependers, plugins, appenders):
self.logger = logging.getLogger("fuglu.SessionHandler")
self.action = DUNNO
self.config = config
self.prependers = prependers
self.plugins = plugins
self.appenders = appenders
self.stats = Statskeeper()
self.workerthread = None
self.message = None
self.protohandler = protohandler
def set_threadinfo(self, status):
if self.workerthread != None:
self.workerthread.threadinfo = status
def handlesession(self, workerthread=None):
self.workerthread = workerthread
starttime = time.time()
prependheader = self.config.get('main', 'prependaddedheaders')
try:
self.set_threadinfo('receiving message')
self.stats.incount += 1
suspect = self.protohandler.get_suspect()
if suspect == None:
self.logger.error('No Suspect retrieved, ending session')
return
if len(suspect.recipients) != 1:
self.logger.warning(
'Notice: Message from %s has %s recipients. Plugins supporting only one recipient will see: %s'
% (suspect.from_address, len(
suspect.recipients), suspect.to_address))
self.logger.debug("Message from %s to %s: %s bytes stored to %s" %
(suspect.from_address, suspect.to_address,
suspect.size, suspect.tempfile))
self.set_threadinfo("Handling message %s" % suspect)
# store incoming port to tag, could be used to disable plugins
# based on port
try:
port = self.protohandler.socket.getsockname()[1]
if port is not None:
suspect.tags['incomingport'] = port
except Exception as e:
self.logger.warning('Could not get incoming port: %s' % str(e))
pluglist = self.run_prependers(suspect)
starttime = time.time()
self.run_plugins(suspect, pluglist)
# Set fuglu spam status if wanted
if self.config.getboolean('main', 'spamstatusheader'):
if suspect.is_spam():
suspect.addheader("%sSpamstatus" % prependheader, 'YES')
else:
suspect.addheader("%sSpamstatus" % prependheader, 'NO')
# how long did it all take?
difftime = time.time() - starttime
suspect.tags['fuglu.scantime'] = "%.4f" % difftime
# Debug info to mail
if self.config.getboolean('main', 'debuginfoheader'):
debuginfo = str(suspect)
suspect.addheader("%sDebuginfo" % prependheader, debuginfo)
# add suspect id for tracking
if self.config.getboolean('main', 'suspectidheader'):
suspect.addheader('%sSuspect' % prependheader, suspect.id)
# checks done.. print out suspect status
logformat = self.config.get('main', 'logtemplate')
if logformat.strip() != '':
self.logger.info(suspect.log_format(logformat))
suspect.debug(suspect)
# check if one of the plugins made a decision
result = self.action
self.set_threadinfo("Finishing message %s" % suspect)
message_is_deferred = False
if result == ACCEPT or result == DUNNO:
try:
self.protohandler.commitback(suspect)
self.stats.outcount += 1
except KeyboardInterrupt:
sys.exit()
except Exception as e:
message_is_deferred = True
self.logger.error("Could not commit message. Error: %s" %
e)
traceback.print_exc(file=sys.stdout)
self.protohandler.defer('Internal error trying to commit.')
elif result == DELETE:
self.logger.info("MESSAGE DELETED: %s" % suspect.id)
retmesg = 'OK: (%s)' % suspect.id
if self.message != None:
retmesg = self.message
self.protohandler.discard(retmesg)
elif result == REJECT:
retmesg = "Rejected by content scanner"
if self.message != None:
retmesg = self.message
self.protohandler.reject(retmesg)
elif result == DEFER:
message_is_deferred = True
retmesg = 'Internal problem - message deferred'
if self.message != None:
retmesg = self.message
self.protohandler.defer(retmesg)
else:
self.logger.error(
'Invalid Message action Code: %s. Using DEFER' % result)
message_is_deferred = True
self.protohandler.defer('Internal problem - message deferred')
# run appenders (stats plugin etc) unless msg is deferred
if not message_is_deferred:
self.stats.increasecounters(suspect)
self.run_appenders(suspect, result)
else:
self.logger.warning("DEFERRED %s" % suspect.id)
# clean up
try:
os.remove(suspect.tempfile)
self.logger.debug('Removed tempfile %s' % suspect.tempfile)
except:
self.logger.warning('Could not remove tempfile %s' %
suspect.tempfile)
except KeyboardInterrupt:
sys.exit(0)
except Exception as e:
exc = traceback.format_exc()
self.logger.error('Exception %s: %s' % (e, exc))
#try to end the session gracefully, but this might cause the same exception again,
#in case of a broken pipe for example
try:
self.protohandler.defer("internal problem - message deferred")
except:
pass
self.logger.debug('Session finished')
def trash(self, suspect, killerplugin=None):
"""copy suspect to trash if this is enabled"""
trashdir = self.config.get('main', 'trashdir').strip()
if trashdir == "":
return
if not os.path.isdir(trashdir):
try:
os.makedirs(trashdir)
except:
self.logger.error(
"Trashdir %s does not exist and could not be created" %
trashdir)
return
self.logger.info('Created trashdir %s' % trashdir)
try:
(handle, trashfilename) = tempfile.mkstemp(prefix=suspect.id,
dir=self.config.get(
'main', 'trashdir'))
trashfile = os.fdopen(handle, 'w+b')
trashfile.write(suspect.get_source())
trashfile.close()
self.logger.debug('Message stored to trash: %s' % trashfilename)
except Exception as e:
self.logger.error("could not create file %s: %s" %
(trashfilename, e))
# TODO: document main.trashlog
if self.config.has_option('main',
'trashlog') and self.config.getboolean(
'main', 'trashlog'):
try:
handle = open(
'%s/00-fuglutrash.log' %
self.config.get('main', 'trashdir'), 'a')
# <date> <time> <from address> <to address> <plugin that said "DELETE"> <filename>
time = datetime.datetime.now().strftime("%Y-%m-%d %H:%M:%S")
handle.write("%s %s %s %s %s" %
(time, suspect.from_address, suspect.to_address,
killerplugin, trashfilename))
handle.write("\n")
handle.close()
except Exception as e:
self.logger.error("Could not update trash log: %s" % e)
def run_plugins(self, suspect, pluglist):
"""Run scannerplugins on suspect"""
suspect.debug('Will run plugins: %s' % pluglist)
for plugin in pluglist:
try:
self.logger.debug('Running plugin %s' % plugin)
self.set_threadinfo("%s : Running Plugin %s" %
(suspect, plugin))
suspect.debug('Running plugin %s' % str(plugin))
starttime = time.time()
ans = plugin.examine(suspect)
plugintime = time.time() - starttime
suspect.tags['scantimes'].append((plugin.section, plugintime))
message = None
if type(ans) is tuple:
result, message = ans
else:
result = ans
if result == None:
result = DUNNO
suspect.tags['decisions'].append((plugin.section, result))
if result == DUNNO:
suspect.debug('Plugin makes no final decision')
elif result == ACCEPT:
suspect.debug(
'Plugin accepts the message - skipping all further tests'
)
self.logger.debug(
'Plugin says: ACCEPT. Skipping all other tests')
self.action = ACCEPT
break
elif result == DELETE:
suspect.debug(
'Plugin DELETES this message - no further tests')
self.logger.debug(
'Plugin says: DELETE. Skipping all other tests')
self.action = DELETE
self.message = message
self.trash(suspect, str(plugin))
break
elif result == REJECT:
suspect.debug(
'Plugin REJECTS this message - no further tests')
self.logger.debug(
'Plugin says: REJECT. Skipping all other tests')
self.action = REJECT
self.message = message
break
elif result == DEFER:
suspect.debug(
'Plugin DEFERS this message - no further tests')
self.logger.debug(
'Plugin says: DEFER. Skipping all other tests')
self.action = DEFER
self.message = message
break
else:
self.logger.error(
'Invalid Message action Code: %s. Using DUNNO' %
result)
except Exception as e:
CrashStore.store_exception()
exc = traceback.format_exc()
self.logger.error('Plugin %s failed: %s' % (str(plugin), exc))
suspect.debug(
'Plugin failed : %s . Please check fuglu log for more details'
% e)
def run_prependers(self, suspect):
"""Run prependers on suspect"""
plugcopy = self.plugins[:]
for plugin in self.prependers:
try:
self.logger.debug('Running prepender %s' % plugin)
self.set_threadinfo("%s : Running Prepender %s" %
(suspect, plugin))
starttime = time.time()
result = plugin.pluginlist(suspect, plugcopy)
plugintime = time.time() - starttime
suspect.tags['scantimes'].append((plugin.section, plugintime))
if result != None:
plugcopyset = set(plugcopy)
resultset = set(result)
removed = list(plugcopyset - resultset)
added = list(resultset - plugcopyset)
if len(removed) > 0:
self.logger.debug('Prepender %s removed plugins: %s' %
(plugin, list(map(str, removed))))
if len(added) > 0:
self.logger.debug('Prepender %s added plugins: %s' %
(plugin, list(map(str, added))))
plugcopy = result
except Exception:
CrashStore.store_exception()
exc = traceback.format_exc()
self.logger.error('Prepender plugin %s failed: %s' %
(str(plugin), exc))
return plugcopy
def run_appenders(self, suspect, finaldecision):
"""Run appenders on suspect"""
if suspect.get_tag('noappenders'):
return
for plugin in self.appenders:
try:
self.logger.debug('Running appender %s' % plugin)
suspect.debug('Running appender %s' % plugin)
self.set_threadinfo("%s : Running appender %s" %
(suspect, plugin))
starttime = time.time()
plugin.process(suspect, finaldecision)
plugintime = time.time() - starttime
suspect.tags['scantimes'].append((plugin.section, plugintime))
except Exception:
CrashStore.store_exception()
exc = traceback.format_exc()
self.logger.error('Appender plugin %s failed: %s' %
(str(plugin), exc))
def fuglu_process_worker(queue, config, shared_state, child_to_server_messages,
logQueue):
signal.signal(signal.SIGHUP, signal.SIG_IGN)
logtools.client_configurer(logQueue)
logging.basicConfig(level=logging.DEBUG)
workerstate = WorkerStateWrapper(shared_state, 'loading configuration')
logger = logging.getLogger(
'fuglu.process.%s(%u)' %
(workerstate.process.name, workerstate.process.pid))
logger.debug("New worker: %s" % logtools.createPIDinfo())
# Setup address compliance checker
# -> Due to default linux forking behavior this should already
# have the correct setup but it's better not to rely on this
try:
address_check = config.get('main', 'address_compliance_checker')
except Exception as e:
# might happen for some tests which do not propagate defaults
address_check = "Default"
Addrcheck().set(address_check)
# load config and plugins
logger.debug("Create MainController")
controller = fuglu.core.MainController(config,
logQueue=logQueue,
nolog=True)
controller.load_extensions()
controller.load_plugins()
prependers = controller.prependers
plugins = controller.plugins
appenders = controller.appenders
# forward statistics counters to parent process
stats = Statskeeper()
stats.stat_listener_callback.append(
lambda event: child_to_server_messages.put(event.as_message()))
logger.debug("%s: Enter service loop..." % logtools.createPIDinfo())
try:
while True:
workerstate.workerstate = 'waiting for task'
logger.debug("%s: Child process waiting for task" %
logtools.createPIDinfo())
task = queue.get()
if task is None: # poison pill
logger.debug(
"%s: Child process received poison pill - shut down" %
logtools.createPIDinfo())
try:
# it might be possible it does not work to properly set the workerstate
# since this is a shared variable -> prevent exceptions
workerstate.workerstate = 'ended (poison pill)'
except Exception as e:
logger.debug(
"Exception setting workstate while getting poison pill"
)
logger.exception(e)
pass
finally:
return
workerstate.workerstate = 'starting scan session'
logger.debug("%s: Child process starting scan session" %
logtools.createPIDinfo())
sock, handler_modulename, handler_classname, port = uncompress_task(
task)
handler_class = getattr(
importlib.import_module(handler_modulename), handler_classname)
handler_instance = handler_class(sock, config)
handler = SessionHandler(handler_instance, config, prependers,
plugins, appenders, port)
handler.handlesession(workerstate)
del handler
del handler_instance
del handler_class
del handler_modulename
del handler_classname
del sock
# developers only:
# for debugging memory this can be enabled
# Note this can NOT be copied to threadpool worker because
# it will create a memory leak
if OBJGRAPH_EXTENSION_ENABLED and False:
debug_procpoolworkermemory(logger, config)
except KeyboardInterrupt:
workerstate.workerstate = 'ended (keyboard interrupt)'
logger.debug("Keyboard interrupt")
except Exception as e:
logger.error("Exception in worker process: %s" % str(e))
workerstate.workerstate = 'crashed'
finally:
# this process will not put any object in queue
queue.close()
controller.shutdown()
