Unify logging with QueueHandler (smicallef#1292)

* Unify logging with QueueHandler

sf.py

@@ -21,47 +21,19 @@
 import sys
 import time
 from copy import deepcopy
-from logging import handlers
 
 import cherrypy
 import cherrypy_cors
 from cherrypy.lib import auth_digest
 
 from sflib import SpiderFoot
-from sfscan import SpiderFootScanner
+from sfscan import startSpiderFootScanner
 from sfwebui import SpiderFootWebUi
 from spiderfoot import SpiderFootHelpers
 from spiderfoot import SpiderFootDb
+from spiderfoot.logger import logListenerSetup, logWorkerSetup
 from spiderfoot import __version__
 
-log = logging.getLogger()
-log.setLevel(logging.DEBUG)
-log_format = logging.Formatter("%(asctime)s [%(levelname)s] %(message)s")
-
-debug_handler = handlers.TimedRotatingFileHandler(
-    "log/spiderfoot.debug.log",
-    when="d",
-    interval=1,
-    backupCount=30
-)
-debug_handler.setLevel(logging.DEBUG)
-debug_handler.setFormatter(log_format)
-log.addHandler(debug_handler)
-
-error_handler = handlers.TimedRotatingFileHandler(
-    "log/spiderfoot.error.log",
-    when="d",
-    interval=1,
-    backupCount=30
-)
-error_handler.setLevel(logging.WARN)
-error_handler.setFormatter(log_format)
-log.addHandler(error_handler)
-
-console_handler = logging.StreamHandler(sys.stderr)
-console_handler.setFormatter(log_format)
-log.addHandler(console_handler)
-
 scanId = None
 dbh = None
 
@@ -142,15 +114,17 @@ def main():
 
     if args.debug:
         sfConfig['_debug'] = True
-        log.setLevel(logging.DEBUG)
     else:
-        log.setLevel(logging.INFO)
         sfConfig['_debug'] = False
 
     if args.q:
-        log.setLevel(logging.NOTSET)
         sfConfig['__logging'] = False
 
+    loggingQueue = mp.Queue()
+    logListenerSetup(loggingQueue, sfConfig)
+    logWorkerSetup(loggingQueue)
+    log = logging.getLogger(f"spiderfoot.{__name__}")
+
     sfModules = dict()
     sft = SpiderFoot(sfConfig)
 
@@ -221,20 +195,23 @@ def main():
         sfWebUiConfig['host'] = host
         sfWebUiConfig['port'] = port
 
-        start_web_server(sfWebUiConfig, sfConfig)
+        start_web_server(sfWebUiConfig, sfConfig, loggingQueue)
         exit(0)
 
-    start_scan(sfConfig, sfModules, args)
+    start_scan(sfConfig, sfModules, args, loggingQueue)
 
 
-def start_scan(sfConfig, sfModules, args):
+def start_scan(sfConfig, sfModules, args, loggingQueue):
     """Start scan
 
     Args:
         sfConfig (dict): SpiderFoot config options
         sfModules (dict): modules
         args (argparse.Namespace): command line args
+        loggingQueue (Queue): main SpiderFoot logging queue
     """
+    log = logging.getLogger(f"spiderfoot.{__name__}")
+
     global dbh
     global scanId
 
@@ -413,7 +390,7 @@ def start_scan(sfConfig, sfModules, args):
     scanName = target
     scanId = SpiderFootHelpers.genScanInstanceId()
     try:
-        p = mp.Process(target=SpiderFootScanner, args=(scanName, scanId, target, targetType, modlist, cfg))
+        p = mp.Process(target=startSpiderFootScanner, args=(loggingQueue, scanName, scanId, target, targetType, modlist, cfg))
         p.daemon = True
         p.start()
     except BaseException as e:
@@ -436,13 +413,14 @@ def start_scan(sfConfig, sfModules, args):
     return
 
 
-def start_web_server(sfWebUiConfig, sfConfig):
+def start_web_server(sfWebUiConfig, sfConfig, loggingQueue=None):
     """Start the web server so you can start looking at results
 
     Args:
         sfWebUiConfig (dict): web server options
         sfConfig (dict): SpiderFoot config options
     """
+    log = logging.getLogger(f"spiderfoot.{__name__}")
 
     web_host = sfWebUiConfig.get('host', '127.0.0.1')
     web_port = sfWebUiConfig.get('port', 5001)
@@ -560,7 +538,7 @@ def start_web_server(sfWebUiConfig, sfConfig):
     # Disable auto-reloading of content
     cherrypy.engine.autoreload.unsubscribe()
 
-    cherrypy.quickstart(SpiderFootWebUi(sfWebUiConfig, sfConfig), script_name=web_root, config=conf)
+    cherrypy.quickstart(SpiderFootWebUi(sfWebUiConfig, sfConfig, loggingQueue), script_name=web_root, config=conf)
 
 
 def handle_abort(signal, frame):
@@ -570,6 +548,8 @@ def handle_abort(signal, frame):
         signal: TBD
         frame: TBD
     """
+    log = logging.getLogger(f"spiderfoot.{__name__}")
+
     global dbh
     global scanId
 

sflib.py

@@ -58,7 +58,6 @@ class SpiderFoot:
     _scanId = None
     _socksProxy = None
     opts = dict()
-    log = logging.getLogger(__name__)
 
     def __init__(self, options):
         """Initialize SpiderFoot object.
@@ -74,6 +73,8 @@ def __init__(self, options):
 
         self.opts = deepcopy(options)
 
+        self.log = logging.getLogger(f"spiderfoot.{__name__}")
+
         # This is ugly but we don't want any fetches to fail - we expect
         # to encounter unverified SSL certs!
         ssl._create_default_https_context = ssl._create_unverified_context  # noqa: DUO122
@@ -184,27 +185,6 @@ def optValueToData(self, val):
 
         return val
 
-    def _dblog(self, level, message, component=None):
-        """Log a scan event.
-
-        Args:
-            level (str): log level
-            message (str): log message
-            component (str): component from which the log event originated
-
-        Returns:
-            bool: scan event logged successfully
-
-        Raises:
-            BaseException: internal error encountered attempting to access the database handler
-        """
-
-        if not self.dbh:
-            self.log.exception(f"No database handle. Could not log event to database: {message}")
-            raise BaseException(f"Internal Error Encountered: {message}")
-
-        return self.dbh.scanLogEvent(self.scanId, level, message, component)
-
     def error(self, message):
         """Print and log an error message
 
@@ -215,10 +195,7 @@ def error(self, message):
         if not self.opts['__logging']:
             return
 
-        if self.dbh:
-            self._dblog("ERROR", message)
-
-        self.log.error(message)
+        self.log.error(message, extra={'scanId': self._scanId})
 
     def fatal(self, error):
         """Print an error message and stacktrace then exit.
@@ -227,10 +204,7 @@ def fatal(self, error):
             error (str): error message
         """
 
-        if self.dbh:
-            self._dblog("FATAL", error)
-
-        self.log.critical(error)
+        self.log.critical(error, extra={'scanId': self._scanId})
 
         print(str(inspect.stack()))
 
@@ -246,10 +220,7 @@ def status(self, message):
         if not self.opts['__logging']:
             return
 
-        if self.dbh:
-            self._dblog("STATUS", message)
-
-        self.log.info(message)
+        self.log.info(message, extra={'scanId': self._scanId})
 
     def info(self, message):
         """Log and print an info message.
@@ -277,10 +248,7 @@ def info(self, message):
             else:
                 modName = mod.__name__
 
-        if self.dbh:
-            self._dblog("INFO", message, modName)
-
-        self.log.info(f"{modName} : {message}")
+        self.log.info(f"{modName} : {message}", extra={'scanId': self._scanId, 'component': modName})
 
     def debug(self, message):
         """Log and print a debug message.
@@ -309,10 +277,7 @@ def debug(self, message):
             else:
                 modName = mod.__name__
 
-        if self.dbh:
-            self._dblog("DEBUG", message, modName)
-
-        self.log.debug(f"{modName} : {message}")
+        self.log.debug(f"{modName} : {message}", extra={'scanId': self._scanId})
 
     @staticmethod
     def myPath():

sfscan.py

@@ -21,7 +21,12 @@
 import dns.resolver
 
 from sflib import SpiderFoot
-from spiderfoot import SpiderFootDb, SpiderFootEvent, SpiderFootPlugin, SpiderFootTarget, SpiderFootHelpers
+from spiderfoot import SpiderFootDb, SpiderFootEvent, SpiderFootPlugin, SpiderFootTarget, SpiderFootHelpers, logger
+
+
+def startSpiderFootScanner(loggingQueue, *args, **kwargs):
+    logger.logWorkerSetup(loggingQueue)
+    return SpiderFootScanner(*args, **kwargs)
 
 
 class SpiderFootScanner():

sfwebui.py

@@ -30,7 +30,8 @@
 from spiderfoot import SpiderFootHelpers
 from spiderfoot import __version__
 from sflib import SpiderFoot
-from sfscan import SpiderFootScanner
+from sfscan import startSpiderFootScanner
+from spiderfoot.logger import logListenerSetup, logWorkerSetup
 
 mp.set_start_method("spawn", force=True)
 
@@ -43,9 +44,8 @@ class SpiderFootWebUi:
     config = dict()
     token = None
     docroot = ''
-    log = logging.getLogger(__name__)
 
-    def __init__(self, web_config, config):
+    def __init__(self, web_config, config, loggingQueue=None):
         """Initialize web server
 
         Args:
@@ -76,6 +76,15 @@ def __init__(self, web_config, config):
         sf = SpiderFoot(self.defaultConfig)
         self.config = sf.configUnserialize(dbh.configGet(), self.defaultConfig)
 
+        # Set up logging
+        if loggingQueue is None:
+            self.loggingQueue = mp.Queue()
+            logListenerSetup(self.loggingQueue, self.config)
+        else:
+            self.loggingQueue = loggingQueue
+        logWorkerSetup(self.loggingQueue)
+        self.log = logging.getLogger(f"spiderfoot.{__name__}")
+
         cherrypy.config.update({
             'error_page.401': self.error_page_401,
             'error_page.404': self.error_page_404,
@@ -571,7 +580,7 @@ def rerunscan(self, id):
         # Start running a new scan
         scanId = SpiderFootHelpers.genScanInstanceId()
         try:
-            p = mp.Process(target=SpiderFootScanner, args=(scanname, scanId, scantarget, targetType, modlist, cfg))
+            p = mp.Process(target=startSpiderFootScanner, args=(self.loggingQueue, scanname, scanId, scantarget, targetType, modlist, cfg))
             p.daemon = True
             p.start()
         except Exception as e:
@@ -626,7 +635,7 @@ def rerunscanmulti(self, ids):
             # Start running a new scan
             scanId = SpiderFootHelpers.genScanInstanceId()
             try:
-                p = mp.Process(target=SpiderFootScanner, args=(scanname, scanId, scantarget, targetType, modlist, cfg))
+                p = mp.Process(target=startSpiderFootScanner, args=(self.loggingQueue, scanname, scanId, scantarget, targetType, modlist, cfg))
                 p.daemon = True
                 p.start()
             except Exception as e:
@@ -1201,7 +1210,7 @@ def startscan(self, scanname, scantarget, modulelist, typelist, usecase):
         # Start running a new scan
         scanId = SpiderFootHelpers.genScanInstanceId()
         try:
-            p = mp.Process(target=SpiderFootScanner, args=(scanname, scanId, scantarget, targetType, modlist, cfg))
+            p = mp.Process(target=startSpiderFootScanner, args=(self.loggingQueue, scanname, scanId, scantarget, targetType, modlist, cfg))
             p.daemon = True
             p.start()
         except Exception as e: