Feature/custom log formatting

docs/configuration.rst

@@ -301,6 +301,35 @@ follows.
 
   *Introduced*: 3.0
 
+``logfile_format``
+
+  The format string used for entries in the main supervisord activity log.
+  This uses Python's `logging format strings <https://docs.python.org/3/library/logging.html#logrecord-attributes>`_.
+  Available fields include ``%(asctime)s`` (timestamp), ``%(levelname)s``
+  (log level), ``%(message)s`` (log message), ``%(process)d`` (process ID),
+  ``%(name)s`` (logger name), and other standard Python logging attributes.
+
+  *Default*: ``%(asctime)s %(levelname)s %(message)s``
+
+  *Required*:  No.
+
+  *Introduced*: 4.3.0
+
+``childlog_format``
+
+  The format string used for entries in child process log files (stdout/stderr).
+  This uses Python's `logging format strings <https://docs.python.org/3/library/logging.html#logrecord-attributes>`_.
+  Available fields include ``%(asctime)s`` (timestamp), ``%(message)s``
+  (the actual output from the child process), ``%(name)s`` (logger name),
+  and other standard Python logging attributes. Note that ``%(levelname)s``
+  and ``%(process)d`` refer to the supervisord process, not the child process.
+
+  *Default*: ``%(message)s``
+
+  *Required*:  No.
+
+  *Introduced*: 4.3.0
+
 ``pidfile``
 
   The location in which supervisord keeps its pid file.  This option
@@ -485,6 +514,8 @@ follows.
    logfile_maxbytes = 50MB
    logfile_backups=10
    loglevel = info
+   logfile_format = %(asctime)s %(levelname)s %(message)s
+   childlog_format = %(message)s
    pidfile = /tmp/supervisord.pid
    nodaemon = false
    minfds = 1024
@@ -930,6 +961,13 @@ where specified.
     that is not seekable, log rotation must be disabled by setting
     ``stdout_logfile_maxbytes = 0``.
 
+  .. note::
+
+    The format of entries written to the stdout log file is controlled
+    by the ``childlog_format`` option in the ``[supervisord]`` section.
+    By default, only the raw output from the child process is logged,
+    but you can customize it to include timestamps and other information.
+
   *Default*: ``AUTO``
 
   *Required*:  No.
@@ -990,6 +1028,8 @@ where specified.
 ``stdout_syslog``
 
   If true, stdout will be directed to syslog along with the process name.
+  The format of syslog entries is controlled by the ``childlog_format``
+  option in the ``[supervisord]`` section, prefixed with the process name.
 
   *Default*: False
 
@@ -1015,6 +1055,13 @@ where specified.
     that is not seekable, log rotation must be disabled by setting
     ``stderr_logfile_maxbytes = 0``.
 
+  .. note::
+
+    The format of entries written to the stderr log file is controlled
+    by the ``childlog_format`` option in the ``[supervisord]`` section.
+    By default, only the raw output from the child process is logged,
+    but you can customize it to include timestamps and other information.
+
   *Default*: ``AUTO``
 
   *Required*:  No.
@@ -1073,6 +1120,8 @@ where specified.
 ``stderr_syslog``
 
   If true, stderr will be directed to syslog along with the process name.
+  The format of syslog entries is controlled by the ``childlog_format``
+  option in the ``[supervisord]`` section, prefixed with the process name.
 
   *Default*: False
 

supervisor/dispatchers.py

@@ -105,7 +105,13 @@ def __init__(self, process, event_type, fd):
         self.endtoken_data = (endtoken, len(endtoken))
         self.mainlog_level = loggers.LevelsByName.DEBG
         config = self.process.config
-        self.log_to_mainlog = config.options.loglevel <= self.mainlog_level
+        # Handle case where options haven't been realized yet
+        loglevel = getattr(config.options, 'loglevel', None)
+        if loglevel is None:
+            # Default loglevel when not set
+            from supervisor.loggers import LevelsByName
+            loglevel = LevelsByName.INFO
+        self.log_to_mainlog = loglevel <= self.mainlog_level
         self.stdout_events_enabled = config.stdout_events_enabled
         self.stderr_events_enabled = config.stderr_events_enabled
 
@@ -126,19 +132,26 @@ def _init_normallog(self):
             self.normallog = config.options.getLogger()
 
         if logfile:
+            fmt = getattr(config.options, 'childlog_format', None)
+            if fmt is None:
+                fmt = '%(message)s'  # Default format
             loggers.handle_file(
                 self.normallog,
                 filename=logfile,
-                fmt='%(message)s',
+                fmt=fmt,
                 rotating=not not maxbytes, # optimization
                 maxbytes=maxbytes,
                 backups=backups
             )
 
         if to_syslog:
+            childlog_format = getattr(config.options, 'childlog_format', None)
+            if childlog_format is None:
+                childlog_format = '%(message)s'  # Default format
+            fmt = config.name + ' ' + childlog_format
             loggers.handle_syslog(
                 self.normallog,
-                fmt=config.name + ' %(message)s'
+                fmt=fmt
             )
 
     def _init_capturelog(self):

