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