feat(logging): add customizable log formats for main and child logs

Author: Morteza Ghasempour

.vscode/settings.json

@@ -0,0 +1,11 @@
+{
+    "python.testing.unittestArgs": [
+        "-v",
+        "-s",
+        ".",
+        "-p",
+        "test_*.py"
+    ],
+    "python.testing.pytestEnabled": false,
+    "python.testing.unittestEnabled": true
+}

supervisor/dispatchers.py

@@ -126,19 +126,21 @@ def _init_normallog(self):
             self.normallog = config.options.getLogger()
 
         if logfile:
+            fmt = config.options.childlog_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:
+            fmt = config.name + ' ' + config.options.childlog_format
             loggers.handle_syslog(
                 self.normallog,
-                fmt=config.name + ' %(message)s'
+                fmt=fmt
             )
 
     def _init_capturelog(self):

supervisor/loggers.py

@@ -292,8 +292,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:
@@ -413,10 +422,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,26 @@ 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 logfile:
+            loggers.handle_file(
+                self.logger,
+                self.logfile,
+                logfile_format,
+                rotating=True,
+                maxbytes=section.logfile_maxbytes,
+                backups=section.logfile_backups
+            )
+
         if not self.loglevel:
             self.loglevel = section.loglevel
 
@@ -650,6 +676,9 @@ 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')
+        section.childlog_format = get('childlog_format', '%(message)s')
         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/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):

supervisor/tests/test_loggers.py

@@ -221,6 +221,32 @@ def test_emit_error(self):
         self.assertTrue(dummy_stderr.written.endswith(b'OSError\n'),
                         dummy_stderr.written)
 
+    def test_format_applied_to_handler(self):
+        """Test that the format is correctly applied to the handler"""
+        from supervisor.loggers import FileHandler
+        custom_format = '%(asctime)s [%(levelname)s] %(message)s'
+        handler = FileHandler(self.filename, fmt=custom_format)
+        record = self._makeLogRecord("test message")
+        handler.emit(record)
+        handler.close()
+        with open(self.filename, 'r') as f:
+            content = f.read()
+        # Check that the format was applied - should have timestamp and level
+        import re
+        self.assertTrue(re.match(r'\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2},\d{3} \[INFO\] test message', content))
+
+    def test_default_format_when_not_specified(self):
+        """Test default format when no format is specified"""
+        from supervisor.loggers import FileHandler
+        handler = FileHandler(self.filename)  # No format specified
+        record = self._makeLogRecord("test message")
+        handler.emit(record)
+        handler.close()
+        with open(self.filename, 'r') as f:
+            content = f.read()
+        # Should just contain the message itself
+        self.assertEqual(content, "test message")
+
 if os.path.exists('/dev/stdout'):
     StdoutTestsBase = FileHandlerTests
 else:

supervisor/tests/test_options.py

@@ -3409,6 +3409,28 @@ def test_daemonize_notifies_poller_before_and_after_fork(self):
         instance.poller.before_daemonize.assert_called_once_with()
         instance.poller.after_daemonize.assert_called_once_with()
 
+    def test_default_log_format_options(self):
+        """Test that default log format options are set correctly"""
+        instance = self._makeOne()
+        instance.realize(args=[])
+        options = instance.configroot.supervisord
+        self.assertEqual(options.logfile_format, '%(asctime)s %(levelname)s %(message)s')
+        self.assertEqual(options.childlog_format, '%(message)s')
+
+    def test_parse_log_format_options(self):
+        """Test parsing log format options from config"""
+        text = lstrip('''
+        [supervisord]
+        logfile=/tmp/supervisord.log
+        logfile_format=%(asctime)s [%(levelname)s] [PID:%(process)d] %(message)s
+        childlog_format=[%(asctime)s] %(message)s
+        ''')
+        instance = self._makeOne()
+        instance.configfile = StringIO(text)
+        instance.realize(args=[])
+        options = instance.configroot.supervisord
+        self.assertEqual(options.logfile_format, '%(asctime)s [%(levelname)s] [PID:%(process)d] %(message)s')
+        self.assertEqual(options.childlog_format, '[%(asctime)s] %(message)s')
 class ProcessConfigTests(unittest.TestCase):
     def _getTargetClass(self):
         from supervisor.options import ProcessConfig