Add: use structured logging in qvarnbackend

We also hijack all the log messages logged via the Python stdlib
logging library so they don't get lost. Especially we hijack the ones
logged by gunicorn.

8 files changed, 99 insertions, 28 deletions

diff --git a/qvarn/__init__.py b/qvarn/__init__.py
index a58e52d..5bec17f 100644
--- a/qvarn/__init__.py
+++ b/qvarn/__init__.py
@@ -15,6 +15,9 @@
 
 
 from .version import __version__, __version_info__
+from .logging import log, setup_logging
+from .idgen import ResourceIdGenerator
+from .resource_type import ResourceType
 
 from .objstore import (
     ObjectStoreInterface,
@@ -26,9 +29,6 @@ from .objstore import (
     All,
 )
 
-from .idgen import ResourceIdGenerator
-from .resource_type import ResourceType
-
 from .collection import (
     CollectionAPI,
     HasId,
diff --git a/qvarn/logging.py b/qvarn/logging.py
new file mode 100644
index 0000000..61d62f4
--- /dev/null
+++ b/qvarn/logging.py
@@ -0,0 +1,60 @@
+# Copyright (C) 2017  Lars Wirzenius
+#
+# This program is free software: you can redistribute it and/or modify
+# it under the terms of the GNU Affero General Public License as
+# published by the Free Software Foundation, either version 3 of the
+# License, or (at your option) any later version.
+#
+# This program is distributed in the hope that it will be useful,
+# but WITHOUT ANY WARRANTY; without even the implied warranty of
+# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+# GNU Affero General Public License for more details.
+#
+# You should have received a copy of the GNU Affero General Public License
+# along with this program.  If not, see <http://www.gnu.org/licenses/>.
+
+
+import slog
+
+
+# We are probably run under gunicorn, which sets up logging via the
+# logging library. Hijack that so actual logging happens via the slog
+# library. For this, we need to know the logger names gunicorn uses.
+gunicorn_loggers = ['gunicorn.access', 'gunicorn.error']
+
+
+# This sets up a global log variable that doesn't actually log
+# anything anywhere. This is useful so that code can unconditionally
+# call log.log(...) from anywhere. See setup_logging() for setting up
+# actual logging to somewhere persistent.
+
+log = slog.StructuredLog()
+log.add_log_writer(slog.NullSlogWriter(), slog.FilterAllow())
+slog.hijack_logging(log, logger_names=gunicorn_loggers)
+
+
+def setup_logging(config):
+    for target in config.get('log', []):
+        setup_logging_to_target(target)
+
+
+def setup_logging_to_target(target):
+    rule = get_filter_rules(target)
+    if 'filename' in target:
+        setup_logging_to_file(target, rule)
+    else:
+        raise Exception('Do not understand logging target %r' % target)
+
+
+def get_filter_rules(target):
+    if 'filter' in target:
+        return slog.construct_log_filter(target['filter'])
+    return slog.FilterAllow()
+
+
+def setup_logging_to_file(target, rule):
+    writer = slog.FileSlogWriter()
+    writer.set_filename(target['filename'])
+    if 'max_bytes' in target:
+        writer.set_max_file_size(target['max_bytes'])
+    log.add_log_writer(writer, rule)
diff --git a/qvarnbackend.py b/qvarnbackend.py
index b42d29b..74e3c88 100644
--- a/qvarnbackend.py
+++ b/qvarnbackend.py
@@ -27,25 +27,14 @@ import yaml
 
 import apifw
 import qvarn
+import slog
 
 
 DEFAULT_CONFIG_FILE = '/dev/null'
 
 
 def dict_logger(log, stack_info=None):
-    logging.info('Start log entry')
-    for key in sorted(log.keys()):
-        logging.info('  %r=%r', key, log[key])
-    logging.info('Endlog entry')
-    if stack_info:
-        logging.info('Traceback', exc_info=True)
-
-
-
-def setup_logging(config):
-    filename = config.get('log')
-    if filename:
-        logging.basicConfig(filename=filename, level=logging.DEBUG)
+    qvarn.log.log(exc_info=stack_info, **log)
 
 
 def read_config(config_filename):
@@ -65,14 +54,16 @@ default_config = {
     'token-public-key': None,
     'token-audience': None,
     'token-issuer': None,
+    'log': [],
 }
 
 
 actual_config = read_config(os.environ.get('QVARN_CONFIG', DEFAULT_CONFIG_FILE))
 config = dict(default_config)
-config.update(actual_config)
+config.update(actual_config or {})
 check_config(config)
-setup_logging(config)
+qvarn.setup_logging(config)
+qvarn.log.log('info', msg_text='Qvarn backend starting')
 
 subject = qvarn.ResourceType()
 subject.from_spec({
diff --git a/run-qvarn-debug b/run-qvarn-debug
index b15025a..5659499 100755
--- a/run-qvarn-debug
+++ b/run-qvarn-debug
@@ -42,12 +42,12 @@ AUD=aud
 ./create-token "$tmp/key" "$ISS" "$AUD" "$scopes" > "$token"
 
 cat <<EOF > "$tmp/qvarn.yaml"
-log: qvarn.log
+log: 
+  - filename: qvarn.log
 token-issuer: $ISS
 token-audience: $AUD
 token-public-key: $(cat "$tmp/key.pub")
 EOF
 export QVARN_CONFIG="$tmp/qvarn.yaml"
 
-gunicorn3 --bind 127.0.0.1:12765 -p "$tmp/pid" -w1 \
-          --log-file "qvarn.gunicorn.log" --log-level=debug qvarnbackend:app
+gunicorn3 --bind 127.0.0.1:12765 -p "$tmp/pid" -w1 qvarnbackend:app
diff --git a/slog/__init__.py b/slog/__init__.py
index cb76b14..45f93b0 100644
--- a/slog/__init__.py
+++ b/slog/__init__.py
@@ -21,6 +21,7 @@ from .slog import (
     NullSlogWriter,
     FileSlogWriter,
     SyslogSlogWriter,
+    SlogHandler,
     hijack_logging,
 )
 
diff --git a/slog/slog.py b/slog/slog.py
index 6ea403a..81d2c61 100644
--- a/slog/slog.py
+++ b/slog/slog.py
@@ -244,20 +244,35 @@ class SlogHandler(logging.Handler):  # pragma: no cover
         self.log = log
 
     def emit(self, record):
+        attr_names = {
+            'msg': 'msg_text',
+        }
+
         log_args = dict()
         for attr in dir(record):
             if not attr.startswith('_'):
                 value = getattr(record, attr)
                 if not isinstance(value, (str, int, bool, float)):
                     value = repr(value)
-                log_args[attr] = value
-        self.log.log('logging', **log_args)
+                log_args[attr_names.get(attr, attr)] = value
+        self.log.log('logging.' + record.levelname, **log_args)
 
 
-def hijack_logging(log):  # pragma: no cover
+def hijack_logging(log, logger_names=None):  # pragma: no cover
     '''Hijack log messages that come via logging.* into a slog.'''
 
     handler = SlogHandler(log)
+
+    for name in logger_names or []:
+        logger = logging.getLogger(name)
+        hijack_logger_handlers(logger, handler)
+
     logger = logging.getLogger()
+    hijack_logger_handlers(logger, handler)
+
+
+def hijack_logger_handlers(logger, handler):  # pragma: no cover
     logger.setLevel(logging.DEBUG)
+    for h in logger.handlers:
+        logger.removeHandler(h)
     logger.addHandler(handler)
diff --git a/without-tests b/without-tests
index 075518d..6b8a93c 100644
--- a/without-tests
+++ b/without-tests
@@ -6,5 +6,6 @@ apifw/apixface.py
 slog/__init__.py
 qvarnbackend.py
 qvarn/__init__.py
+qvarn/logging.py
 qvarn/version.py
 yarns/lib.py
diff --git a/yarns/900-implements.yarn b/yarns/900-implements.yarn
index 61c2579..8e2ee4c 100644
--- a/yarns/900-implements.yarn
+++ b/yarns/900-implements.yarn
@@ -22,7 +22,11 @@ Start a Qvarn running in the background.
     vars['port'] = 12765
     vars['url'] = 'http://127.0.0.1:{}'.format(vars['port'])
     config = {
-        'log': vars['api.log'],
+        'log': [
+            {
+                'filename': vars['api.log'],
+            },
+        ],
         'token-issuer': vars['iss'],
         'token-audience': vars['aud'],
         'token-public-key': vars['pubkey'],
@@ -33,14 +37,13 @@ Start a Qvarn running in the background.
         '--daemon',
         '--bind', '127.0.0.1:{}'.format(vars['port']),
         '-p', vars['pid-file'],
-        '--log-file', vars['gunicorn3.log'],
-        '--log-level', 'debug',
         'qvarnbackend:app',
     ]
     env = dict(os.environ)
     env['QVARN_CONFIG'] = 'qvarn.yaml'
-    cliapp.runcmd(argv, env=env)
+    cliapp.runcmd(argv, env=env, stdout=None, stderr=None)
     time.sleep(2)
+    assert os.path.exists(vars['pid-file'])
 
 ## Stop a Qvarn we started