[logging] Fix logging for all commands

bob/devtools/log.py

+#!/usr/bin/env python
+# -*- coding: utf-8 -*-
+
+"""Sets-up logging, centrally for Bob.
+"""
+
+import sys
+import logging
+
+# get the default root logger of Bob
+_logger = logging.getLogger('bob')
+
+# by default, warning and error messages should be written to sys.stderr
+_warn_err = logging.StreamHandler(sys.stderr)
+_warn_err.setLevel(logging.WARNING)
+_logger.addHandler(_warn_err)
+
+# debug and info messages are written to sys.stdout
+
+class _InfoFilter:
+  def filter(self, record):
+    return record.levelno <= logging.INFO
+
+
+_debug_info = logging.StreamHandler(sys.stdout)
+_debug_info.setLevel(logging.DEBUG)
+_debug_info.addFilter(_InfoFilter())
+_logger.addHandler(_debug_info)
+
+
+# helper functions to instantiate and set-up logging
+def setup(logger_name,
+          format="%(name)s@%(asctime)s -- %(levelname)s: %(message)s"):
+  """This function returns a logger object that is set up to perform logging
+  using Bob loggers.
+
+  Parameters
+  ----------
+  logger_name : str
+      The name of the module to generate logs for
+  format : :obj:`str`, optional
+      The format of the logs, see :py:class:`logging.LogRecord` for more
+      details. By default, the log contains the logger name, the log time, the
+      log level and the massage.
+
+  Returns
+  -------
+  logger : :py:class:`logging.Logger`
+      The logger configured for logging. The same logger can be retrieved using
+      the :py:func:`logging.getLogger` function.
+  """
+  # generate new logger object
+  logger = logging.getLogger(logger_name)
+
+  # add log the handlers if not yet done
+  if not logger_name.startswith("bob") and not logger.handlers:
+    logger.addHandler(_warn_err)
+    logger.addHandler(_debug_info)
+
+  # this formats the logger to print the desired information
+  formatter = logging.Formatter(format)
+  # we have to set the formatter to all handlers registered in the current
+  # logger
+  for handler in logger.handlers:
+    handler.setFormatter(formatter)
+
+  # set the same formatter for bob loggers
+  for handler in _logger.handlers:
+    handler.setFormatter(formatter)
+
+  return logger
+
+
+def set_verbosity_level(logger, level):
+  """Sets the log level for the given logger.
+
+  Parameters
+  ----------
+  logger : :py:class:`logging.Logger` or str
+      The logger to generate logs for, or the name  of the module to generate
+      logs for.
+  level : int
+      Possible log levels are: 0: Error; 1: Warning; 2: Info; 3: Debug.
+
+  Raises
+  ------
+  ValueError
+      If the level is not in range(0, 4).
+  """
+  if level not in range(0, 4):
+    raise ValueError(
+        "The verbosity level %d does not exist. Please reduce the number of "
+        "'--verbose' parameters in your command line" % level)
+  # set up the verbosity level of the logging system
+  log_level = {
+      0: logging.ERROR,
+      1: logging.WARNING,
+      2: logging.INFO,
+      3: logging.DEBUG
+  }[level]
+
+  # set this log level to the logger with the specified name
+  if isinstance(logger, str):
+    logger = logging.getLogger(logger)
+  logger.setLevel(log_level)
+  # set the same log level for the bob logger
+  _logger.setLevel(log_level)
+
+
+def verbosity_option(**kwargs):
+    """Adds a -v/--verbose option to a click command.
+
+    Parameters
+    ----------
+    **kwargs
+        All kwargs are passed to click.option.
+
+    Returns
+    -------
+    callable
+        A decorator to be used for adding this option.
+    """
+    global _logger
+    import click
+
+    def custom_verbosity_option(f):
+        def callback(ctx, param, value):
+            ctx.meta['verbosity'] = value
+            set_verbosity_level(_logger, value)
+            _logger.debug("`bob' logging level set to %d", value)
+            return value
+        return click.option(
+            '-v', '--verbose', count=True,
+            expose_value=False, default=0,
+            help="Increase the verbosity level from 0 (only error messages) "
+            "to 1 (warnings), 2 (info messages), 3 (debug information) by "
+            "adding the --verbose option as often as desired "
+            "(e.g. '-vvv' for debug).",
+            callback=callback, **kwargs)(f)
+    return custom_verbosity_option

