logging_utils.py

   1 #!/usr/bin/env python3
   2
   3 """Utilities related to logging."""
   4
   5 import contextlib
   6 import datetime
   7 import logging
   8 from logging.handlers import RotatingFileHandler, SysLogHandler
   9 import os
  10 import pytz
  11 import sys
  12
  13 # This module is commonly used by others in here and should avoid
  14 # taking any unnecessary dependencies back on them.
  15 import argparse_utils
  16 import config
  17
  18 cfg = config.add_commandline_args(
  19     f'Logging ({__file__})',
  20     'Args related to logging')
  21 cfg.add_argument(
  22     '--logging_config_file',
  23     type=argparse_utils.valid_filename,
  24     default=None,
  25     metavar='FILENAME',
  26     help='Config file containing the logging setup, see: https://docs.python.org/3/howto/logging.html#logging-advanced-tutorial',
  27 )
  28 cfg.add_argument(
  29     '--logging_level',
  30     type=str,
  31     default='INFO',
  32     choices=['NOTSET', 'DEBUG', 'INFO', 'WARNING', 'ERROR', 'CRITICAL'],
  33     metavar='LEVEL',
  34     help='The level below which to squelch log messages.',
  35 )
  36 cfg.add_argument(
  37     '--logging_format',
  38     type=str,
  39     default='%(levelname)s:%(asctime)s: %(message)s',
  40     help='The format for lines logged via the logger module.'
  41 )
  42 cfg.add_argument(
  43     '--logging_date_format',
  44     type=str,
  45     default='%Y/%m/%dT%H:%M:%S.%f%z',
  46     metavar='DATEFMT',
  47     help='The format of any dates in --logging_format.'
  48 )
  49 cfg.add_argument(
  50     '--logging_console',
  51     action=argparse_utils.ActionNoYes,
  52     default=True,
  53     help='Should we log to the console (stderr)',
  54 )
  55 cfg.add_argument(
  56     '--logging_filename',
  57     type=str,
  58     default=None,
  59     metavar='FILENAME',
  60     help='The filename of the logfile to write.'
  61 )
  62 cfg.add_argument(
  63     '--logging_filename_maxsize',
  64     type=int,
  65     default=(1024*1024),
  66     metavar='#BYTES',
  67     help='The maximum size (in bytes) to write to the logging_filename.'
  68 )
  69 cfg.add_argument(
  70     '--logging_filename_count',
  71     type=int,
  72     default=2,
  73     metavar='COUNT',
  74     help='The number of logging_filename copies to keep before deleting.'
  75 )
  76 cfg.add_argument(
  77     '--logging_syslog',
  78     action=argparse_utils.ActionNoYes,
  79     default=False,
  80     help='Should we log to localhost\'s syslog.'
  81 )
  82 cfg.add_argument(
  83     '--logging_debug_threads',
  84     action=argparse_utils.ActionNoYes,
  85     default=False,
  86     help='Should we prepend pid/tid data to all log messages?'
  87 )
  88 cfg.add_argument(
  89     '--logging_info_is_print',
  90     action=argparse_utils.ActionNoYes,
  91     default=False,
  92     help='logging.info also prints to stdout.'
  93 )
  94
  95
  96 class OnlyInfoFilter(logging.Filter):
  97     def filter(self, record):
  98         return record.levelno == logging.INFO
  99
 100
 101 class MillisecondAwareFormatter(logging.Formatter):
 102     converter = datetime.datetime.fromtimestamp
 103
 104     def formatTime(self, record, datefmt=None):
 105         ct = MillisecondAwareFormatter.converter(
 106             record.created, pytz.timezone("US/Pacific")
 107         )
 108         if datefmt:
 109             s = ct.strftime(datefmt)
 110         else:
 111             t = ct.strftime("%Y-%m-%d %H:%M:%S")
 112             s = "%s,%03d" % (t, record.msecs)
 113         return s
 114
 115
 116 def initialize_logging(logger=None) -> logging.Logger:
 117     assert config.has_been_parsed()
 118     if logger is None:
 119         logger = logging.getLogger()       # Root logger
 120
 121     if config.config['logging_config_file'] is not None:
 122         logging.config.fileConfig('logging.conf')
 123         return logger
 124
 125     handlers = []
 126     numeric_level = getattr(
 127         logging,
 128         config.config['logging_level'].upper(),
 129         None
 130     )
 131     if not isinstance(numeric_level, int):
 132         raise ValueError('Invalid level: %s' % config.config['logging_level'])
 133
 134     fmt = config.config['logging_format']
 135     if config.config['logging_debug_threads']:
 136         fmt = f'%(process)d.%(thread)d|{fmt}'
 137
 138     if config.config['logging_syslog']:
 139         if sys.platform in ('win32', 'cygwin'):
 140             print(
 141                 "WARNING: Current platform does not support syslog; IGNORING.",
 142                 file=sys.stderr
 143             )
 144         else:
 145             handler = SysLogHandler()
 146 #            for k, v in encoded_priorities.items():
 147 #                handler.encodePriority(k, v)
 148             handler.setFormatter(
 149                 MillisecondAwareFormatter(
 150                     fmt=fmt,
 151                     datefmt=config.config['logging_date_format'],
 152                 )
 153             )
 154             handler.setLevel(numeric_level)
 155             handlers.append(handler)
 156
 157     if config.config['logging_filename'] is not None:
 158         handler = RotatingFileHandler(
 159             config.config['logging_filename'],
 160             maxBytes = config.config['logging_filename_maxsize'],
 161             backupCount = config.config['logging_filename_count'],
 162         )
 163         handler.setLevel(numeric_level)
 164         handler.setFormatter(
 165             MillisecondAwareFormatter(
 166                 fmt=fmt,
 167                 datefmt=config.config['logging_date_format'],
 168             )
 169         )
 170         handlers.append(handler)
 171
 172     if config.config['logging_console']:
 173         handler = logging.StreamHandler(sys.stderr)
 174         handler.setLevel(numeric_level)
 175         handler.setFormatter(
 176             MillisecondAwareFormatter(
 177                 fmt=fmt,
 178                 datefmt=config.config['logging_date_format'],
 179             )
 180         )
 181         handlers.append(handler)
 182
 183     if len(handlers) == 0:
 184         handlers.append(logging.NullHandler())
 185
 186     for handler in handlers:
 187         logger.addHandler(handler)
 188     if config.config['logging_info_is_print']:
 189         handler = logging.StreamHandler(sys.stdout)
 190         handler.addFilter(OnlyInfoFilter())
 191         logger.addHandler(handler)
 192     logger.setLevel(numeric_level)
 193     logger.propagate = False
 194     return logger
 195
 196
 197 def get_logger(name: str = ""):
 198     logger = logging.getLogger(name)
 199     return initialize_logging(logger)
 200
 201
 202 def tprint(*args, **kwargs) -> None:
 203     if config.config['logging_debug_threads']:
 204         from thread_utils import current_thread_id
 205         print(f'{current_thread_id()}', end="")
 206         print(*args, **kwargs)
 207     else:
 208         pass
 209
 210
 211 def dprint(*args, **kwargs) -> None:
 212     print(*args, file=sys.stderr, **kwargs)
 213
 214
 215 class OutputSink(object):
 216
 217     # Bits in the destination_bitv bitvector.  Used to indicate the
 218     # output destination.
 219     STDOUT = 0x1
 220     STDERR = 0x2
 221     LOG_DEBUG = 0x4          # -\
 222     LOG_INFO = 0x8           #  |
 223     LOG_WARNING = 0x10       #   > Should provide logger to the c'tor.
 224     LOG_ERROR = 0x20         #  |
 225     LOG_CRITICAL = 0x40      # _/
 226     FILENAME = 0x80          # Must provide a filename to the c'tor.
 227     HLOG = 0x100
 228
 229     ALL_LOG_DESTINATIONS = (
 230         LOG_DEBUG | LOG_INFO | LOG_WARNING | LOG_ERROR | LOG_CRITICAL
 231     )
 232     ALL_OUTPUT_DESTINATIONS = 0x1FF
 233
 234     def __init__(self,
 235                  destination_bitv: int,
 236                  *,
 237                  logger=None,
 238                  filename=None):
 239         if logger is None:
 240             logger = logging.getLogger(None)
 241         self.logger = logger
 242
 243         if filename is not None:
 244             self.f = open(filename, "wb", buffering=0)
 245         else:
 246             if self.destination_bitv & OutputSink.FILENAME:
 247                 raise ValueError(
 248                     "Filename argument is required if bitv & FILENAME"
 249                 )
 250             self.f = None
 251         self.set_destination_bitv(destination_bitv)
 252
 253     def get_destination_bitv(self):
 254         return self.destination_bitv
 255
 256     def set_destination_bitv(self, destination_bitv: int):
 257         if destination_bitv & self.FILENAME and self.f is None:
 258             raise ValueError(
 259                 "Filename argument is required if bitv & FILENAME"
 260             )
 261         self.destination_bitv = destination_bitv
 262
 263     def print(self, *args, **kwargs):
 264         from string_utils import sprintf, strip_escape_sequences
 265         end = kwargs.pop("end", None)
 266         if end is not None:
 267             if not isinstance(end, str):
 268                 raise TypeError("end must be None or a string")
 269         sep = kwargs.pop("sep", None)
 270         if sep is not None:
 271             if not isinstance(sep, str):
 272                 raise TypeError("sep must be None or a string")
 273         if kwargs:
 274             raise TypeError("invalid keyword arguments to print()")
 275         buf = sprintf(*args, end="", sep=sep)
 276         if sep is None:
 277             sep = " "
 278         if end is None:
 279             end = "\n"
 280         if self.destination_bitv & self.STDOUT:
 281             print(buf, file=sys.stdout, sep=sep, end=end)
 282         if self.destination_bitv & self.STDERR:
 283             print(buf, file=sys.stderr, sep=sep, end=end)
 284         if end == '\n':
 285             buf += '\n'
 286         if self.destination_bitv & self.FILENAME and self.f is not None:
 287             self.f.write(buf.encode('utf-8'))
 288             self.f.flush()
 289         buf = strip_escape_sequences(buf)
 290         if self.logger is not None:
 291             if self.destination_bitv & self.LOG_DEBUG:
 292                 self.logger.debug(buf)
 293             if self.destination_bitv & self.LOG_INFO:
 294                 self.logger.info(buf)
 295             if self.destination_bitv & self.LOG_WARNING:
 296                 self.logger.warning(buf)
 297             if self.destination_bitv & self.LOG_ERROR:
 298                 self.logger.error(buf)
 299             if self.destination_bitv & self.LOG_CRITICAL:
 300                 self.logger.critical(buf)
 301         if self.destination_bitv & self.HLOG:
 302             hlog(buf)
 303
 304     def close(self):
 305         if self.f is not None:
 306             self.f.close()
 307
 308
 309 class OutputContext(OutputSink, contextlib.ContextDecorator):
 310     def __init__(self,
 311                  destination_bitv: int,
 312                  *,
 313                  logger=None,
 314                  filename=None):
 315         super().__init__(destination_bitv, logger=logger, filename=filename)
 316
 317     def __enter__(self):
 318         return self
 319
 320     def __exit__(self, etype, value, traceback):
 321         super().close()
 322         if etype is not None:
 323             return False
 324         return True
 325
 326
 327 def hlog(message: str) -> None:
 328     message = message.replace("'", "'\"'\"'")
 329     os.system(f"/usr/bin/logger -p local7.info -- '{message}'")