From 7736ff23a73b0f6aa12c903718679112efd0159f Mon Sep 17 00:00:00 2001 From: the-c0d3r <4526565+the-c0d3r@users.noreply.github.com> Date: Sun, 7 Feb 2021 21:08:35 +0800 Subject: [PATCH 1/9] Added stdout_prepand_timestamp, stderr_prepand_timestamp. --- supervisor/dispatchers.py | 16 +++++++++++++--- supervisor/options.py | 8 +++++++- supervisor/skel/sample.conf | 2 ++ 3 files changed, 22 insertions(+), 4 deletions(-) diff --git a/supervisor/dispatchers.py b/supervisor/dispatchers.py index f0e17104c..681a0cab6 100644 --- a/supervisor/dispatchers.py +++ b/supervisor/dispatchers.py @@ -126,6 +126,11 @@ 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) + + formatter = '%(message)s' + if prepend_timestamp: + formatter = '%(asctime)s: %(message)s' if logfile or to_syslog: self.normallog = config.options.getLogger() @@ -134,7 +139,7 @@ def _init_normallog(self): loggers.handle_file( self.normallog, filename=logfile, - fmt='%(message)s', + fmt=formatter, rotating=not not maxbytes, # optimization maxbytes=maxbytes, backups=backups @@ -310,11 +315,17 @@ def __init__(self, process, channel, fd): if logfile: maxbytes = getattr(process.config, '%s_logfile_maxbytes' % channel) backups = getattr(process.config, '%s_logfile_backups' % channel) + prepend_timestamp = getattr(process.config, '%s_prepend_timestamp' % channel) + + formatter = '%(message)s' + if prepend_timestamp: + formatter = '%(asctime)s %(message)s' + self.childlog = process.config.options.getLogger() loggers.handle_file( self.childlog, logfile, - '%(message)s', + formatter, rotating=not not maxbytes, # optimization maxbytes=maxbytes, backups=backups, @@ -331,7 +342,6 @@ def reopenlogs(self): for handler in self.childlog.handlers: handler.reopen() - def writable(self): return False diff --git a/supervisor/options.py b/supervisor/options.py index 273d8a5d0..0ffabe5c8 100644 --- a/supervisor/options.py +++ b/supervisor/options.py @@ -987,6 +987,10 @@ 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 + # rewrite deprecated "syslog" magic logfile into the equivalent # TODO remove this in a future version if lf_val is Syslog: @@ -1030,12 +1034,14 @@ def get(section, opt, *args, **kwargs): startretries=startretries, uid=uid, stdout_logfile=logfiles['stdout_logfile'], + stdout_prepend_timestamp = logfiles['stdout_prepend_timestamp'], 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_capture_maxbytes = stderr_cmaxbytes, stderr_events_enabled = stderr_events, stderr_logfile_backups=logfiles['stderr_logfile_backups'], @@ -1869,7 +1875,7 @@ 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', 'stderr_prepend_timestamp' ] def __init__(self, options, **params): self.options = options diff --git a/supervisor/skel/sample.conf b/supervisor/skel/sample.conf index 289c9cb38..a4498fd46 100644 --- a/supervisor/skel/sample.conf +++ b/supervisor/skel/sample.conf @@ -105,12 +105,14 @@ 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_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_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) From 906e6f895485194e9b9b42ac6af2ebd0fae5f593 Mon Sep 17 00:00:00 2001 From: the-c0d3r <4526565+the-c0d3r@users.noreply.github.com> Date: Sun, 7 Feb 2021 21:09:08 +0800 Subject: [PATCH 2/9] Added test for stdout_prepand_timestamp and stderr_prepand_timestamp. --- supervisor/tests/base.py | 3 +++ supervisor/tests/test_options.py | 6 ++++++ 2 files changed, 9 insertions(+) diff --git a/supervisor/tests/base.py b/supervisor/tests/base.py index b4ec8149b..413fbbe66 100644 --- a/supervisor/tests/base.py +++ b/supervisor/tests/base.py @@ -520,6 +520,7 @@ 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, stderr_logfile_backups=0, stderr_logfile_maxbytes=0, stderr_syslog=False, redirect_stderr=False, @@ -547,6 +548,8 @@ 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.stderr_prepend_timestamp = stderr_prepend_timestamp if stopsignal is None: import signal stopsignal = signal.SIGTERM diff --git a/supervisor/tests/test_options.py b/supervisor/tests/test_options.py index 70935b952..e5e10a626 100644 --- a/supervisor/tests/test_options.py +++ b/supervisor/tests/test_options.py @@ -484,6 +484,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 @@ -571,6 +573,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) @@ -596,6 +600,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) From 68580b67f9b79426efef173d8458022267ff993e Mon Sep 17 00:00:00 2001 From: the-c0d3r <4526565+the-c0d3r@users.noreply.github.com> Date: Sun, 7 Feb 2021 21:09:39 +0800 Subject: [PATCH 3/9] WIP test for POutputDispatcher.test_stdout_prepend_timestamp. --- supervisor/tests/test_dispatchers.py | 19 +++++++++++++++++++ 1 file changed, 19 insertions(+) diff --git a/supervisor/tests/test_dispatchers.py b/supervisor/tests/test_dispatchers.py index 5d8f0b047..e0070ecd5 100644 --- a/supervisor/tests/test_dispatchers.py +++ b/supervisor/tests/test_dispatchers.py @@ -570,6 +570,25 @@ 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): + 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' + config = DummyPConfig(options, 'process1', '/bin/process1', + stdout_logfile=logfile, stdout_prepend_timestamp=True) + process = DummyProcess(config) + dispatcher = self._makeOne(process) + dispatcher.output_buffer = 'a' + dispatcher.record_output() + + [x.flush() for x in dispatcher.childlog.handlers] + with open(logfile, 'rb') as f: + self.assertEqual(b'testing stdout prepend timestamp', f.read()) class PInputDispatcherTests(unittest.TestCase): def _getTargetClass(self): From 7341d4586cd0641a7ba600a88c81716c4973be7f Mon Sep 17 00:00:00 2001 From: the-c0d3r <4526565+the-c0d3r@users.noreply.github.com> Date: Mon, 8 Feb 2021 21:12:34 +0800 Subject: [PATCH 4/9] Removed the formatter at PEventListenerDispatcher --- supervisor/dispatchers.py | 9 ++------- 1 file changed, 2 insertions(+), 7 deletions(-) diff --git a/supervisor/dispatchers.py b/supervisor/dispatchers.py index 681a0cab6..c1fb04884 100644 --- a/supervisor/dispatchers.py +++ b/supervisor/dispatchers.py @@ -315,17 +315,11 @@ def __init__(self, process, channel, fd): if logfile: maxbytes = getattr(process.config, '%s_logfile_maxbytes' % channel) backups = getattr(process.config, '%s_logfile_backups' % channel) - prepend_timestamp = getattr(process.config, '%s_prepend_timestamp' % channel) - - formatter = '%(message)s' - if prepend_timestamp: - formatter = '%(asctime)s %(message)s' - self.childlog = process.config.options.getLogger() loggers.handle_file( self.childlog, logfile, - formatter, + '%(message)s', rotating=not not maxbytes, # optimization maxbytes=maxbytes, backups=backups, @@ -342,6 +336,7 @@ def reopenlogs(self): for handler in self.childlog.handlers: handler.reopen() + def writable(self): return False From d025e5f23e0dc04fcf94a46dfb52e021a4cea733 Mon Sep 17 00:00:00 2001 From: the-c0d3r <4526565+the-c0d3r@users.noreply.github.com> Date: Mon, 8 Feb 2021 21:54:49 +0800 Subject: [PATCH 5/9] Fixed test_stdout_prepend_timestamp and added test_stderr_prepend_timestamp. The tests are leaking open file descriptors, not sure why calling dispatcher.close() doesn't close them. --- supervisor/tests/test_dispatchers.py | 59 ++++++++++++++++++++++++++-- 1 file changed, 56 insertions(+), 3 deletions(-) diff --git a/supervisor/tests/test_dispatchers.py b/supervisor/tests/test_dispatchers.py index e0070ecd5..8674aa346 100644 --- a/supervisor/tests/test_dispatchers.py +++ b/supervisor/tests/test_dispatchers.py @@ -571,24 +571,77 @@ def test_close(self): 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.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.output_buffer = 'a' + 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: - self.assertEqual(b'testing stdout prepend timestamp', f.read()) + 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.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.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.close() + dispatcher.removelogs() class PInputDispatcherTests(unittest.TestCase): def _getTargetClass(self): From 5890a645a1762daaad064d1bc77562aae3409e74 Mon Sep 17 00:00:00 2001 From: the-c0d3r <4526565+the-c0d3r@users.noreply.github.com> Date: Mon, 8 Feb 2021 22:11:29 +0800 Subject: [PATCH 6/9] Fixed leaking open file descriptors. --- supervisor/tests/test_dispatchers.py | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-) diff --git a/supervisor/tests/test_dispatchers.py b/supervisor/tests/test_dispatchers.py index 8674aa346..6e513804b 100644 --- a/supervisor/tests/test_dispatchers.py +++ b/supervisor/tests/test_dispatchers.py @@ -604,6 +604,7 @@ def test_stdout_prepend_timestamp(self): # 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): @@ -622,8 +623,8 @@ def test_stderr_prepend_timestamp(self): process = DummyProcess(config) dispatcher = self._makeOne(process, channel='stderr') - dispatcher.removelogs() dispatcher.output_buffer = message + dispatcher.removelogs() dispatcher.record_output() # flush out the log into log files @@ -640,8 +641,8 @@ def test_stderr_prepend_timestamp(self): # check if the message is at the end of the log line self.assertEqual(message.encode(), content[-len(message):]) + dispatcher.childlog.close() dispatcher.close() - dispatcher.removelogs() class PInputDispatcherTests(unittest.TestCase): def _getTargetClass(self): From 87518d3376e66ee59c38bb9026b61ec073f679e0 Mon Sep 17 00:00:00 2001 From: the-c0d3r <4526565+the-c0d3r@users.noreply.github.com> Date: Tue, 22 Mar 2022 20:13:06 +0800 Subject: [PATCH 7/9] Added support for customised timestamp format from config file. Created new format variable "custime" for customised timestamp format. --- supervisor/dispatchers.py | 10 +++- supervisor/loggers.py | 20 +++++-- supervisor/options.py | 9 +++- supervisor/skel/sample.conf | 4 +- supervisor/tests/base.py | 3 ++ supervisor/tests/test_dispatchers.py | 79 ++++++++++++++++++++++++++++ 6 files changed, 117 insertions(+), 8 deletions(-) diff --git a/supervisor/dispatchers.py b/supervisor/dispatchers.py index c1fb04884..6716551cd 100644 --- a/supervisor/dispatchers.py +++ b/supervisor/dispatchers.py @@ -127,10 +127,15 @@ def _init_normallog(self): 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: - formatter = '%(asctime)s: %(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() @@ -140,6 +145,7 @@ def _init_normallog(self): self.normallog, filename=logfile, 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 12d676128..0aa4b2b77 100644 --- a/supervisor/options.py +++ b/supervisor/options.py @@ -1000,6 +1000,10 @@ def get(section, opt, *args, **kwargs): 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: @@ -1044,6 +1048,7 @@ def get(section, opt, *args, **kwargs): 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'], @@ -1051,6 +1056,7 @@ def get(section, opt, *args, **kwargs): 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'], @@ -1881,7 +1887,8 @@ class ProcessConfig(Config): 'stderr_events_enabled', 'stderr_syslog', 'stopsignal', 'stopwaitsecs', 'stopasgroup', 'killasgroup', 'exitcodes', 'redirect_stderr' ] - optional_param_names = [ 'environment', 'serverurl', 'stdout_prepend_timestamp', 'stderr_prepend_timestamp' ] + 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 a4498fd46..4deeeac76 100644 --- a/supervisor/skel/sample.conf +++ b/supervisor/skel/sample.conf @@ -105,7 +105,8 @@ 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=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 false) ;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 @@ -113,6 +114,7 @@ serverurl=unix:///tmp/supervisor.sock ; use a unix:// URL for a unix socket ;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 stdout log file (default false) ;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 5e8630bcc..388b23fdc 100644 --- a/supervisor/tests/base.py +++ b/supervisor/tests/base.py @@ -517,6 +517,7 @@ def __init__(self, options, name, command, directory=None, umask=None, 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, @@ -545,7 +546,9 @@ def __init__(self, options, name, command, directory=None, umask=None, 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 a3b515922..9d8ce7ac1 100644 --- a/supervisor/tests/test_dispatchers.py +++ b/supervisor/tests/test_dispatchers.py @@ -607,6 +607,44 @@ def test_stdout_prepend_timestamp(self): 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 @@ -644,6 +682,47 @@ def test_stderr_prepend_timestamp(self): 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): from supervisor.dispatchers import PInputDispatcher From 7b1442d87ee95c2f5a93becd5c5b656d8220958b Mon Sep 17 00:00:00 2001 From: the-c0d3r <4526565+the-c0d3r@users.noreply.github.com> Date: Tue, 22 Mar 2022 20:20:16 +0800 Subject: [PATCH 8/9] sample.conf: removed the unnecessary double quotes for the timestamp format. --- supervisor/skel/sample.conf | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/supervisor/skel/sample.conf b/supervisor/skel/sample.conf index 4deeeac76..cb5983c00 100644 --- a/supervisor/skel/sample.conf +++ b/supervisor/skel/sample.conf @@ -106,7 +106,7 @@ serverurl=unix:///tmp/supervisor.sock ; use a unix:// URL for a unix socket ;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 false) +;stdout_prepend_timestamp_format=%%Y-%%m-%%d %%H:%%M:%%S; customise prepend timestamp to stdout log file (default false) ;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 @@ -114,7 +114,7 @@ serverurl=unix:///tmp/supervisor.sock ; use a unix:// URL for a unix socket ;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 stdout log file (default false) +;stderr_prepend_timestamp_format=%%Y-%%m-%%d %%H:%%M:%%S; customise prepend timestamp to stdout log file (default false) ;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) From d213e28d7428b11ed86731da5c12a96f66a75360 Mon Sep 17 00:00:00 2001 From: the-c0d3r <4526565+the-c0d3r@users.noreply.github.com> Date: Tue, 22 Mar 2022 20:24:47 +0800 Subject: [PATCH 9/9] sample.conf: corrected the sample config default value for the timestamp format. --- supervisor/skel/sample.conf | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/supervisor/skel/sample.conf b/supervisor/skel/sample.conf index cb5983c00..d046cb545 100644 --- a/supervisor/skel/sample.conf +++ b/supervisor/skel/sample.conf @@ -106,7 +106,7 @@ serverurl=unix:///tmp/supervisor.sock ; use a unix:// URL for a unix socket ;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 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 @@ -114,7 +114,7 @@ serverurl=unix:///tmp/supervisor.sock ; use a unix:// URL for a unix socket ;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 stdout 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)