log_utils.py

#!/usr/bin/env python
#
# logs_utils.py - Tools for logging.
#
# Author: Paul McCarthy <pauldmccarthy@gmail.com>
# Author: Fidel Alfaro Almagro <fidel.alfaroalmagro@ndcn.ox.ac.uk>
# Author: Michiel Cottaar <michiel.cottaar@ndcn.ox.ac.uk>
#
# pylint: disable=C0103,E0602,C0114,C0115,C0116,R0913,R0914,R0915
# pylint: disable=W0613
#
import os
import os.path as op
import socket
import shutil
import inspect
import logging
import traceback
import contextlib
import functools as ft
from subprocess import check_output
from fsl import wrappers


def run_command(logger, command, **kwargs):
    try:
        logger.info('COMMAND TO RUN: \t' + command.strip())
        job_output = check_output(command,shell=True,**kawargs).decode('UTF-8')
        logger.info('COMMAND OUTPUT: \t' + job_output.strip())
    except Exception as e:
        logger.error('Exception raised during: \t' + command.strip())
        logger.error('Exception type: \t' + str(type(e)))
        logger.error('Exception args: \t' + str(e.args))
        logger.error('Exception message: \t' + str(e))

        job_output = ""
    return job_output.strip()


def create_formatter():
    """Create a logging.Formatter. """
    return logging.Formatter('%(asctime)s '
                             '%(filename)s '
                             '%(lineno)4d: '
                             '%(funcName)s - '
                             '%(message)s',
                             datefmt='%m/%d/%Y %H:%M:%S')


def setup_logging(fname, level=logging.INFO):
    """Set up BIP logging. Intended to be called once from main
    at application startup.
    """

    log       = logging.getLogger('bip')
    handler   = logging.FileHandler(fname)
    formatter = create_formatter()

    # Add handler/formatter references
    # to the top level logger so the
    # redirect_logging function can
    # manipulate them.
    log.formatter = formatter
    log.handler   = handler

    handler.setFormatter(formatter)
    log.addHandler(handler)
    log.setLevel(level)


def log_bip(logobj, level, msg):
    """Log a message, associating it with the nearest line in the
    bip python codebase in the call stack.
    """
    frames = inspect.stack()[1:]
    for i, frame in enumerate(frames):
        if 'bip' in frame[1]:
            break
    logobj.log(level, msg.strip(), stacklevel=i + 2)


@contextlib.contextmanager
def redirect_logging(name, outdir='.', level=logging.INFO):
    """Context manager which temporarily redirects logging. The following log
    files are created:

       - outdir/name.log: contains log messages, commands that are executed
         through fsl.wrappers functions, and standard output/error of those
         commands.
    """

    fname = op.join(outdir, name)

    with open(f'{fname}.log', 'wt', buffering=1,
              encoding="utf-8") as stdout:
        log     = logging.getLogger('bip')
        handler = logging.StreamHandler(stdout)
        handler.setFormatter(create_formatter())
        log.addHandler(handler)
        log.setLevel(level)

        # If running within a single process, we
        # want to temporarily suppress log messages
        # from the main log file (assumed to have
        # been configured with setup_logging).
        if getattr(log, 'handler', None):
            log.removeHandler(log.handler)

        # Log all fsl.wrappers calls via log_bip
        logcmd = ft.partial(log_bip, log, level)

        # Redirect fsl.wrappers stdout/stderr to
        # the same
        with wrappers.wrapperconfig(log={'tee'    : False,
                                         'stdout' : stdout,
                                         'stderr' : stdout,
                                         'cmd'    : logcmd}):
            try:
                log.info(f'Started {name}')
                log.info(f'Host {socket.gethostname()}')
                yield
            except Exception as e:
                traceback.print_exception(type(e), e, e.__traceback__,
                                          file=stdout)
                raise e
            finally:
                log.info(f'Finished {name}')
                log.removeHandler(handler)
                # Restore main log handler
                if getattr(log, 'handler', None):
                    log.addHandler(log.handler)


@contextlib.contextmanager
def tempdir(dir_name):
    os.makedirs(dir_name, exist_ok=True)
    yield dir_name
    for file_name in os.listdir(dir_name):
        file_path = os.path.join(dir_name, file_name)
        try:
            shutil.rmtree(file_path)
        except OSError:
            os.remove(file_path)