Option to prepend timestamp to stdout and stderr log file with config. Resolves #553

supervisor/dispatchers.py

@@ -126,6 +126,16 @@ 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)
+        prepend_timestamp = getattr(config, '%s_prepend_timestamp' % channel)
+        prepend_timestamp_format = getattr(config, '%s_prepend_timestamp_format' % channel)
+
+        formatter = '%(message)s'
+
+        if prepend_timestamp and not prepend_timestamp_format:
+            formatter = '%(asctime)s %(message)s'
+
+        if prepend_timestamp and prepend_timestamp_format:
+            formatter = '%(custime)s %(message)s'
 
         if logfile or to_syslog:
             self.normallog = config.options.getLogger()
@@ -134,7 +144,8 @@ def _init_normallog(self):
             loggers.handle_file(
                 self.normallog,
                 filename=logfile,
-                fmt='%(message)s',
+                fmt=formatter,
+                datefmt=prepend_timestamp_format,
                 rotating=not not maxbytes, # optimization
                 maxbytes=maxbytes,
                 backups=backups

supervisor/loggers.py

@@ -51,6 +51,7 @@ def getLevelNumByDescription(description):
 
 class Handler:
     fmt = '%(message)s'
+    datefmt = ""
     level = LevelsByName.INFO
 
     def __init__(self, stream=None):
@@ -60,6 +61,9 @@ def __init__(self, stream=None):
     def setFormat(self, fmt):
         self.fmt = fmt
 
+    def setDateFormat(self, datefmt):
+        self.datefmt = datefmt
+
     def setLevel(self, level):
         self.level = level
 
@@ -95,7 +99,10 @@ def emit(self, record):
             if binary:
                 msg = record.msg
             else:
-                msg = self.fmt % record.asdict()
+                if isinstance(self, FileHandler) and self.datefmt is not None:
+                    msg = self.fmt % record.asdict(self.datefmt)
+                else:
+                    msg = self.fmt % record.asdict()
                 if binary_stream:
                     msg = msg.encode('utf-8')
             try:
@@ -282,7 +289,7 @@ def __init__(self, level, msg, **kw):
         self.kw = kw
         self.dictrepr = None
 
-    def asdict(self):
+    def asdict(self, datefmt=None):
         if self.dictrepr is None:
             now = time.time()
             msecs = (now - long(now)) * 1000
@@ -294,13 +301,16 @@ def asdict(self):
                 msg = msg % self.kw
             self.dictrepr = {'message':msg, 'levelname':levelname,
                              'asctime':asctime}
+            if datefmt:
+                self.dictrepr['custime'] = time.strftime(datefmt, time.localtime(now))
         return self.dictrepr
 
 class Logger:
-    def __init__(self, level=None, handlers=None):
+    def __init__(self, level=None, handlers=None, datefmt=None):
         if level is None:
             level = LevelsByName.INFO
         self.level = level
+        self.datefmt = datefmt
 
         if handlers is None:
             handlers = []
@@ -407,7 +417,7 @@ def handle_syslog(logger, fmt):
     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, datefmt=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 +427,8 @@ def handle_file(logger, filename, fmt, rotating=False, maxbytes=0, backups=0):
             handler = FileHandler(filename)
         else:
             handler = RotatingFileHandler(filename, 'a', maxbytes, backups)
+    if datefmt:
+        handler.setDateFormat(datefmt)
     handler.setFormat(fmt)
     handler.setLevel(logger.level)
     logger.addHandler(handler)

supervisor/options.py

@@ -996,6 +996,14 @@ def get(section, opt, *args, **kwargs):
                 syslog = boolean(get(section, sy_key, False))
                 logfiles[sy_key] = syslog
 
+                prepend_ts_key = '%s_prepend_timestamp' % k
+                prepend_ts = boolean(get(section, prepend_ts_key, False))
+                logfiles[prepend_ts_key] = prepend_ts
+
+                prepend_ts_fmt_key = '%s_prepend_timestamp_format' % k
+                prepend_ts_fmt = get(section, prepend_ts_fmt_key, "%%Y-%%m-%%d %%H:%%M:%%S")
+                logfiles[prepend_ts_fmt_key] = prepend_ts_fmt
+
                 # rewrite deprecated "syslog" magic logfile into the equivalent
                 # TODO remove this in a future version
                 if lf_val is Syslog:
@@ -1039,12 +1047,16 @@ def get(section, opt, *args, **kwargs):
                 startretries=startretries,
                 uid=uid,
                 stdout_logfile=logfiles['stdout_logfile'],
+                stdout_prepend_timestamp = logfiles['stdout_prepend_timestamp'],
+                stdout_prepend_timestamp_format = logfiles['stdout_prepend_timestamp_format'],
                 stdout_capture_maxbytes = stdout_cmaxbytes,
                 stdout_events_enabled = stdout_events,
                 stdout_logfile_backups=logfiles['stdout_logfile_backups'],
                 stdout_logfile_maxbytes=logfiles['stdout_logfile_maxbytes'],
                 stdout_syslog=logfiles['stdout_syslog'],
                 stderr_logfile=logfiles['stderr_logfile'],
+                stderr_prepend_timestamp = logfiles['stderr_prepend_timestamp'],
+                stderr_prepend_timestamp_format = logfiles['stderr_prepend_timestamp_format'],
                 stderr_capture_maxbytes = stderr_cmaxbytes,
                 stderr_events_enabled = stderr_events,
                 stderr_logfile_backups=logfiles['stderr_logfile_backups'],
@@ -1875,7 +1887,8 @@ class ProcessConfig(Config):
         'stderr_events_enabled', 'stderr_syslog',
         'stopsignal', 'stopwaitsecs', 'stopasgroup', 'killasgroup',
         'exitcodes', 'redirect_stderr' ]
