Merge pull request #331 from ralphbean/feature/kill-twiggy

Kill twiggy.

bugwarrior/command.py

@@ -1,10 +1,8 @@
 import os
 
-from twiggy import log
 from lockfile import LockTimeout
 from lockfile.pidlockfile import PIDLockFile
 
-import twiggy
 import getpass
 import keyring
 import click
@@ -16,6 +14,9 @@
     synchronize,
 )
 
+import logging
+log = logging.getLogger(__name__)
+
 
 # We overwrite 'list' further down.
 lst = list
@@ -37,7 +38,7 @@ def pull(dry_run, flavor, interactive, debug):
 
     Relies on configuration in bugwarriorrc
     """
-    twiggy.quickSetup()
+
     try:
         main_section = _get_section_name(flavor)
 
@@ -56,17 +57,17 @@ def pull(dry_run, flavor, interactive, debug):
         finally:
             lockfile.release()
     except LockTimeout:
-        log.name('command').critical(
+        log.critical(
             'Your taskrc repository is currently locked. '
             'Remove the file at %s if you are sure no other '
             'bugwarrior processes are currently running.' % (
                 lockfile_path
             )
         )
     except RuntimeError as e:
-        log.name('command').critical("Aborted (%s)" % e)
+        log.critical("Aborted (%s)" % e)
     except:
-        log.name('command').trace('error').critical('oh noes')
+        log.exception('oh noes')
 
 
 @click.group()

bugwarrior/config.py

@@ -5,11 +5,11 @@
 import sys
 
 import six
-import twiggy
-from twiggy import log
-from twiggy.levels import name2level
 from xdg import BaseDirectory
 
+import logging
+log = logging.getLogger(__name__)
+
 
 def asbool(some_value):
     """ Cast config values to boolean. """
@@ -90,16 +90,16 @@ def load_example_rc():
 error_template = """
 *************************************************
 * There was a problem with your bugwarriorrc    *