bob/devtools/scripts/bdt.py

@@ -9,72 +9,8 @@ import pkg_resources
 import click
 from click_plugins import with_plugins
 
-import logging
-logger = logging.getLogger('bdt')
-
-
-def set_verbosity_level(logger, level):
-    """Sets the log level for the given logger.
-
-    Parameters
-    ----------
-    logger : :py:class:`logging.Logger` or str
-        The logger to generate logs for, or the name  of the module to generate
-        logs for.
-    level : int
-        Possible log levels are: 0: Error; 1: Warning; 2: Info; 3: Debug.
-    Raises
-    ------
-    ValueError
-        If the level is not in range(0, 4).
-    """
-    if level not in range(0, 4):
-        raise ValueError(
-            "The verbosity level %d does not exist. Please reduce the number "
-            "of '--verbose' parameters in your command line" % level
-        )
-    # set up the verbosity level of the logging system
-    log_level = {
-        0: logging.ERROR,
-        1: logging.WARNING,
-        2: logging.INFO,
-        3: logging.DEBUG
-    }[level]
-
-    # set this log level to the logger with the specified name
-    if isinstance(logger, str):
-        logger = logging.getLogger(logger)
-    logger.setLevel(log_level)
-
-
-def verbosity_option(**kwargs):
-    """Adds a -v/--verbose option to a click command.
-
-    Parameters
-    ----------
-    **kwargs
-        All kwargs are passed to click.option.
-
-    Returns
-    -------
-    callable
-        A decorator to be used for adding this option.
-    """
-    def custom_verbosity_option(f):
-        def callback(ctx, param, value):
-            ctx.meta['verbosity'] = value
-            set_verbosity_level(logger, value)
-            logger.debug("`bdt' logging level set to %d", value)
-            return value
-        return click.option(
-            '-v', '--verbose', count=True,
-            expose_value=False, default=2,
-            help="Increase the verbosity level from 0 (only error messages) "
-            "to 1 (warnings), 2 (info messages), 3 (debug information) by "
-            "adding the --verbose option as often as desired "
-            "(e.g. '-vvv' for debug).",
-            callback=callback, **kwargs)(f)
-    return custom_verbosity_option
+from ..log import setup
+logger = setup('bob')
 
 
 class AliasedGroup(click.Group):
@@ -114,6 +50,5 @@ def raise_on_error(view_func):
 @with_plugins(pkg_resources.iter_entry_points('bdt.cli'))
 @click.group(cls=AliasedGroup,
              context_settings=dict(help_option_names=['-?', '-h', '--help']))
-@verbosity_option()
 def main():
     """Bob Development Tools - see available commands below"""

bob/devtools/scripts/cb_output.py

 #!/usr/bin/env python
 # -*- coding: utf-8 -*-
 
+import logging
+logger = logging.getLogger(__name__)
+
 import click
 from click.testing import CliRunner
 import conda_build.api as cb
 
 from . import bdt
-
+from ..log import verbosity_option
 from ..conda import should_skip_build
 
 
@@ -23,6 +26,7 @@ $ bdt cb-output ../bob.conda/conda/kaldi -m ../bob.admin/gitlab/conda_build_conf
 @click.argument('recipe_path')
 @click.option('-m', '--variant-config-files', help='see conda build --help')
 @click.option('--python', help='see conda build --help')