-    optional_param_names = [ 'environment', 'serverurl' ]
+    optional_param_names = ['environment', 'serverurl', 'stdout_prepend_timestamp', 'stdout_prepend_timestamp_format',
+                            'stderr_prepend_timestamp', 'stderr_prepend_timestamp_format']
 
     def __init__(self, options, **params):
         self.options = options

supervisor/skel/sample.conf

@@ -105,12 +105,16 @@ serverurl=unix:///tmp/supervisor.sock ; use a unix:// URL  for a unix socket
 ;stdout_logfile_maxbytes=1MB   ; max # logfile bytes b4 rotation (default 50MB)
 ;stdout_logfile_backups=10     ; # of stdout logfile backups (0 means none, default 10)
 ;stdout_capture_maxbytes=1MB   ; number of bytes in 'capturemode' (default 0)
+;stdout_prepend_timestamp=true ; prepend timestamp to stdout log file (default false)
+;stdout_prepend_timestamp_format=%%Y-%%m-%%d %%H:%%M:%%S; customise prepend timestamp to stdout log file (default %%Y-%%m-%%d %%H:%%M:%%S)
 ;stdout_events_enabled=false   ; emit events on stdout writes (default false)
 ;stdout_syslog=false           ; send stdout to syslog with process name (default false)
 ;stderr_logfile=/a/path        ; stderr log path, NONE for none; default AUTO
 ;stderr_logfile_maxbytes=1MB   ; max # logfile bytes b4 rotation (default 50MB)
 ;stderr_logfile_backups=10     ; # of stderr logfile backups (0 means none, default 10)
 ;stderr_capture_maxbytes=1MB   ; number of bytes in 'capturemode' (default 0)
+;stderr_prepend_timestamp=true ; prepend timestamp to stderr log file (default false)
+;stderr_prepend_timestamp_format=%%Y-%%m-%%d %%H:%%M:%%S; customise prepend timestamp to stderr log file (default %%Y-%%m-%%d %%H:%%M:%%S)
 ;stderr_events_enabled=false   ; emit events on stderr writes (default false)
 ;stderr_syslog=false           ; send stderr to syslog with process name (default false)
 ;environment=A="1",B="2"       ; process environment additions (def no adds)

supervisor/tests/base.py

