diff --git a/supervisor/dispatchers.py b/supervisor/dispatchers.py index f0e17104c..6716551cd 100644 --- a/supervisor/dispatchers.py +++ b/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 diff --git a/supervisor/loggers.py b/supervisor/loggers.py index 44d14b44c..d4567c1f8 100644 --- a/supervisor/loggers.py +++ b/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) diff --git a/supervisor/options.py b/supervisor/options.py index 7b53cc760..0aa4b2b77 100644 --- a/supervisor/options.py +++ b/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 diff --git a/supervisor/skel/sample.conf b/supervisor/skel/sample.conf index 289c9cb38..d046cb545 100644 --- a/supervisor/skel/sample.conf +++ b/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) diff --git a/supervisor/tests/base.py b/supervisor/tests/base.py index bef82e964..388b23fdc 100644 --- a/supervisor/tests/base.py +++ b/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 diff --git a/supervisor/tests/test_dispatchers.py b/supervisor/tests/test_dispatchers.py index 87692e21f..9d8ce7ac1 100644 --- a/supervisor/tests/test_dispatchers.py +++ b/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): diff --git a/supervisor/tests/test_options.py b/supervisor/tests/test_options.py index 5c9a35f6d..a395349c6 100644 --- a/supervisor/tests/test_options.py +++ b/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)