+@verbosity_option()
 @bdt.raise_on_error
 def cb_output(recipe_path, variant_config_files, python):
   """Outputs name(s) of package(s) that would be generated by conda build.

bob/devtools/scripts/changelog.py

@@ -4,9 +4,13 @@ import os
 import sys
 import datetime
 
+import logging
+logger = logging.getLogger(__name__)
+
 import click
 
 from . import bdt
+from ..log import verbosity_option
 from ..changelog import get_last_tag_date, write_tags_with_commits
 from ..changelog import parse_date
 from ..release import get_gitlab_instance
@@ -21,24 +25,24 @@ Examples:
 
   1. Generates the changelog for a single package using merge requests:
 
-     $ bdt -vvv changelog group/package.xyz changelog.md
+     $ bdt changelog group/package.xyz changelog.md
 
 
   2. The same as above, but dumps the changelog to stdout instead of a file:
 
-     $ bdt -vvv changelog group/package.xyz
+     $ bdt changelog group/package.xyz
 
 
   3. Generates the changelog for a single package looking at commits
      (not merge requests):
 
-     $ bdt -vvv changelog --mode=commits group/package.xyz changelog.md
+     $ bdt changelog --mode=commits group/package.xyz changelog.md
 
 
   4. Generates the changelog for a single package looking at merge requests starting from a given date of January 1, 2016:
 
 \b
-     $ bdt -vvv changelog --mode=mrs --since=2016-01-01 group/package.xyz changelog.md
+     $ bdt changelog --mode=mrs --since=2016-01-01 group/package.xyz changelog.md
 
 
   5. Generates a complete list of changelogs for a list of packages (one per line:
@@ -47,7 +51,7 @@ Examples:
      $ curl -o order.txt https://gitlab.idiap.ch/bob/bob.nightlies/raw/master/order.txt
      $ bdt lasttag bob/bob
      # copy and paste date to next command
-     $ bdt -vvv changelog --since="2018-07-17 10:23:40" order.txt changelog.md
+     $ bdt changelog --since="2018-07-17 10:23:40" order.txt changelog.md
 ''')
 @click.argument('target')
 @click.argument('changelog', type=click.Path(exists=False, dir_okay=False,
@@ -67,6 +71,7 @@ Examples:
     '(see https://dateutil.readthedocs.io/en/stable/parser.html) from ' \
     'which you want to generate the changelog.  If not set, the package\'s' \
     'last release date will be used')
+@verbosity_option()
 @bdt.raise_on_error
 def changelog(target, changelog, group, mode, since):
     """Generates changelog file for package(s) from the Gitlab server.
@@ -90,13 +95,13 @@ def changelog(target, changelog, group, mode, since):
 
     # reads package list or considers name to be a package name
     if os.path.exists(target) and os.path.isfile(target):
-        bdt.logger.info('Reading package names from file %s...', target)
+        logger.info('Reading package names from file %s...', target)
         with open(target, 'rt') as f:
             packages = [k.strip() for k in f.readlines() if k.strip() and not \
                 k.strip().startswith('#')]
     else:
-        bdt.logger.info('Assuming %s is a package name (file does not ' \
-            'exist)...', target)
+        logger.info('Assuming %s is a package name (file does not exist)...',
+            target)
         packages = [target]
 
     # if the user passed a date, convert it
@@ -110,11 +115,11 @@ def changelog(target, changelog, group, mode, since):
 
         # retrieves the gitlab package object
         use_package = gl.projects.get(package)