supervisor/loggers.py

@@ -153,9 +153,12 @@ class FileHandler(Handler):
     """File handler which supports reopening of logs.
     """
 
-    def __init__(self, filename, mode='ab'):
+    def __init__(self, filename, mode='ab', fmt=None):
         Handler.__init__(self)
 
+        if fmt is not None:
+            self.setFormat(fmt)
+
         try:
             self.stream = open(filename, mode)
         except OSError as e:
@@ -187,7 +190,7 @@ def remove(self):
 
 class RotatingFileHandler(FileHandler):
     def __init__(self, filename, mode='ab', maxBytes=512*1024*1024,
-                 backupCount=10):
+                 backupCount=10, fmt=None):
         """
         Open the specified file and use it as the stream for logging.
 
@@ -210,7 +213,7 @@ def __init__(self, filename, mode='ab', maxBytes=512*1024*1024,
         """
         if maxBytes > 0:
             mode = 'ab' # doesn't make sense otherwise!
-        FileHandler.__init__(self, filename, mode)
+        FileHandler.__init__(self, filename, mode, fmt)
         self.maxBytes = maxBytes
         self.backupCount = backupCount
         self.counter = 0
@@ -292,8 +295,17 @@ def asdict(self):
             msg = as_string(self.msg)
             if self.kw:
                 msg = msg % self.kw
-            self.dictrepr = {'message':msg, 'levelname':levelname,
-                             'asctime':asctime}
+            self.dictrepr = {
+                'message': msg,
+                'levelname': levelname,
+                'asctime': asctime,
+                'levelno': self.level,
+                'process': os.getpid(),
+                'processName': 'supervisord',
+                'threadName': 'MainThread'
+            }
+            self.dictrepr.update(self.kw)
+
         return self.dictrepr
 
 class Logger:
@@ -379,8 +391,18 @@ def emit(self, record):
         except:
             self.handleError()
 
-def getLogger(level=None):
-    return Logger(level)
+def getLogger(level=None, fmt=None):
+    logger = Logger(level)
+    if fmt is not None:
+        # Create a handler with the specified format
+        handler = StreamHandler()
+        handler.setFormat(fmt)
+        if level is not None:
+            handler.setLevel(level)
+        else:
+            handler.setLevel(logger.level)
+        logger.addHandler(handler)
+    return logger
 
 _2MB = 1<<21
 
@@ -400,6 +422,13 @@ def handle_stdout(logger, fmt):
     handler.setLevel(logger.level)
     logger.addHandler(handler)
 
+def handle_stderr(logger, fmt):
+    """Attach a new StreamHandler with stderr handler to an existing Logger"""
+    handler = StreamHandler(sys.stderr)
+    handler.setFormat(fmt)
+    handler.setLevel(logger.level)
+    logger.addHandler(handler)
+
 def handle_syslog(logger, fmt):
     """Attach a new Syslog handler to an existing Logger"""
     handler = SyslogHandler()
@@ -413,10 +442,28 @@ def handle_file(logger, filename, fmt, rotating=False, maxbytes=0, backups=0):
     if filename == 'syslog': # TODO remove this
         handler = SyslogHandler()
     else:
-        if rotating is False:
-            handler = FileHandler(filename)
-        else:
-            handler = RotatingFileHandler(filename, 'a', maxbytes, backups)
-    handler.setFormat(fmt)
-    handler.setLevel(logger.level)
-    logger.addHandler(handler)
+        if filename == 'stdout':
+            return handle_stdout(logger, fmt)
+        if filename == 'stderr':
+            return handle_stderr(logger, fmt)
+        if not os.path.exists(filename):
+            # touching the file
+            try:
+                open(filename, 'a').close()
+            except (IOError, OSError):
+                pass
+        try:
+            if rotating:
+                handler = RotatingFileHandler(
+                    filename,
+                    maxBytes=maxbytes,
+                    backupCount=backups
+                )
+            else:
+                handler = FileHandler(filename)
+            handler.setFormat(fmt)
+            handler.setLevel(logger.level)
+            logger.addHandler(handler)
+            return handler
+        except (IOError, OSError):
+            logger.error('Cannot open file %s for writing' % filename)

supervisor/options.py

@@ -456,6 +456,12 @@ def __init__(self):
         self.add(None, None, "v", "version", self.version)
         self.add("nodaemon", "supervisord.nodaemon", "n", "nodaemon", flag=1,
                  default=0)
+        self.add("logfile_format", "supervisord.logfile_format",
+                 "", "logfile_format=", str,
+                 default="%(asctime)s %(levelname)s %(message)s")
+        self.add("childlog_format", "supervisord.childlog_format",
+                 "", "childlog_format=", str,
+                 default="%(message)s")
         self.add("user", "supervisord.user", "u:", "user=")
         self.add("umask", "supervisord.umask", "m:", "umask=",
                  octal_type, default='022')