-*   {msg}
+*   {error_msg}
 * Here's an example template to help:           *
 *************************************************
 {example}"""
 
 
-def die(msg):
-    log.options(suppress_newlines=False).critical(
+def die(error_msg):
+    log.critical(
         error_template,
-        msg=msg,
+        error_msg=error_msg,
         example=load_example_rc(),
     )
     sys.exit(1)
@@ -109,11 +109,22 @@ def validate_config(config, main_section):
     if not config.has_section(main_section):
         die("No [%s] section found." % main_section)
 
-    twiggy.quickSetup(
-        name2level(config.get(main_section, 'log.level')),
-        config.get(main_section, 'log.file')
+    logging.basicConfig(
+        level=getattr(logging, config.get(main_section, 'log.level')),
+        filename=config.get(main_section, 'log.file'),
     )
 
+    # In general, its nice to log "everything", but some of the loggers from
+    # our dependencies are very very spammy.  Here, we silence most of their
+    # noise:
+    spammers = [
+        'bugzilla.base',
+        'bugzilla.bug',
+        'requests.packages.urllib3.connectionpool',
+    ]
+    for spammer in spammers:
+        logging.getLogger(spammer).setLevel(logging.WARN)
+
     if not config.has_option(main_section, 'targets'):
         die("No targets= item in [%s] found." % main_section)
 
@@ -141,7 +152,7 @@ def validate_config(config, main_section):
 
 
 def load_config(main_section, interactive=False):
-    config = ConfigParser({'log.level': "DEBUG", 'log.file': None})
+    config = ConfigParser({'log.level': "INFO", 'log.file': None})
     path = None
     first_path = BaseDirectory.load_first_config('bugwarrior')
     if first_path is not None:

bugwarrior/db.py

@@ -8,13 +8,15 @@
 import requests
 import dogpile.cache
 import six
-from twiggy import log
 from taskw import TaskWarriorShellout
 from taskw.exceptions import TaskwarriorError
 
 from bugwarrior.config import asbool, get_taskrc_path
 from bugwarrior.notifications import send_notification
 
+import logging
+log = logging.getLogger(__name__)
+
 
 MARKUP = "(bw)"
 
@@ -66,17 +68,6 @@ def get_normalized_annotation(annotation):
     )
 
 
-def sanitize(string):
-    """ Sanitize a string for logging with twiggy.
-
-    It is obnoxious that we have to do this ourselves, but twiggy doesn't like
-    strings with non-ascii characters or with curly braces in them.
-    """
-    if not isinstance(string, six.string_types):
-        return string
-    return six.text_type(string.replace('{', '{{').replace('}', '}}'))
-
-
 def get_annotation_hamming_distance(left, right):
     left = get_normalized_annotation(left)
     right = get_normalized_annotation(right)
@@ -256,19 +247,12 @@ def merge_left(field, local_task, remote_issue, hamming=False):
                 found = True
                 break
         if not found:
-            log.name('db').debug(
-                "%s not found in %r" % (remote, local_field)
-            )
+            log.debug("%s not found in %r" % (remote, local_field))
             local_task[field].append(remote)
             new_count += 1
     if new_count > 0:
-        log.name('db').debug(
-            'Added %s new values to %s (total: %s)' % (
-                new_count,
-                field,
-                len(local_task[field]),
-            )
-        )
+        log.debug('Added %s new values to %s (total: %s)' % (
+            new_count, field, len(local_task[field]),))
 
 
 def run_hooks(conf, name):
@@ -283,7 +267,7 @@ def run_hooks(conf, name):
                     msg = 'Non-zero exit code %d on hook %s' % (
                         exit_code, hook
                     )
-                    log.name('hooks:%s' % name).error(msg)
+                    log.error(msg)
                     raise RuntimeError(msg)
 
 
@@ -300,7 +284,7 @@ def _bool_option(section, option, default):
     uda_list = build_uda_config_overrides(services)
 
     if uda_list:
-        log.name('bugwarrior').info(
+        log.info(
             'Service-defined UDAs exist: you can optionally use the '
             '`bugwarrior-uda` command to export a list of UDAs you can '
             'add to your ~/.taskrc file.'
@@ -366,20 +350,16 @@ def _bool_option(section, option, default):
                 issue_updates['closed'].remove(existing_uuid)
 
         except MultipleMatches as e:
-            log.name('db').error("Multiple matches: {0}", six.text_type(e))
-            log.name('db').trace(e)
+            log.exception("Multiple matches: %s", six.text_type(e))
         except NotFound:
             issue_updates['new'].append(dict(issue))
 
     notreally = ' (not really)' if dry_run else ''
     # Add new issues
-    log.name('db').info("Adding {0} tasks", len(issue_updates['new']))
+    log.info("Adding %i tasks", len(issue_updates['new']))
     for issue in issue_updates['new']:
-        log.name('db').info(
-            "Adding task {0}{1}",
-            issue['description'].encode("utf-8"),
-            notreally
-        )
+        log.info("Adding task %s%s",
+            issue['description'].encode("utf-8"), notreally)
         if dry_run:
             continue
         if notify:
@@ -388,10 +368,9 @@ def _bool_option(section, option, default):
         try:
             tw.task_add(**issue)
         except TaskwarriorError as e:
-            log.name('db').error("Unable to add task: %s" % e.stderr)
-            log.name('db').trace(e)
+            log.exception("Unable to add task: %s" % e.stderr)
 
-    log.name('db').info("Updating {0} tasks", len(issue_updates['changed']))
+    log.info("Updating %i tasks", len(issue_updates['changed']))
     for issue in issue_updates['changed']:
         changes = '; '.join([
             '{field}: {f} -> {t}'.format(
@@ -401,8 +380,8 @@ def _bool_option(section, option, default):
             )
             for field, ch in six.iteritems(issue.get_changes(keep=True))
         ])
-        log.name('db').info(
-            "Updating task {0}, {1}; {2}{3}",
+        log.info(
+            "Updating task %s, %s; %s%s",
             six.text_type(issue['uuid']).encode("utf-8"),
             issue['description'].encode("utf-8"),
             changes,
@@ -414,14 +393,13 @@ def _bool_option(section, option, default):
         try:
             tw.task_update(issue)
         except TaskwarriorError as e:
-            log.name('db').error("Unable to modify task: %s" % e.stderr)
-            log.name('db').trace(e)
+            log.exception("Unable to modify task: %s" % e.stderr)
 
-    log.name('db').info("Closing {0} tasks", len(issue_updates['closed']))
+    log.info("Closing %i tasks", len(issue_updates['closed']))
     for issue in issue_updates['closed']:
         _, task_info = tw.get_task(uuid=issue)
-        log.name('db').info(
-            "Completing task {0} {1}{2}",
+        log.info(
+            "Completing task %s %s%s",
             issue,
             task_info.get('description', '').encode('utf-8'),
             notreally
@@ -435,8 +413,7 @@ def _bool_option(section, option, default):
         try:
             tw.task_done(uuid=issue)
         except TaskwarriorError as e:
-            log.name('db').error("Unable to close task: %s" % e.stderr)
-            log.name('db').trace(e)
+            log.exception("Unable to close task: %s" % e.stderr)
 
     # Send notifications
     if notify:

bugwarrior/services/__init__.py

@@ -11,13 +11,15 @@
 from jinja2 import Template
 import pytz
 import six
-from twiggy import log
 
 from taskw.task import Task
 
 from bugwarrior.config import asbool, die, get_service_password
 from bugwarrior.db import MARKUP, URLShortener
 
+import logging
+log = logging.getLogger(__name__)
+
 
 # Sentinels for process completion status
 SERVICE_FINISHED_OK = 0
@@ -90,7 +92,7 @@ def __init__(self, config, main_section, target):
         if config.has_option(self.target, 'default_priority'):
             self.default_priority = config.get(self.target, 'default_priority')
 
-        log.name(target).info("Working on [{0}]", self.target)
+        log.info("Working on [%s]", self.target)
 
     def get_templates(self):
         """ Get any defined templates for configuration values.
