Disable Format for some messages

Question

I am working with pythons logging library developing a data analysis pipeline. I am logging both custom messages about what steps are being run and also the raw output of invoked programs. I am using sh.py to simplify the calling of shell commands. It lets me define a callback function to process each line of STDOUT/STDERR.

I would like to be able to define my call back function to log each line to the log file with out the formatting (these programs output a lot of lines):

log.info("Starting %s run on %s", program_name, file_name)

def call_back(line):
    log.info.NOFORMAT(line)  # do the no format logging

sh.program(args, _out=call_back)

log.info("Finished running %s", program_name)

My resulting log file would then look like:

"""<br>
2016-01-22|{INFO}: Starting $SOME_PROGRAM$ on $SOME_FILE$<br>
program_output_line<br>
program_output_line<br>
program_output_line<br>
program_output_line<br>
program_output_line<br>
2016-01-22|{INFO}: Finished running $SOME_PROGRAM$<br>
"""

Does anyone know how I can accomplish this?

Answer 1

You can do this by extending the logging.Formatter class. If a log message ships with an optional metadata simple=True - then no formatting will be rendered for that specific message.

class ConditionalFormatter(logging.Formatter):
    def format(self, record):
        if hasattr(record, 'simple') and record.simple:
            return record.getMessage()
        else:
            return logging.Formatter.format(self, record)


rotating_file_formatter = ConditionalFormatter('%(asctime)s %(levelname)s - %(message)s')
rotating_file.setFormatter(rotating_file_formatter)
# ...

• With formatting

  logging.info("starting application ...")
  

  log output:

  2020-05-01 19:38:05,337 INFO - starting application ...
  

• Without formatting

  logging.info("starting application ...", extra={'simple': True})
  

  log output:

  starting application ...
  

---

Full Example

In this script I'm using console logging and file logging. Among general logs, I'm invoking a command ls -ahl / and piping all of it's output straight to log without formatting:

#!/usr/bin/env python3

import logging
import subprocess
import sys
from logging.handlers import RotatingFileHandler


def initialize_logger(log_file_path):
    rotating_file = RotatingFileHandler(log_file_path, mode='a', maxBytes=5 * 1024 * 1024, backupCount=5, encoding=None, delay=0)

    class ConditionalFormatter(logging.Formatter):
        def format(self, record):
            if hasattr(record, 'simple') and record.simple:
                return record.getMessage()
            else:
                return logging.Formatter.format(self, record)

    rotating_file_formatter = ConditionalFormatter('%(asctime)s %(levelname)s - %(message)s')
    rotating_file.setFormatter(rotating_file_formatter)
    rotating_file.setLevel(logging.DEBUG)

    console_logger = logging.StreamHandler(sys.stdout)
    console_logger_formatter = logging.Formatter('%(message)s')
    console_logger.setFormatter(console_logger_formatter)
    console_logger.setLevel(logging.INFO)

    root_logger = logging.getLogger()
    root_logger.setLevel(logging.DEBUG)
    root_logger.addHandler(rotating_file)
    root_logger.addHandler(console_logger)


def main():
    initialize_logger('/var/log/my-app.log')
    logging.info('starting application ...')

    command = ["ls", "-ahl"]
    working_directory = '/'
    logging.info(f'running {command} ...')
    process = subprocess.Popen(command, stdout=subprocess.PIPE, stderr=subprocess.STDOUT, cwd=working_directory)

    with process.stdout:
        for line in iter(process.stdout.readline, b''):
            line = line.decode('utf-8')
            line = line.strip()
            logging.debug(line, extra={'simple': True})

    exit_code = process.wait()
    if exit_code == 0:
        logging.debug(f'command "{command}" finished successfully')
    else:
        logging.debug(f'command "{command}" failed with exit code {exit_code}')

    logging.info('stopping application')


if __name__ == '__main__':
    main()

stdout:

starting application ...
running ['ls', '-ahl'] ...
stopping application

output file /var/log/my-app.log:

2020-05-01 19:48:06,347 INFO - starting application ...
2020-05-01 19:48:06,347 INFO - running ['ls', '-ahl', '/'] ...
total 112K
drwxr-xr-x  25 root root 4.0K Apr 30 06:55 .
drwxr-xr-x  25 root root 4.0K Apr 30 06:55 ..
drwxr-xr-x   2 root root 4.0K Mar 31 06:39 bin
drwxr-xr-x   3 root root 4.0K May  1 06:02 boot
drwxrwxr-x   2 root root 4.0K Oct 11  2018 cdrom
drwxr-xr-x  20 root root 4.2K Apr 30 06:54 dev
drwxr-xr-x 154 root root  12K Apr 30 06:54 etc
drwxr-xr-x   3 root root 4.0K Oct 11  2018 home
lrwxrwxrwx   1 root root   33 Apr 30 06:55 initrd.img -> boot/initrd.img-4.15.0-99-generic
lrwxrwxrwx   1 root root   33 Apr 30 06:55 initrd.img.old -> boot/initrd.img-4.15.0-96-generic
drwxr-xr-x  21 root root 4.0K Oct 20  2018 lib
drwxr-xr-x   2 root root 4.0K Oct 20  2018 lib32
drwxr-xr-x   2 root root 4.0K Jul 25  2018 lib64
drwx------   2 root root  16K Oct 11  2018 lost+found
drwxr-xr-x   4 root root 4.0K Oct 15  2018 media
drwxr-xr-x   3 root root 4.0K Jun 20  2019 mnt
drwxrwxrwx  23 root root 4.0K May  1 16:56 opt
dr-xr-xr-x 302 root root    0 Apr 23 19:57 proc
drwx------   6 root root 4.0K Apr 29 22:31 root
drwxr-xr-x  40 root root 1.4K May  1 14:44 run
drwxr-xr-x   2 root root  12K Feb  9 12:00 sbin
drwxr-xr-x  15 root root 4.0K Apr 25 11:15 snap
drwxr-xr-x   2 root root 4.0K Jul 25  2018 srv
dr-xr-xr-x  13 root root    0 May  1 18:53 sys
drwxrwxrwt  32 root root 4.0K May  1 19:39 tmp
drwxr-xr-x  11 root root 4.0K Oct 20  2018 usr
drwxr-xr-x  15 root root 4.0K Jun 20  2019 var
lrwxrwxrwx   1 root root   30 Apr 30 06:55 vmlinuz -> boot/vmlinuz-4.15.0-99-generic
lrwxrwxrwx   1 root root   30 Apr 30 06:55 vmlinuz.old -> boot/vmlinuz-4.15.0-96-generic
2020-05-01 19:48:06,357 DEBUG - command "['ls', '-ahl', '/']" finished successfully
2020-05-01 19:48:06,357 INFO - stopping application

Answer 2

You can setup a logging.Formatter object for the handler that will be used by the Logger. It should implement the format(record) method that will return the string that will be actually displayed.

import sh
import logging

class MyFormatter(logging.Formatter):
    def __init__(self, *args, **kwargs):
        logging.Formatter.__init__(self, *args, **kwargs)
        self._enableFormatFlag = True

    def enableFormat(self):
        self._enableFormatFlag = True
    def disableFormat(self):
        self._enableFormatFlag = False

    def format(self, record):
        if self._enableFormatFlag:
            return logging.Formatter.format(self, record)
        else:
            return record.getMessage()

logger = logging.getLogger('myapp')
logger.setLevel(logging.INFO)
handler = logging.StreamHandler()
logger.addHandler(handler)
formatter = MyFormatter(fmt="prefix[%(message)s]suffix")
handler.setFormatter(formatter)


def callback(line):
    logger.info(line.strip())

logger.info("Will start program")
formatter.disableFormat()
sh.ls(['-l'],_out=callback)
formatter.enableFormat()
logger.info("Finished program")

PS: My previous answer was about getting the callback, sorry.