-        bdt.logger.info('Found gitlab project %s (id=%d)',
+        logger.info('Found gitlab project %s (id=%d)',
             use_package.attributes['path_with_namespace'], use_package.id)
 
         last_release_date = since or get_last_tag_date(use_package)
-        bdt.logger.info('Retrieving data (mode=%s) since %s', mode,
+        logger.info('Retrieving data (mode=%s) since %s', mode,
             last_release_date.strftime('%b %d, %Y %H:%M'))
 
         # add 1s to avoid us retrieving previous release data
@@ -127,13 +132,13 @@ def changelog(target, changelog, group, mode, since):
 
         if use_package.attributes['namespace'] == use_package.name:
             # skip system meta-package
-            bdt.logger.warn('Skipping meta package %s...',
+            logger.warn('Skipping meta package %s...',
                 use_package.attributes['path_with_namespace'])
             continue
 
         if use_package.attributes['visibility'] not in visibility:
-            bdt.logger.warn('Skipping package %s (visibility not in ' \
-                '"%s")...', use_package.attributes['path_with_namespace'],
+            logger.warn('Skipping package %s (visibility not in "%s")...',
+                use_package.attributes['path_with_namespace'],
                 '|'.join(visibility))
             continue
 

bob/devtools/scripts/lasttag.py

 #!/usr/bin/env python
 
 import os
+import logging
+logger = logging.getLogger(__name__)
 
 import click
 
 from . import bdt
+from ..log import verbosity_option
 from ..changelog import get_last_tag, parse_date
 from ..release import get_gitlab_instance
 
@@ -27,6 +30,7 @@ Examples:
 
 ''')
 @click.argument('package')
+@verbosity_option()
 @bdt.raise_on_error
 def lasttag(package):
     """Returns the last tag information on a given PACKAGE
@@ -39,7 +43,7 @@ def lasttag(package):
 
     # we lookup the gitlab group once
     use_package = gl.projects.get(package)
-    bdt.logger.info('Found gitlab project %s (id=%d)',
+    logger.info('Found gitlab project %s (id=%d)',
         use_package.attributes['path_with_namespace'], use_package.id)
 
     tag = get_last_tag(use_package)

bob/devtools/scripts/release.py

@@ -3,10 +3,13 @@
 
 
 import os
+import logging
+logger = logging.getLogger(__name__)
 
 import click
 
 from . import bdt
+from ..log import verbosity_option
 from ..release import release_bob, parse_and_process_package_changelog
 from ..release import release_package, wait_for_pipeline_to_finish
 from ..release import get_gitlab_instance
@@ -20,28 +23,28 @@ Examples:
 
   1. Releases a single package:
 
-     $ bdt -vvv release --package=bob.package.xyz changelog.md
+     $ bdt release --package=bob.package.xyz changelog.md
 
 
   2. If there is a single package in the ``changelog.md`` file, the flag
      ``--package`` is not required:
 
-     $ bdt -vvv release changelog.md
+     $ bdt release changelog.md
 
 
   2. Releases the whole of bob using `changelog_since_last_release.md`:
 
-     $ bdt -vvv release bob/devtools/data/changelog_since_last_release.md
+     $ bdt release bob/devtools/data/changelog_since_last_release.md
 
 
   3. In case of errors, resume the release of the whole of Bob:
 
-     $ bdt -vvv release --resume bob/devtools/data/changelog_since_last_release.md
+     $ bdt release --resume bob/devtools/data/changelog_since_last_release.md
 
 
   4. The option `-dry-run` can be used to let the script print what it would do instead of actually doing it:
 
-     $ bdt -vvv release --dry-run changelog_since_last_release.md
+     $ bdt release --dry-run changelog_since_last_release.md
 '''
 )
 @click.argument('changelog', type=click.File('rb', lazy=False))
@@ -59,6 +62,7 @@ Examples:
     help='Only goes through the actions, but does not execute them ' \
         '(combine with the verbosity flags - e.g. ``-vvv``) to enable ' \
         'printing to help you understand what will be done')
+@verbosity_option()
 @bdt.raise_on_error
 def release(changelog, group, package, resume, dry_run):
     """\b
@@ -149,7 +153,7 @@ def release(changelog, group, package, resume, dry_run):
             if line[1:].strip() == package]
 
         if not start_idx:
-            bdt.logger.error('Package %s was not found in the changelog',
+            logger.error('Package %s was not found in the changelog',
                 package)
             return
 
@@ -157,14 +161,14 @@ def release(changelog, group, package, resume, dry_run):
 
     # if we are in a dry-run mode, let's let it be known
     if dry_run:
-        bdt.logger.warn('!!!! DRY RUN MODE !!!!')
-        bdt.logger.warn('Nothing is being committed to Gitlab')
+        logger.warn('!!!! DRY RUN MODE !!!!')
+        logger.warn('Nothing is being committed to Gitlab')
 
     # go through the list of packages and release them starting from the
     # start_idx
     for i in range(start_idx, len(pkgs) - 1):
         cur_package_name = changelogs[pkgs[i]][1:].strip()
-        bdt.logger.info('Processing package %s', changelogs[pkgs[i]])
+        logger.info('Processing package %s', changelogs[pkgs[i]])
         gitpkg, tag, tag_comments = parse_and_process_package_changelog(gl,
             use_group, cur_package_name,
             changelogs[pkgs[i] + 1: pkgs[i + 1]], dry_run)
@@ -181,4 +185,4 @@ def release(changelog, group, package, resume, dry_run):
         if package == cur_package_name and not resume:
             break
 
-    bdt.logger.info('Finished processing %s', changelog)
+    logger.info('Finished processing %s', changelog)

bob/devtools/scripts/visibility.py

@@ -6,7 +6,11 @@ import sys
 import click
 import gitlab
 
+import logging
+logger = logging.getLogger(__name__)
+
 from . import bdt
+from ..log import verbosity_option
 from ..release import get_gitlab_instance
 
 
@@ -19,20 +23,21 @@ Examples:
 
   1. Check the visibility of a package you can access
 
-     $ bdt -vvv visibility bob/bob.extension
+     $ bdt visibility bob/bob.extension
 
 
   2. Checks the visibility of all packages in a file list:
 
 \b
      $ curl -o order.txt https://gitlab.idiap.ch/bob/bob.nightlies/raw/master/order.txt
-     $ bdt -vvv visibility order.txt
+     $ bdt visibility order.txt
 ''')
 @click.argument('target')
 @click.option('-g', '--group', default='bob', show_default=True,
     help='Gitlab default group name where packages are located (if not ' \
         'specified using a "/" on the package name - e.g. ' \
         '"bob/bob.extension")')
+@verbosity_option()
 @bdt.raise_on_error
 def visibility(target, group):
     """Checks if the gitlab repository is visible to the current user
@@ -47,12 +52,12 @@ def visibility(target, group):
 
     # reads package list or considers name to be a package name
     if os.path.exists(target) and os.path.isfile(target):
-        bdt.logger.info('Reading package names from file %s...', target)
+        logger.info('Reading package names from file %s...', target)
         with open(target, 'rt') as f:
             packages = [k.strip() for k in f.readlines() if k.strip() and not \
                 k.strip().startswith('#')]
     else:
-        bdt.logger.info('Assuming %s is a package name (file does not ' \
+        logger.info('Assuming %s is a package name (file does not ' \
             'exist)...', target)
         packages = [target]
 
@@ -65,11 +70,11 @@ def visibility(target, group):
         # retrieves the gitlab package object
         try:
           use_package = gl.projects.get(package)
-          bdt.logger.info('Found gitlab project %s (id=%d)',
+          logger.info('Found gitlab project %s (id=%d)',
               use_package.attributes['path_with_namespace'], use_package.id)
           click.echo('%s: %s' % (package,
             use_package.attributes['visibility'].lower()))
         except gitlab.GitlabGetError as e:
-          bdt.logger.warn('Gitlab access error - package %s does not exist?',
+          logger.warn('Gitlab access error - package %s does not exist?',
               package)
           click.echo('%s: unknown' % (package,))

doc/api.rst

@@ -6,6 +6,7 @@
 ============
 
 .. autosummary::
+   bob.devtools.log
    bob.devtools.conda
    bob.devtools.release
    bob.devtools.changelog
@@ -14,6 +15,8 @@
 Detailed Information
 --------------------
 
+.. automodule:: bob.devtools.log
+
 .. automodule:: bob.devtools.conda
 
 .. automodule:: bob.devtools.release