diff --git a/supervisor/dispatchers.py b/supervisor/dispatchers.py index f0e17104c..01fba9713 100644 --- a/supervisor/dispatchers.py +++ b/supervisor/dispatchers.py @@ -126,15 +126,19 @@ def _init_normallog(self): maxbytes = getattr(config, '%s_logfile_maxbytes' % channel) backups = getattr(config, '%s_logfile_backups' % channel) to_syslog = getattr(config, '%s_syslog' % channel) + loglevel = getattr(config, 'loglevel') + logformat = getattr(config, 'logformat') + logformatter = getattr(config, 'logformatter') if logfile or to_syslog: - self.normallog = config.options.getLogger() + self.normallog = config.options.getLogger(loglevel) if logfile: loggers.handle_file( self.normallog, filename=logfile, - fmt='%(message)s', + fmt=logformat, + formatter=logformatter, rotating=not not maxbytes, # optimization maxbytes=maxbytes, backups=backups diff --git a/supervisor/loggers.py b/supervisor/loggers.py index 44d14b44c..359d012a9 100644 --- a/supervisor/loggers.py +++ b/supervisor/loggers.py @@ -12,11 +12,18 @@ import sys import time import traceback +import logging +import json +import re from supervisor.compat import syslog from supervisor.compat import long from supervisor.compat import is_text_stream from supervisor.compat import as_string +from pythonjsonlogger import jsonlogger +from string import Template +from string import Formatter as StrFormatter + class LevelsByName: CRIT = 50 # messages that probably require immediate user attention @@ -44,21 +51,217 @@ def _levelNumbers(): return bynumber LOG_LEVELS_BY_NUM = _levelNumbers() +_str_formatter = StrFormatter() +del StrFormatter def getLevelNumByDescription(description): num = getattr(LevelsByDescription, description, None) return num +class PercentStyle(logging.PercentStyle): + validation_pattern = re.compile(r'%\(\w+\)[#0+ -]*(\*|\d+)?(\.(\*|\d+))?[diouxefgcrsa%]', re.I) + + def validate(self): + """Validate the input format, ensure it matches the correct style""" + if not self.validation_pattern.search(self._fmt): + raise ValueError("Invalid format '%s' for '%s' style" % (self._fmt, self.default_format[0])) + +class StrFormatStyle(logging.StrFormatStyle): + fmt_spec = re.compile(r'^(.?[<>=^])?[+ -]?#?0?(\d+|{\w+})?[,_]?(\.(\d+|{\w+}))?[bcdefgnosx%]?$', re.I) + field_spec = re.compile(r'^(\d+|\w+)(\.\w+|\[[^]]+\])*$') + + def _format(self, record): + return self._fmt.format(**record.__dict__) + + def validate(self): + """Validate the input format, ensure it is the correct string formatting style""" + fields = set() + try: + for _, fieldname, spec, conversion in _str_formatter.parse(self._fmt): + if fieldname: + if not self.field_spec.match(fieldname): + raise ValueError('invalid field name/expression: %r' % fieldname) + fields.add(fieldname) + if conversion and conversion not in 'rsa': + raise ValueError('invalid conversion: %r' % conversion) + if spec and not self.fmt_spec.match(spec): + raise ValueError('bad specifier: %r' % spec) + except ValueError as e: + raise ValueError('invalid format: %s' % e) + if not fields: + raise ValueError('invalid format: no fields') + + +class StringTemplateStyle(logging.StringTemplateStyle): + def validate(self): + pattern = Template.pattern + fields = set() + for m in pattern.finditer(self._fmt): + d = m.groupdict() + if d['named']: + fields.add(d['named']) + elif d['braced']: + fields.add(d['braced']) + elif m.group(0) == '$': + raise ValueError('invalid format: bare \'$\' not allowed') + if not fields: + raise ValueError('invalid format: no fields') + +BASIC_FORMAT = "%(asctime)s %(levelname)s %(message)s" +_STYLES = { + '%': (PercentStyle, BASIC_FORMAT), + '$': (StringTemplateStyle, '${asctim} ${levelname} ${message}'), + '{': (StrFormatStyle, '{asctim} {levelname} {message}') +} + +class PlainTextFormatter(logging.Formatter): + def __init__(self, *args, **kwargs): + """Constructor.""" + self.fields_with_default_value = kwargs.pop('fields_with_default_value', {}) + super().__init__(*args, **kwargs) + + def format(self, record): + # Add the fields with the default values first and then + # overwrite the default values with the existing LogReocrd fields. + _record = self.fields_with_default_value.copy() + _record.update(record.__dict__) + record.__dict__ = _record + + record.message = record.getMessage().rstrip('\n') + if self.usesTime(): + record.asctime = self.formatTime(record, self.datefmt) + return self.formatMessage(record) + +class CustomJsonFormatter(jsonlogger.JsonFormatter): + def __init__(self, *args, **kwargs): + """Constructor.""" + self.fields_with_default_value = kwargs.pop('fields_with_default_value', {}) + super().__init__(*args, **kwargs) + reserved_attrs = ('level', 'levelname', 'msg', 'kw', 'dictrepr', 'created', 'msecs') + reserved_attrs_dict = dict(zip(reserved_attrs, reserved_attrs)) + self._skip_fields.update(reserved_attrs_dict) + + def parse(self): + """ + Parses format string looking for substitutions + This method is responsible for returning a list of fields (as strings) + to include in all log messages. + """ + if isinstance(self._style, logging.StringTemplateStyle): + formatter_style_pattern = re.compile(r'\$\{(.+?)\}', re.IGNORECASE) + elif isinstance(self._style, logging.StrFormatStyle): + formatter_style_pattern = re.compile(r'\{(.+?)\}', re.IGNORECASE) + # PercentStyle is parent class of StringTemplateStyle and StrFormatStyle so + # it needs to be checked last. + elif isinstance(self._style, logging.PercentStyle): + formatter_style_pattern = re.compile(r'%\((.+?)\)s', re.IGNORECASE) + else: + raise ValueError('Invalid format: %s' % self._fmt) + return formatter_style_pattern.findall(self._fmt) + + def serialize_log_record(self, log_record): + """Returns the final representation of the log record.""" + return "%s%s" % (self.prefix, self.jsonify_log_record(log_record)) + + def format(self, record): + """Formats a log record and serializes to json""" + # Add the fields with the default values first and then + # overwrite the default values with the existing LogReocrd fields. + _record = self.fields_with_default_value.copy() + _record.update(record.__dict__) + record.__dict__ = _record + + record.__dict__ = _record + message_dict = {} + if isinstance(record.msg, dict): + message_dict = record.msg + record.message = None + else: + message = record.getMessage() + try: + message_dict = json.loads(message) + record.message = None + except json.decoder.JSONDecodeError: + record.message = message.rstrip('\n') + + # only format time if needed + if "asctime" in self._required_fields: + record.asctime = self.formatTime(record, self.datefmt) + + try: + log_record = OrderedDict() + except NameError: + log_record = {} + + self.add_fields(log_record, record, message_dict) + log_record = self.process_log_record(log_record) + return self.serialize_log_record(log_record) + + +class FormatterFacotry: + def get_formatter(self, name=None, fmt=None, style=None): + if name is None: + name = 'plaintext' + + if fmt is None: + fmt = '%(asctime)s %(levelname)s %(message)s' + + fmt, fields_with_default_value = self.get_fields_default_values(fmt) + + if style is None: + style = self.get_logformat_style(fmt) + + if name == 'plaintext': + return PlainTextFormatter(fmt, style=style, fields_with_default_value=fields_with_default_value) + elif name == 'json': + return CustomJsonFormatter(fmt, style=style, fields_with_default_value=fields_with_default_value) + else: + raise ValueError('Invalid formatter name: %s' % name) + + def get_logformat_style(self, fmt): + """Determine the string format style based on the logformat.""" + style = None + for style in _STYLES: + _style = _STYLES[style][0](fmt) + try: + _style.validate() + break # exit the loop if fmt passes style validation + except ValueError: + style = None + + if style is None: + raise ValueError('Invalid logging format: %s' % fmt) + + return style + + def get_fields_default_values(self, fmt): + fields_with_default_value = {} + placeholder_pattern = re.compile(r'[\{\(](.+?)[\}\)]', re.IGNORECASE) + for placeholder in placeholder_pattern.findall(fmt): + kv = placeholder.split(':', 1) + if len(kv) == 2: + key, val = kv + fields_with_default_value[key] = val + # remove the default value from the format string + fmt = fmt.replace(placeholder, key) + return fmt, fields_with_default_value + + +_formatter_factory = FormatterFacotry().get_formatter +BASIC_FORMATTER = _formatter_factory(name='plaintext', fmt=BASIC_FORMAT) + class Handler: - fmt = '%(message)s' level = LevelsByName.INFO def __init__(self, stream=None): self.stream = stream self.closed = False + self.formatter = BASIC_FORMATTER - def setFormat(self, fmt): - self.fmt = fmt + def setFormatter(self, formatter): + if type(formatter) not in [PlainTextFormatter, CustomJsonFormatter]: + raise ValueError('Invalid formatter: %s (%s)' % (formatter, type(formatter))) + self.formatter = formatter def setLevel(self, level): self.level = level @@ -87,17 +290,10 @@ def close(self): self.closed = True def emit(self, record): + raise NotImplementedError('emit must be implemented by Handler subclasses') + + def write(self, msg): try: - binary = (self.fmt == '%(message)s' and - isinstance(record.msg, bytes) and - (not record.kw or record.kw == {'exc_info': None})) - binary_stream = not is_text_stream(self.stream) - if binary: - msg = record.msg - else: - msg = self.fmt % record.asdict() - if binary_stream: - msg = msg.encode('utf-8') try: self.stream.write(msg) except UnicodeError: @@ -116,6 +312,8 @@ def handleError(self): del ei class StreamHandler(Handler): + terminator = '\n' + def __init__(self, strm=None): Handler.__init__(self, strm) @@ -126,6 +324,10 @@ def remove(self): def reopen(self): pass + def emit(self, record): + msg = self.formatter.format(record) + self.write(msg + self.terminator) + class BoundIO: def __init__(self, maxbytes, buf=b''): self.maxbytes = maxbytes @@ -152,6 +354,7 @@ def clear(self): class FileHandler(Handler): """File handler which supports reopening of logs. """ + terminator = '\n' def __init__(self, filename, mode='ab'): Handler.__init__(self) @@ -185,6 +388,15 @@ def remove(self): if why.args[0] != errno.ENOENT: raise + def emit(self, record): + msg = self.formatter.format(record) + if 'b' in self.mode: + msg = bytes(msg, 'utf-8') + bytes_terminator = bytes(self.terminator, 'utf-8') + self.write(msg + bytes_terminator) + else: + self.write(msg + self.terminator) + class RotatingFileHandler(FileHandler): def __init__(self, filename, mode='ab', maxBytes=512*1024*1024, backupCount=10): @@ -278,15 +490,18 @@ def doRollover(self): class LogRecord: def __init__(self, level, msg, **kw): self.level = level - self.msg = msg + self.levelname = LOG_LEVELS_BY_NUM[level] + self.msg = msg if isinstance(msg, str) else msg.decode('utf-8') self.kw = kw self.dictrepr = None + self.created = time.time() + self.msecs = (self.created - int(self.created)) * 1000 def asdict(self): if self.dictrepr is None: - now = time.time() - msecs = (now - long(now)) * 1000 - part1 = time.strftime("%Y-%m-%d %H:%M:%S", time.localtime(now)) + ct = self.created + msecs = (ct - long(ct)) * 1000 + part1 = time.strftime("%Y-%m-%d %H:%M:%S", time.localtime(ct)) asctime = '%s,%03d' % (part1, msecs) levelname = LOG_LEVELS_BY_NUM[self.level] msg = as_string(self.msg) @@ -296,6 +511,9 @@ def asdict(self): 'asctime':asctime} return self.dictrepr + def getMessage(self): + return self.msg + class Logger: def __init__(self, level=None, handlers=None): if level is None: @@ -371,7 +589,7 @@ def emit(self, record): message = params['message'] for line in message.rstrip('\n').split('\n'): params['message'] = line - msg = self.fmt % params + msg = self.fmt % params # BUG: this will break with the new foramtter. try: self._syslog(msg) except UnicodeError: @@ -384,30 +602,33 @@ def getLogger(level=None): _2MB = 1<<21 -def handle_boundIO(logger, fmt, maxbytes=_2MB): +def handle_boundIO(logger, fmt, formatter=None, maxbytes=_2MB): """Attach a new BoundIO handler to an existing Logger""" io = BoundIO(maxbytes) handler = StreamHandler(io) handler.setLevel(logger.level) - handler.setFormat(fmt) + _formatter = _formatter_factory(name=formatter, fmt=fmt) + handler.setFormatter(_formatter) logger.addHandler(handler) logger.getvalue = io.getvalue -def handle_stdout(logger, fmt): +def handle_stdout(logger, fmt, formatter=None): """Attach a new StreamHandler with stdout handler to an existing Logger""" handler = StreamHandler(sys.stdout) - handler.setFormat(fmt) + _formatter = _formatter_factory(name=formatter, fmt=fmt) + handler.setFormatter(_formatter) handler.setLevel(logger.level) logger.addHandler(handler) -def handle_syslog(logger, fmt): +def handle_syslog(logger, fmt, formatter=None): """Attach a new Syslog handler to an existing Logger""" handler = SyslogHandler() - handler.setFormat(fmt) + _formatter = _formatter_factory(name=formatter, fmt=fmt) + handler.setFormatter(_formatter) handler.setLevel(logger.level) logger.addHandler(handler) -def handle_file(logger, filename, fmt, rotating=False, maxbytes=0, backups=0): +def handle_file(logger, filename, fmt, formatter=None, rotating=False, maxbytes=0, backups=0): """Attach a new file handler to an existing Logger. If the filename is the magic name of 'syslog' then make it a syslog handler instead.""" if filename == 'syslog': # TODO remove this @@ -417,6 +638,8 @@ def handle_file(logger, filename, fmt, rotating=False, maxbytes=0, backups=0): handler = FileHandler(filename) else: handler = RotatingFileHandler(filename, 'a', maxbytes, backups) - handler.setFormat(fmt) + + _formatter = _formatter_factory(name=formatter, fmt=fmt) + handler.setFormatter(_formatter) handler.setLevel(logger.level) logger.addHandler(handler) diff --git a/supervisor/options.py b/supervisor/options.py index 7b53cc760..5320eedac 100644 --- a/supervisor/options.py +++ b/supervisor/options.py @@ -433,6 +433,10 @@ def __init__(self): "z:", "logfile_backups=", integer, default=10) self.add("loglevel", "supervisord.loglevel", "e:", "loglevel=", logging_level, default="info") + self.add("logformat", "supervisord.logformat", + default="%(asctime)s %(levelname)s %(message)s") + self.add("logformatter", "supervisord.logformatter", + default="plaintext") self.add("pidfile", "supervisord.pidfile", "j:", "pidfile=", existing_dirpath, default="supervisord.pid") self.add("identifier", "supervisord.identifier", "i:", "identifier=", @@ -451,6 +455,7 @@ def __init__(self): "", "profile_options=", profile_options, default=None) self.add("silent", "supervisord.silent", "s", "silent", flag=1, default=0) + self.pidhistory = {} self.process_group_configs = [] self.parse_criticals = [] @@ -497,6 +502,12 @@ def realize(self, *arg, **kw): if not self.loglevel: self.loglevel = section.loglevel + if not self.logformat: + self.logformat = section.logformat + + if not self.logformatter: + self.logformatter = section.logformatter + if self.logfile: logfile = self.logfile else: @@ -643,6 +654,9 @@ def get(opt, default, **kwargs): section.logfile_maxbytes = byte_size(get('logfile_maxbytes', '50MB')) section.logfile_backups = integer(get('logfile_backups', 10)) section.loglevel = logging_level(get('loglevel', 'info')) + # Default to str.format style to avoid conflicting with environment variables expansion syntax. + section.logformat = get('logformat', '{asctime} {levelname} {message}') + section.logformatter = get('logformatter', 'plaintext') section.pidfile = existing_dirpath(get('pidfile', 'supervisord.pid')) section.identifier = get('identifier', 'supervisor') section.nodaemon = boolean(get('nodaemon', 'false')) @@ -930,6 +944,10 @@ def get(section, opt, *args, **kwargs): stderr_cmaxbytes = byte_size(get(section,'stderr_capture_maxbytes','0')) stderr_events = boolean(get(section, 'stderr_events_enabled','false')) serverurl = get(section, 'serverurl', None) + loglevel = logging_level(get(section, 'loglevel', 'info')) + # Default to str.format style to avoid conflicting with environment variables expansion syntax. + logformat = get(section, 'logformat', '{asctime} {levelname} {message}') + logformatter = get(section, 'logformatter', 'plaintext') if serverurl and serverurl.strip().upper() == 'AUTO': serverurl = None @@ -1057,7 +1075,11 @@ def get(section, opt, *args, **kwargs): exitcodes=exitcodes, redirect_stderr=redirect_stderr, environment=environment, - serverurl=serverurl) + serverurl=serverurl, + loglevel=loglevel, + logformat=logformat, + logformatter=logformatter + ) programs.append(pconfig) @@ -1487,14 +1509,14 @@ def set_rlimits_or_exit(self): def make_logger(self): # must be called after realize() and after supervisor does setuid() - format = '%(asctime)s %(levelname)s %(message)s\n' self.logger = loggers.getLogger(self.loglevel) if self.nodaemon and not self.silent: - loggers.handle_stdout(self.logger, format) + loggers.handle_stdout(self.logger, self.logformat, self.logformatter) loggers.handle_file( self.logger, self.logfile, - format, + self.logformat, + self.logformatter, rotating=not not self.logfile_maxbytes, maxbytes=self.logfile_maxbytes, backups=self.logfile_backups, @@ -1874,7 +1896,7 @@ class ProcessConfig(Config): 'stderr_logfile_backups', 'stderr_logfile_maxbytes', 'stderr_events_enabled', 'stderr_syslog', 'stopsignal', 'stopwaitsecs', 'stopasgroup', 'killasgroup', - 'exitcodes', 'redirect_stderr' ] + 'exitcodes', 'redirect_stderr', 'loglevel', 'logformat', 'logformatter'] optional_param_names = [ 'environment', 'serverurl' ] def __init__(self, options, **params): diff --git a/supervisor/tests/base.py b/supervisor/tests/base.py index bef82e964..3001dec25 100644 --- a/supervisor/tests/base.py +++ b/supervisor/tests/base.py @@ -520,7 +520,8 @@ def __init__(self, options, name, command, directory=None, umask=None, stderr_syslog=False, redirect_stderr=False, stopsignal=None, stopwaitsecs=10, stopasgroup=False, killasgroup=False, - exitcodes=(0,), environment=None, serverurl=None): + exitcodes=(0,), environment=None, serverurl=None, + loglevel='info', logformat='{message}', logformatter='plaintext'): self.options = options self.name = name self.command = command @@ -556,6 +557,9 @@ def __init__(self, options, name, command, directory=None, umask=None, self.umask = umask self.autochildlogs_created = False self.serverurl = serverurl + self.loglevel = loglevel + self.logformat = logformat + self.logformatter = logformatter def get_path(self): return ["/bin", "/usr/bin", "/usr/local/bin"]