@@ -528,6 +534,31 @@ def realize(self, *arg, **kw):
             self.uid = uid
             self.gid = gid_for_uid(uid)
 
+        loglevel = self.loglevel
+        if loglevel is None:
+            loglevel = section.loglevel
+
+        logfile_format = section.logfile_format
+        childlog_format = section.childlog_format
+
+        # Configure the main logger
+        self.logger = loggers.getLogger(loglevel)
+
+        if self.logfile:
+            logfile = self.logfile
+        else:
+            logfile = section.logfile
+
+        if logfile:
+            loggers.handle_file(
+                self.logger,
+                logfile,
+                logfile_format,
+                rotating=True,
+                maxbytes=section.logfile_maxbytes,
+                backups=section.logfile_backups
+            )
+
         if not self.loglevel:
             self.loglevel = section.loglevel
 
@@ -650,6 +681,11 @@ def get(opt, default, **kwargs):
         section.pidfile = existing_dirpath(get('pidfile', 'supervisord.pid'))
         section.identifier = get('identifier', 'supervisor')
         section.nodaemon = boolean(get('nodaemon', 'false'))
+        section.logfile_format = get('logfile_format',
+                                '%(asctime)s %(levelname)s %(message)s',
+                        do_expand=False)
+        section.childlog_format = get('childlog_format', '%(message)s',
+                        do_expand=False)
         section.silent = boolean(get('silent', 'false'))
 
         tempdir = tempfile.gettempdir()

supervisor/skel/sample.conf

@@ -46,6 +46,17 @@ logfile=/tmp/supervisord.log ; main log file; default $CWD/supervisord.log
 logfile_maxbytes=50MB        ; max main logfile bytes b4 rotation; default 50MB
 logfile_backups=10           ; # of main logfile backups; 0 means none, default 10
 loglevel=info                ; log level; default info; others: debug,warn,trace
+
+; Main supervisord log file format
+; Format string for main log file - uses standard Python logging format strings
+; Default: %(asctime)s %(levelname)s %(message)s
+;logfile_format=%(asctime)s %(levelname)s %(message)s
+
+; Child process log file format
+; Format string for child process logs - uses standard Python logging format strings
+; Default: %(message)s
+;childlog_format=%(message)s
+
 pidfile=/tmp/supervisord.pid ; supervisord pidfile; default supervisord.pid
 nodaemon=false               ; start in foreground if true; default false
 silent=false                 ; no logs to stdout if true; default false

supervisor/tests/base.py

@@ -89,6 +89,7 @@ def __init__(self):
         self.umaskset = None
         self.poller = DummyPoller(self)
         self.silent = False
+        self.childlog_format = '%(message)s'
 
     def getLogger(self, *args, **kw):
         logger = DummyLogger()

supervisor/tests/test_dispatchers.py

@@ -569,6 +569,47 @@ def test_close(self):
         dispatcher.close() # make sure we don't error if we try to close twice
         self.assertEqual(dispatcher.closed, True)
 
+    def test_custom_format_for_process_logs(self):
+        """Test custom format is applied to process logs"""
+        from supervisor.datatypes import boolean, logfile_name
+        from supervisor.options import ServerOptions
+        options = ServerOptions()  # need real options to get a real logger
+        options.childlog_format = '%(asctime)s [%(levelname)s] %(message)s'
+
+        config = DummyPConfig(options, 'process1', '/bin/process1',
+                            stdout_logfile=logfile_name('/tmp/foo'))
+        process = DummyProcess(config)
+        dispatcher = self._makeOne(process)
+
+        # Check that format is passed to logger
+        self.assertEqual(dispatcher.childlog.handlers[0].fmt,
+                    '%(asctime)s [%(levelname)s] %(message)s')
+
+    def test_different_formats_for_main_and_child_logs(self):
+        """Test different formats for main and child logs"""
+        from supervisor.datatypes import boolean, logfile_name
+        from supervisor.options import ServerOptions
+        options = ServerOptions()
+        options.logfile_format = '%(asctime)s MAIN: %(message)s'
+        options.childlog_format = '%(asctime)s CHILD: %(message)s'
+
+        # Configure child process logs
+        config = DummyPConfig(options, 'process1', '/bin/process1',
+                            stdout_logfile=logfile_name('/tmp/foo'))
+        process = DummyProcess(config)
+        dispatcher = self._makeOne(process)
+
+        # Check that child format is used
+        self.assertEqual(dispatcher.childlog.handlers[0].fmt,
+                    '%(asctime)s CHILD: %(message)s')
+
+        # Configure a main log
+        from supervisor.loggers import getLogger
+        logger = getLogger(fmt=options.logfile_format)
+
+        # Check that main format is used
+        self.assertEqual(logger.handlers[0].fmt,
+                    '%(asctime)s MAIN: %(message)s')
 
 class PInputDispatcherTests(unittest.TestCase):
     def _getTargetClass(self):