switch from logging to structlog

nvchecker/core.py

@@ -1,25 +1,30 @@
 # vim: se sw=2:
 # MIT licensed
-# Copyright (c) 2013-2017 lilydjwg <lilydjwg@gmail.com>, et al.
+# Copyright (c) 2013-2018 lilydjwg <lilydjwg@gmail.com>, et al.
 
 import os
 import sys
-import logging
 import configparser
 import asyncio
+import logging
+import structlog
 
 from .lib import nicelogger
 from .get_version import get_version
 from .source import session
+from . import slogconf
 
 from . import __version__
 
-logger = logging.getLogger(__name__)
+logger = structlog.get_logger(logger_name=__name__)
 
 def add_common_arguments(parser):
   parser.add_argument('-l', '--logging',
                       choices=('debug', 'info', 'warning', 'error'), default='info',
                       help='logging level (default: info)')
+  parser.add_argument('--logger', choices=['stdlib', 'structlog'],
+                      default='stdlib',
+                      help='select which logger to use')
   parser.add_argument('-V', '--version', action='store_true',
                       help='show version and exit')
   parser.add_argument('file', metavar='FILE', nargs='?', type=open,
@@ -27,7 +32,27 @@ def add_common_arguments(parser):
 
 def process_common_arguments(args):
   '''return True if should stop'''
-  nicelogger.enable_pretty_logging(getattr(logging, args.logging.upper()))
+  if args.logger == 'stdlib':
+    slogconf.fix_logging()
+    nicelogger.enable_pretty_logging(
+      getattr(logging, args.logging.upper()))
+    structlog.configure(
+      processors=[
+        slogconf.exc_info,
+        slogconf.stdlib_renderer,
+      ],
+      logger_factory=structlog.PrintLoggerFactory(
+        file=open(os.devnull, 'w')),
+    )
+  else:
+    structlog.configure(
+      processors=[
+        slogconf.exc_info,
+        structlog.processors.format_exc_info,
+        slogconf.json_renderer,
+      ],
+      logger_factory=structlog.PrintLoggerFactory(file=sys.stderr),
+    )
 
   if args.version:
     progname = os.path.basename(sys.argv[0])
@@ -129,16 +154,16 @@ class Source:
       if version is not None:
         self.print_version_update(name, version)
     except Exception:
-      logger.exception('unexpected error happened with %s', name)
+      logger.exception('unexpected error happened', name=name)
 
   def print_version_update(self, name, version):
     oldver = self.oldvers.get(name, None)
     if not oldver or oldver != version:
-      logger.info('%s updated to %s', name, version)
+      logger.info('updated', name=name, version=version, old_version=oldver)
       self.curvers[name] = version
       self.on_update(name, version, oldver)
     else:
-      logger.debug('%s current %s', name, version)
+      logger.debug('up-to-date', name=name, version=version)
 
   def on_update(self, name, version, oldver):
     pass

nvchecker/get_version.py

@@ -1,11 +1,13 @@
 # MIT licensed
 # Copyright (c) 2013-2017 lilydjwg <lilydjwg@gmail.com>, et al.
 
-import logging
 import re
 from importlib import import_module
 
-logger = logging.getLogger(__name__)
+import structlog
+
+logger = structlog.get_logger(logger_name=__name__)
+
 handler_precedence = (
   'github', 'aur', 'pypi', 'archpkg', 'debianpkg', 'ubuntupkg',
   'gems', 'pacman',
@@ -46,7 +48,7 @@ async def get_version(name, conf):
         try:
           version = substitute_version(version, name, conf)
         except (ValueError, re.error):
-          logger.exception('error occurred in version substitutions for %s', name)
+          logger.exception('error occurred in version substitutions', name=name)
       return version
   else:
-    logger.error('%s: no idea to get version info.', name)
+    logger.error('no idea to get version info.', name=name)

nvchecker/main.py

@@ -2,15 +2,16 @@
 # MIT licensed
 # Copyright (c) 2013-2017 lilydjwg <lilydjwg@gmail.com>, et al.
 
-import logging
 import argparse
-
 import asyncio
 
+import structlog
+
 from .lib import notify
 from . import core
 
-logger = logging.getLogger(__name__)
+logger = structlog.get_logger(logger_name=__name__)
+
 notifications = []
 args = None
 

nvchecker/slogconf.py

@@ -0,0 +1,87 @@
+# vim: se sw=2:
+# MIT licensed
+# Copyright (c) 2018 lilydjwg <lilydjwg@gmail.com>, et al.
+
+import logging
+import os
+import io
+import traceback
+
+import structlog
+
+def _console_msg(event):
+  evt = event['event']
+  if evt == 'up-to-date':
+    msg = 'up-to-date, version %s' % event['version']
+  elif evt == 'updated':
+    if event.get('old_version'):
+      msg = 'updated from %(old_version)s to %(version)s' % event
+    else:
+      msg = 'updated to %(version)s' % event
+  else:
+    msg = evt
+
+  if 'name' in event:
+    msg = '%s: %s' % (event['name'], msg)
+    del event['name']
+
+  event['msg'] = msg
+
+  return event
+
+def exc_info(logger, level, event):
+  if level == 'exception':
+    event['exc_info'] = True
+  return event
+
+def stdlib_renderer(logger, level, event):
+  event = _console_msg(event)
+  logger = logging.getLogger(event.get('logger_name'))
+  msg = event.pop('msg', event['event'])
+  exc_info = event.pop('exc_info', None)
+  getattr(logger, level)(
+    msg, exc_info = exc_info, extra=event,
+  )
+  return ''
+
+_renderer = structlog.processors.JSONRenderer(ensure_ascii=False)
+def json_renderer(logger, level, event):
+  return _renderer(logger, level, event)
+
+class _Logger(logging.Logger):
+  _my_srcfile = os.path.normcase(
+    stdlib_renderer.__code__.co_filename)
+
+  def findCaller(self, stack_info=False):
+    """
+    Find the stack frame of the caller so that we can note the source
+    file name, line number and function name.
+    """
+    f = logging.currentframe()
+    #On some versions of IronPython, currentframe() returns None if
+    #IronPython isn't run with -X:Frames.
+    if f is not None:
+      f = f.f_back
+    rv = "(unknown file)", 0, "(unknown function)", None
+    while hasattr(f, "f_code"):
+      co = f.f_code
+      filename = os.path.normcase(co.co_filename)
+      if filename in [logging._srcfile, self._my_srcfile]:
+        f = f.f_back
+        continue
+      sinfo = None
+      if stack_info:
+        sio = io.StringIO()
+        sio.write('Stack (most recent call last):\n')
+        traceback.print_stack(f, file=sio)
+        sinfo = sio.getvalue()
+        if sinfo[-1] == '\n':
+          sinfo = sinfo[:-1]
+        sio.close()
+      rv = (co.co_filename, f.f_lineno, co.co_name, sinfo)
+      break
+    return rv
+
+def fix_logging():
+  logging.setLoggerClass(_Logger)
+

nvchecker/sortversion.py

@@ -7,12 +7,8 @@ Sort versions using pkg_resource.parse_version or pyalpm.vercmp
 
 __all__ = ["sort_version_keys"]
 
-import logging
-
 from functools import cmp_to_key
 
-logger = logging.getLogger(__name__)
-
 from pkg_resources import parse_version
 try:
   import pyalpm

nvchecker/source/anitya.py

@@ -1,10 +1,11 @@
 # MIT licensed
 # Copyright (c) 2017 lilydjwg <lilydjwg@gmail.com>, et al.
 
-import logging
+import structlog
+
 from . import session
 
-logger = logging.getLogger(__name__)
+logger = structlog.get_logger(logger_name=__name__)
 
 URL = 'https://release-monitoring.org/api/project/{pkg}'
 

nvchecker/source/archpkg.py

@@ -1,10 +1,11 @@
 # MIT licensed
 # Copyright (c) 2013-2017 lilydjwg <lilydjwg@gmail.com>, et al.
 
-import logging
+import structlog
+
 from . import session
 
-logger = logging.getLogger(__name__)
+logger = structlog.get_logger(logger_name=__name__)
 
 URL = 'https://www.archlinux.org/packages/search/json/'
 
@@ -15,7 +16,7 @@ async def get_version(name, conf):
     data = await res.json()
 
   if not data['results']:
-    logger.error('Arch package not found: %s', name)
+    logger.error('Arch package not found', name=name)
     return
 
   r = [r for r in data['results'] if r['repo'] != 'testing'][0]

nvchecker/source/aur.py

@@ -1,12 +1,13 @@
 # MIT licensed
 # Copyright (c) 2013-2017 lilydjwg <lilydjwg@gmail.com>, et al.
 
-import logging
+import structlog
+
 from . import session
 
-AUR_URL = 'https://aur.archlinux.org/rpc/?v=5&type=info&arg[]='
+logger = structlog.get_logger(logger_name=__name__)
 
-logger = logging.getLogger(__name__)
+AUR_URL = 'https://aur.archlinux.org/rpc/?v=5&type=info&arg[]='
 
 async def get_version(name, conf):
   aurname = conf.get('aur') or name
@@ -15,7 +16,7 @@ async def get_version(name, conf):
     data = await res.json()
 
   if not data['results']:
-    logger.error('AUR upstream not found for %s', name)
+    logger.error('AUR upstream not found', name=name)
     return
 
   version = data['results'][0]['Version']

nvchecker/source/cmd.py

@@ -1,10 +1,11 @@
 # MIT licensed
 # Copyright (c) 2013-2017 lilydjwg <lilydjwg@gmail.com>, et al.
 
-import logging
 import asyncio
 
-logger = logging.getLogger(__name__)
+import structlog
+
+logger = structlog.get_logger(logger_name=__name__)
 
 async def get_version(name, conf):
   cmd = conf['cmd']
@@ -12,7 +13,8 @@ async def get_version(name, conf):
 
   output = (await p.communicate())[0].strip().decode('latin1')
   if p.returncode != 0:
-    logger.error('%s: command exited with %d.', name, p.returncode)
+    logger.error('command exited with error',
+                 name=name, returncode=p.returncode)
     return
 
   return output

nvchecker/source/debianpkg.py

@@ -1,10 +1,11 @@
 # MIT licensed
 # Copyright (c) 2017 Felix Yan <felixonmars@archlinux.org>, et al.
 
-import logging
+import structlog
+
 from . import session
 
-logger = logging.getLogger(__name__)
+logger = structlog.get_logger(logger_name=__name__)
 
 URL = 'https://sources.debian.org/api/src/%(pkgname)s/?suite=%(suite)s'
 
@@ -17,7 +18,7 @@ async def get_version(name, conf):
     data = await res.json()
 
   if not data.get('versions'):
-    logger.error('Debian package not found: %s', name)
+    logger.error('Debian package not found', name=name)
     return
 
   r = data['versions'][0]

nvchecker/source/github.py

@@ -2,17 +2,18 @@
 # Copyright (c) 2013-2017 lilydjwg <lilydjwg@gmail.com>, et al.
 
 import os
-import logging
+
+import structlog
 
 from . import session
 from ..sortversion import sort_version_keys
 
+logger = structlog.get_logger(logger_name=__name__)
+
 GITHUB_URL = 'https://api.github.com/repos/%s/commits'
 GITHUB_LATEST_RELEASE = 'https://api.github.com/repos/%s/releases/latest'
 GITHUB_MAX_TAG = 'https://api.github.com/repos/%s/tags'
 
-logger = logging.getLogger(__name__)
-
 async def get_version(name, conf):
   repo = conf.get('github')
   br = conf.get('branch')
@@ -42,14 +43,16 @@ async def get_version(name, conf):
     data = await res.json()
   if use_latest_release:
     if 'tag_name' not in data:
-      logger.error('%s: No tag found in upstream repository.', name)
+      logger.error('No tag found in upstream repository.',
+                   name=name)
       return
     version = data['tag_name']
   elif use_max_tag:
     data = [tag["name"] for tag in data if tag["name"] not in ignored_tags]
     data.sort(key=sort_version_key)
     if not len(data):
-      logger.error('%s: No tag found in upstream repository.', name)
+      logger.error('No tag found in upstream repository.',
+                   name=name)
       return
     version = data[-1]
   else:

nvchecker/source/gitlab.py

@@ -2,17 +2,18 @@
 # Copyright (c) 2013-2017 lilydjwg <lilydjwg@gmail.com>, et al.
 
 import os
-import logging
 import urllib.parse
 
+import structlog
+
 from . import session
 from ..sortversion import sort_version_keys
 
+logger = structlog.get_logger(logger_name=__name__)
+
 GITLAB_URL = 'https://%s/api/v3/projects/%s/repository/commits?ref_name=%s'
 GITLAB_MAX_TAG = 'https://%s/api/v3/projects/%s/repository/tags'
 
-logger = logging.getLogger(__name__)
-
 async def get_version(name, conf):
   repo = urllib.parse.quote_plus(conf.get('gitlab'))
   br = conf.get('branch', 'master')
@@ -24,7 +25,7 @@ async def get_version(name, conf):
   env_name = "NVCHECKER_GITLAB_TOKEN_" + host.upper().replace(".", "_").replace("/", "_")
   token = conf.get('token', os.environ.get(env_name, None))
   if token is None:
-    logger.error('%s: No gitlab token specified.', name)
+    logger.error('No gitlab token specified.', name=name)
     return
 
   if use_max_tag:

nvchecker/source/regex.py

@@ -3,18 +3,19 @@
 
 import re
 import sre_constants
-import logging
+
+import structlog
 
 from . import session
 from ..sortversion import sort_version_keys
 
-logger = logging.getLogger(__name__)
+logger = structlog.get_logger(logger_name=__name__)
 
 async def get_version(name, conf):
   try:
     regex = re.compile(conf['regex'])
   except sre_constants.error:
-    logger.warn('%s: bad regex, skipped.', name, exc_info=True)
+    logger.warn('bad regex, skipped.', name=name, exc_info=True)
     return
 
   encoding = conf.get('encoding', 'latin1')
@@ -33,5 +34,5 @@ async def get_version(name, conf):
       version = max(regex.findall(body), key=sort_version_key)
     except ValueError:
       version = None
-      logger.error('%s: version string not found.', name)
+      logger.error('version string not found.', name=name)
     return version

nvchecker/source/ubuntupkg.py

@@ -1,10 +1,11 @@
 # MIT licensed
 # Copyright (c) 2017 Felix Yan <felixonmars@archlinux.org>, et al.
 
-import logging
+import structlog
+
 from . import session
 
-logger = logging.getLogger(__name__)
+logger = structlog.get_logger(logger_name=__name__)
 
 URL = 'https://api.launchpad.net/1.0/ubuntu/+archive/primary?ws.op=getPublishedSources&source_name=%s&exact_match=true'
 
@@ -24,7 +25,7 @@ async def get_version(name, conf):
       data = await res.json()
 
     if not data.get('entries'):
-      logger.error('Ubuntu package not found: %s', name)
+      logger.error('Ubuntu package not found', name=name)
       return
 
     releases = [r for r in data["entries"] if r["status"] == "Published"]
@@ -38,7 +39,7 @@ async def get_version(name, conf):
     url = data["next_collection_link"]
 
   if not releases:
-    logger.error('Ubuntu package not found: %s', name)
+    logger.error('Ubuntu package not found', name=name)
     return
 
   if strip_release:

nvchecker/source/vcs.py

@@ -1,13 +1,13 @@
 # MIT licensed
 # Copyright (c) 2013-2017 lilydjwg <lilydjwg@gmail.com>, et al.
 
-import logging
 import asyncio
-from pkg_resources import parse_version
-
 import os.path as _path
 
-logger = logging.getLogger(__name__)
+from pkg_resources import parse_version
+import structlog
+
+logger = structlog.get_logger(logger_name=__name__)
 _self_path = _path.dirname(_path.abspath(__file__))
 _cmd_prefix = ['/bin/bash', _path.join(_self_path, 'vcs.sh')]
 
@@ -38,7 +38,8 @@ async def get_version(name, conf):
 
   output = (await p.communicate())[0].strip().decode('latin1')
   if p.returncode != 0:
-    logger.error('%s: command exited with %d.', name, p.returncode)
+    logger.error('command exited with error',
+                 name=name, returncode=p.returncode)
     return
   else:
     if use_max_tag:

nvchecker/tools.py

@@ -5,11 +5,11 @@
 import sys
 import os
 import argparse
-import logging
+import structlog
 
 from . import core
 
-logger = logging.getLogger(__name__)
+logger = structlog.get_logger(logger_name=__name__)
 
 def take():
   parser = argparse.ArgumentParser(description='update version records of nvchecker')
@@ -25,7 +25,7 @@ def take():
   s = core.Source(args.file)
   if not s.oldver or not s.newver:
     logger.fatal(
-      "%s doesn't have both 'oldver' and 'newver' set.", s
+      "doesn't have both 'oldver' and 'newver' set.", source=s,
     )
     sys.exit(2)
 
@@ -40,7 +40,7 @@ def take():
         oldvers[name] = newvers[name]
       except KeyError:
         logger.fatal(
-          "%s doesn't exist in 'newver' set.", name
+          "doesn't exist in 'newver' set.", name=name,
         )
         sys.exit(2)