@@ -514,34 +516,28 @@ def _aggregate_issues(conf, main_section, target, queue, service_name):
             queue.put(issue)
             issue_count += 1
     except SystemExit as e:
-        log.name(target).critical(str(e))
+        log.critical(str(e))
         queue.put((SERVICE_FINISHED_ERROR, (target, e)))
     except BaseException as e:
-        log.name(target).trace('error').critical(
-            "Worker for [%s] failed: %s" % (target, e)
-        )
-        queue.put(
-            (SERVICE_FINISHED_ERROR, (target, e))
-        )
+        log.exception("Worker for [%s] failed: %s" % (target, e))
+        queue.put((SERVICE_FINISHED_ERROR, (target, e)))
     else:
-        queue.put(
-            (SERVICE_FINISHED_OK, (target, issue_count, ))
-        )
+        queue.put((SERVICE_FINISHED_OK, (target, issue_count, )))
     finally:
         duration = time.time() - start
-        log.name(target).info("Done with [%s] in %fs" % (target, duration))
+        log.info("Done with [%s] in %fs" % (target, duration))
 
 
 def aggregate_issues(conf, main_section, debug):
     """ Return all issues from every target. """
-    log.name('bugwarrior').info("Starting to aggregate remote issues.")
+    log.info("Starting to aggregate remote issues.")
 
     # Create and call service objects for every target in the config
     targets = [t.strip() for t in conf.get(main_section, 'targets').split(',')]
 
     queue = multiprocessing.Queue()
 
-    log.name('bugwarrior').info("Spawning %i workers." % len(targets))
+    log.info("Spawning %i workers." % len(targets))
     processes = []
 
     if debug:
@@ -575,7 +571,7 @@ def aggregate_issues(conf, main_section, debug):
             completion_type, args = issue
             if completion_type == SERVICE_FINISHED_ERROR:
                 target, e = args
-                log.name('bugwarrior').info("Terminating workers")
+                log.info("Terminating workers")
                 for process in processes:
                     process.terminate()
                 raise RuntimeError(
@@ -584,4 +580,4 @@ def aggregate_issues(conf, main_section, debug):
             continue
         yield issue
 
-    log.name('bugwarrior').info("Done aggregating remote issues.")
+    log.info("Done aggregating remote issues.")

bugwarrior/services/activecollab.py

@@ -1,11 +1,13 @@
 import re
 
 import pypandoc
-from twiggy import log
 from pyac.library import activeCollab
 from bugwarrior.services import IssueService, Issue
 from bugwarrior.config import die
 
+import logging
+log = logging.getLogger(__name__)
+
 
 class ActiveCollabClient(object):
     def __init__(self, url, key, user_id):
@@ -242,8 +244,8 @@ def issues(self):
                             subtask['task_id'] = task['task_id']
                             subtask['milestone'] = task['milestone']
                             issues.append(subtask)
-        log.name(self.target).debug(" Found {0} total", task_count)
-        log.name(self.target).debug(" Pruned down to {0}", len(issues))
+        log.debug(" Found %i total", task_count)
+        log.debug(" Pruned down to %i", len(issues))
         for issue in issues:
             issue_obj = self.get_issue_for_record(issue)
             extra = {