Worker: logging config is now stored in config file

packages/flamenco-worker-python/flamenco-worker.cfg

@@ -2,3 +2,36 @@
 manager_url = http://localhost:8083/
 job_types = sleep blender-render
 task_update_queue_db = flamenco-worker.db
+
+[loggers]
+keys = root,flamenco_worker
+
+[logger_root]
+level = WARNING
+handlers = console,file
+
+[logger_flamenco_worker]
+level = INFO
+qualname = flamenco_worker
+handlers = console,file
+propagate = 0
+
+[handlers]
+keys = console,file
+
+[handler_console]
+class = logging.StreamHandler
+formatter = flamenco
+args = (sys.stderr,)
+
+[handler_file]
+class = logging.handlers.TimedRotatingFileHandler
+formatter = flamenco
+# (filename, when, interval, backupCount, encoding, delay, utc, atTime=None)
+args = ('/tmp/flamenco-worker.log', 'midnight', 1, 7, 'utf8', True, True)
+
+[formatters]
+keys = flamenco
+
+[formatter_flamenco]
+format = %(asctime)-15s %(levelname)8s %(name)s %(message)s

packages/flamenco-worker-python/flamenco_worker/cli.py

@@ -11,48 +11,18 @@ def main():
     parser = argparse.ArgumentParser()
     parser.add_argument('-c', '--config',
                         help='Load this configuration file instead of the default files.')
-    parser.add_argument('-q', '--quiet', action='store_true',
-                        help='Log less (only WARNING and more severe).')
     parser.add_argument('-v', '--verbose', action='store_true',
-                        help='Log more (DEBUG and more severe).')
+                        help='Show configuration before starting, '
+                             'and asyncio task status at shutdown.')
     args = parser.parse_args()
 
-    # Set up logging
-    if args.quiet:
-        level = 'WARNING'
-    elif args.verbose:
-        level = 'DEBUG'
-    else:
-        level = 'INFO'
-    logging.config.dictConfig({
-        'version': 1,
-        'formatters': {
-            'default': {'format': '%(asctime)-15s %(levelname)8s %(name)s %(message)s'}
-        },
-        'handlers': {
-            'console': {
-                'class': 'logging.StreamHandler',
-                'formatter': 'default',
-                'stream': 'ext://sys.stderr',
-            }
-        },
-        'loggers': {
-            'flamenco_worker': {'level': level},
-        },
-        'root': {
-            'level': 'WARNING',
-            'handlers': [
-                'console',
-            ],
-        }
-    })
-
-    log = logging.getLogger(__name__)
-    log.debug('Starting')
-
     # Load configuration
     from . import config
     confparser = config.load_config(args.config, args.verbose)
+    config.configure_logging(confparser)
+
+    log = logging.getLogger(__name__)
+    log.debug('Starting')
 
     # Construct the AsyncIO loop
     loop = construct_asyncio_loop()
@@ -126,11 +96,12 @@ def main():
     log.warning('Closing asyncio loop')
 
     # Report on the asyncio task status
-    all_tasks = asyncio.Task.all_tasks()
-    if not len(all_tasks):
-        log.debug('no more scheduled tasks, this is a clean shutdown.')
-    elif all(task.done() for task in all_tasks):
-        log.debug('all %i tasks are done, this is a clean shutdown.', len(all_tasks))
+    if args.verbose:
+        all_tasks = asyncio.Task.all_tasks()
+        if not len(all_tasks):
+            log.info('no more scheduled tasks, this is a clean shutdown.')
+        elif all(task.done() for task in all_tasks):
+            log.info('all %i tasks are done, this is a clean shutdown.', len(all_tasks))
 
         import gc
         import traceback
@@ -145,15 +116,15 @@ def main():
             # noinspection PyBroadException
             try:
                 res = task.result()
-                log.debug('   task #%i: %s result=%r', task_idx, task, res)
+                log.info('   task #%i: %s result=%r', task_idx, task, res)
             except asyncio.CancelledError:
                 # No problem, we want to stop anyway.
-                log.debug('   task #%i: %s cancelled', task_idx, task)
+                log.info('   task #%i: %s cancelled', task_idx, task)
             except Exception:
                 print('{}: resulted in exception'.format(task))
                 traceback.print_exc()
             # for ref in gc.get_referrers(task):
-            #     log.debug('      - referred by %s', ref)
+            #     log.info('      - referred by %s', ref)
 
     loop.close()
 

packages/flamenco-worker-python/flamenco_worker/config.py

@@ -48,7 +48,12 @@ def load_config(config_file: str = None,
                 show_effective_config: bool = False) -> configparser.ConfigParser:
     """Loads one or more configuration files."""
 
-    confparser = configparser.ConfigParser()
+    # Logging and the default interpolation of configparser both use the
+    # same syntax for variables. To make it easier to work with, we use
+    # another interpolation for config files, so they now use ${loglevel}
+    # whereas logging still uses %(levelname)s.
+    confparser = configparser.ConfigParser(
+        interpolation=configparser.ExtendedInterpolation())
     confparser.read_dict(DEFAULT_CONFIG)
 
     if config_file:
@@ -64,10 +69,19 @@ def load_config(config_file: str = None,
     if show_effective_config:
         import sys
         log.info('Effective configuration:')
-        to_show = configparser.ConfigParser()
+        to_show = configparser.ConfigParser(
+            interpolation=configparser.ExtendedInterpolation()
+        )
         to_show.read_dict(confparser)
         if to_show.get(CONFIG_SECTION, 'worker_secret'):
             to_show.set(CONFIG_SECTION, 'worker_secret', '-hidden-')
         to_show.write(sys.stderr)
 
     return confparser
+
+
+def configure_logging(confparser: configparser.ConfigParser):
+    import logging.config
+
+    logging.config.fileConfig(confparser, disable_existing_loggers=True)
+    logging.captureWarnings(capture=True)