logging_utils.py

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