@@ -516,6 +516,8 @@ def __init__(self, options, name, command, directory=None, umask=None,
                  stdout_syslog=False,
                  stderr_logfile=None, stderr_capture_maxbytes=0,
                  stderr_events_enabled=False,
+                 stdout_prepend_timestamp=False, stderr_prepend_timestamp=False,
+                 stdout_prepend_timestamp_format=None, stderr_prepend_timestamp_format=None,
                  stderr_logfile_backups=0, stderr_logfile_maxbytes=0,
                  stderr_syslog=False,
                  redirect_stderr=False,
@@ -543,6 +545,10 @@ def __init__(self, options, name, command, directory=None, umask=None,
         self.stderr_logfile_maxbytes = stderr_logfile_maxbytes
         self.stderr_syslog = stderr_syslog
         self.redirect_stderr = redirect_stderr
+        self.stdout_prepend_timestamp = stdout_prepend_timestamp
+        self.stdout_prepend_timestamp_format = stdout_prepend_timestamp_format
+        self.stderr_prepend_timestamp = stderr_prepend_timestamp
+        self.stderr_prepend_timestamp_format = stderr_prepend_timestamp_format
         if stopsignal is None:
             import signal
             stopsignal = signal.SIGTERM

supervisor/tests/test_dispatchers.py

@@ -570,6 +570,158 @@ 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_stdout_prepend_timestamp(self):
+        import time
+        from supervisor import loggers
+        from supervisor.loggers import getLogger
+
+        options = DummyOptions()
+        options.getLogger = getLogger  # actually use real logger
+        options.loglevel = loggers.LevelsByName.TRAC
+
+        logfile = '/tmp/foo'
+        message = "testing prepand"
+        config = DummyPConfig(options, 'process1', '/bin/process1',
+                              stdout_logfile=logfile, stdout_prepend_timestamp=True)
+        process = DummyProcess(config)
+
+        dispatcher = self._makeOne(process)
+        dispatcher.removelogs()
+        dispatcher.output_buffer = message
+        dispatcher.record_output()
+
+        # flush out the log into log files
+        [x.flush() for x in dispatcher.childlog.handlers]
+
+        # logger will prefix the stdout log with the timestamp down to milliseconds
+        # but not feasible to test to that resolution
+        timestamp_prefix = time.strftime("%Y-%m-%d %H:%M:%S")
+
+        with open(logfile, 'rb') as f:
+            content = f.read()
+            # check if the timestamp is prepended to the log
+            self.assertEqual(timestamp_prefix.encode(), content[0:len(timestamp_prefix)])
+            # check if the message is at the end of the log line
+            self.assertEqual(message.encode(), content[-len(message):])
+
+        dispatcher.childlog.close()
+        dispatcher.close()
+
+    def test_stdout_prepend_timestamp_format(self):
+        import time
+        from supervisor import loggers
+        from supervisor.loggers import getLogger
+
+        options = DummyOptions()
+        options.getLogger = getLogger  # actually use real logger
+        options.loglevel = loggers.LevelsByName.TRAC
+
+        logfile = '/tmp/foo'
+        message = "testing prepand"
+        config = DummyPConfig(options, 'process1', '/bin/process1',
+                              stdout_logfile=logfile, stdout_prepend_timestamp=True,
+                              stdout_prepend_timestamp_format="%H:%M:%S")
+        process = DummyProcess(config)
+
+        dispatcher = self._makeOne(process)
+        dispatcher.removelogs()
+        dispatcher.output_buffer = message
+        dispatcher.record_output()
+
+        # flush out the log into log files
+        [x.flush() for x in dispatcher.childlog.handlers]
+
+        # logger will prefix the stdout log with the timestamp down to milliseconds
+        # but not feasible to test to that resolution
+        timestamp_prefix = time.strftime("%H:%M:%S")
+
+        with open(logfile, 'rb') as f:
+            content = f.read()
+            # check if the timestamp is prepended to the log
+            self.assertEqual(timestamp_prefix.encode(), content[0:len(timestamp_prefix)])
+            # check if the message is at the end of the log line
+            self.assertEqual(message.encode(), content[-len(message):])
+
+        dispatcher.childlog.close()
+        dispatcher.close()
+
+    def test_stderr_prepend_timestamp(self):
+        import time
+        from supervisor import loggers
+        from supervisor.loggers import getLogger
+
+        options = DummyOptions()
+        options.getLogger = getLogger  # actually use real logger
+        options.loglevel = loggers.LevelsByName.TRAC
+
+        logfile = '/tmp/foo'
+        message = "testing prepand"
+        config = DummyPConfig(options, 'process1', '/bin/process1',
+                              stderr_logfile=logfile, stderr_prepend_timestamp=True)
+        process = DummyProcess(config)
+
+        dispatcher = self._makeOne(process, channel='stderr')
+        dispatcher.output_buffer = message
+        dispatcher.removelogs()
+        dispatcher.record_output()
+
+        # flush out the log into log files
+        [x.flush() for x in dispatcher.childlog.handlers]
+
+        # logger will prefix the stdout log with the timestamp down to milliseconds
+        # but not feasible to test to that resolution
+        timestamp_prefix = time.strftime("%Y-%m-%d %H:%M:%S")
+
+        with open(logfile, 'rb') as f:
+            content = f.read()
+            # check if the timestamp is prepended to the log
+            self.assertEqual(timestamp_prefix.encode(), content[0:len(timestamp_prefix)])
+            # check if the message is at the end of the log line
+            self.assertEqual(message.encode(), content[-len(message):])
+
+        dispatcher.childlog.close()
+        dispatcher.close()
+
+    def test_stderr_prepend_timestamp_format(self):
+        import time
+        from supervisor import loggers
+        from supervisor.loggers import getLogger
+
+        options = DummyOptions()
+        options.getLogger = getLogger  # actually use real logger
+        options.loglevel = loggers.LevelsByName.TRAC
+
+        logfile = '/tmp/foo'
+        message = "testing prepand"
+        config = DummyPConfig(options, 'process1', '/bin/process1',
+                              stderr_logfile=logfile, stderr_prepend_timestamp=True,
+                              stderr_prepend_timestamp_format="%H:%M:%S")
+        process = DummyProcess(config)
+
+        dispatcher = self._makeOne(process, channel='stderr')
+        dispatcher.output_buffer = message
+        dispatcher.removelogs()
+        dispatcher.record_output()
+
+        # flush out the log into log files
+        [x.flush() for x in dispatcher.childlog.handlers]
+
+        # logger will prefix the stdout log with the timestamp down to milliseconds
+        # but not feasible to test to that resolution
+        timestamp_prefix = time.strftime("%H:%M:%S")
+
+        with open(logfile, 'rb') as f:
+            content = f.read()
+            # check if the timestamp is prepended to the log
+            self.assertEqual(timestamp_prefix.encode(), content[0:len(timestamp_prefix)])
+            # check if the message is at the end of the log line
+            self.assertEqual(message.encode(), content[-len(message):])
+
+        dispatcher.childlog.close()
+        dispatcher.close()
+
+
+
 
 class PInputDispatcherTests(unittest.TestCase):
     def _getTargetClass(self):

supervisor/tests/test_options.py

@@ -486,6 +486,8 @@ def test_options(self):
         autostart=true
         user=root
         stdout_logfile=/tmp/cat.log
+        stdout_prepend_timestamp=true
+        stderr_prepend_timestamp=false
         stopsignal=KILL
         stopwaitsecs=5
         startsecs=5
@@ -573,6 +575,8 @@ def test_options(self):
         self.assertEqual(proc1.startretries, 10)
         self.assertEqual(proc1.uid, 0)
         self.assertEqual(proc1.stdout_logfile, '/tmp/cat.log')
+        self.assertEqual(proc1.stdout_prepend_timestamp, True)
+        self.assertEqual(proc1.stderr_prepend_timestamp, False)
         self.assertEqual(proc1.stopsignal, signal.SIGKILL)
         self.assertEqual(proc1.stopwaitsecs, 5)
         self.assertEqual(proc1.stopasgroup, False)
@@ -598,6 +602,8 @@ def test_options(self):
         self.assertEqual(proc2.autorestart, False)
         self.assertEqual(proc2.uid, None)
         self.assertEqual(proc2.stdout_logfile, '/tmp/cat2.log')
+        self.assertEqual(proc2.stdout_prepend_timestamp, False)
+        self.assertEqual(proc2.stderr_prepend_timestamp, False)
         self.assertEqual(proc2.stopsignal, signal.SIGTERM)
         self.assertEqual(proc2.stopasgroup, False)
         self.assertEqual(proc2.killasgroup, False)