Differential D375

Flush preinit log messages from mem handler into file
ClosedPublic
Actions

Authored by mkrizek on May 20 2015, 2:52 PM.

Details

Reviewers
kparal
tflink
jskladan
Maniphest Tasks
T273: capture pre-logger initialization messages
Commits
rLTRN612ad442aa09: Flush preinit log messages from mem handler into file
Test Plan

Enable file logging and see if messages prior to file logger being initialized are flushed into taskotron.log.

Diff Detail

Repository
rLTRN libtaskotron
Lint
Automatic diff as part of commit; lint not applicable.
Unit
Automatic diff as part of commit; unit tests not applicable.
mkrizek retitled this revision from to Flush preinit log messages from mem handler into file.May 20 2015, 2:52 PM
mkrizek updated this object.
mkrizek edited the test plan for this revision. (Show Details)
mkrizek added reviewers: tflink, kparal, jskladan.
tflink accepted this revision.May 22 2015, 8:07 PM
This revision is now accepted and ready to land.May 22 2015, 8:07 PM
kparal requested changes to this revision.Jun 2 2015, 3:56 PM

Hey Martin, this is awesome! I had no idea this would be so easy and that MemoryHandler is already implemented in logging. Thanks a lot for finding this out!

I've found an issue with your current patch, so I tried to fix it and add some unit tests, I hope you don't mind :-) The patch is here:
https://phab.qadevel.cloud.fedoraproject.org/differential/diff/1015/

It seems to work well, I manually tested it by editing taskotron.yaml and setting log_file_enabled and log_level_file.

In the future, I think we could even get rid of the whole method init_prior_config, and use mem_handler for forwarding to stream_handler as well, once everything is initialized. But that's not important for the moment, so if you no objections to my patch and it works for you, I think this is good to go.

libtaskotron/logger.py
131

We don't want to limit memory records to just anything above the stream level. The stream level and the file level might be different. Let's not set it at all and leave it with NOTSET, so that it contains everything.

243

I have tested this and it unfortunately forward all records to the target and the target does not filter them according to their level. If you edit taskotron.yaml and set log_level_file: INFO, you'll see that the file still contains initial DEBUG messages. So we need to do record forwarding manually.

This revision now requires changes to proceed.Jun 2 2015, 3:56 PM
Closed by commit rLTRN612ad442aa09: Flush preinit log messages from mem handler into file (authored by mkrizek). · Explain WhyJun 3 2015, 8:29 AM
This revision was automatically updated to reflect the committed changes.

Revision Contents

Diff 1017

View Options

libtaskotron/logger.py

Show First 20 Lines • Show All 47 Lines • ▼ Show 20 Line(s)
48stream_handler = None 48​stream_handler = None
49 49​
50#: our current syslog handler sending logged messages to syslog 50​#: our current syslog handler sending logged messages to syslog
51syslog_handler = None 51​syslog_handler = None
52 52​
53#: our current file handler sending logged messages to file log 53​#: our current file handler sending logged messages to file log
54file_handler = None 54​file_handler = None
55 55​
56​#: our current memory handler sending logged messages to memory
57​#: log prior to creating file log (after its creation, content
58​#: of the memory log is flushed into the file log)
59​mem_handler = None
60​
56 61​
57def _create_handlers(syslog=False, filelog_path=None): 62​def _create_handlers(syslog=False, filelog_path=None):
58 '''Create all handlers. This should be called before any method tries to 63​ '''Create all handlers. This should be called before any method tries to
59 operate on handlers. Handlers are created only if they don't exist yet 64​ operate on handlers. Handlers are created only if they don't exist yet
60 (they are `None`), otherwise they are skipped. So this method can easily be 65​ (they are `None`), otherwise they are skipped. So this method can easily be
61 called multiple times. 66​ called multiple times.
62 67​
63 Note: Handlers can't be created during module import, because that breaks 68​ Note: Handlers can't be created during module import, because that breaks
64 stream capturing functionality when running through ``pytest``. 69​ stream capturing functionality when running through ``pytest``.
65 70​
66 :param bool syslog: create syslog handler. Syslog must be available. 71​ :param bool syslog: create syslog handler. Syslog must be available.
67 :param str filelog_path: path to the log file where :data:`file_handler` 72​ :param str filelog_path: path to the log file where :data:`file_handler`
68 should emit messages. If this is ``None``, then 73​ should emit messages. If this is ``None``, then
69 :data:`file_handler` is not created. 74​ :data:`file_handler` is not created.
70 :raise socket.error: if syslog handler creation failed 75​ :raise socket.error: if syslog handler creation failed
71 ''' 76​ '''
72 global stream_handler, syslog_handler, file_handler 77​ global stream_handler, syslog_handler, file_handler, mem_handler
73 78​
74 if not stream_handler: 79​ if not stream_handler:
75 stream_handler = logging.StreamHandler() 80​ stream_handler = logging.StreamHandler()
76 stream_handler.setFormatter(_formatter_simple) 81​ stream_handler.setFormatter(_formatter_simple)
77 82​
78 if syslog and not syslog_handler: 83​ if syslog and not syslog_handler:
79 syslog_handler = logging.handlers.SysLogHandler(address='/dev/log', 84​ syslog_handler = logging.handlers.SysLogHandler(address='/dev/log',
80 facility=logging.handlers.SysLogHandler.LOG_LOCAL4) 85​ facility=logging.handlers.SysLogHandler.LOG_LOCAL4)
81 86​
82 if not file_handler and filelog_path: 87​ if not file_handler and filelog_path:
83 file_handler = logging.FileHandler(filelog_path, encoding='UTF-8') 88​ file_handler = logging.FileHandler(filelog_path, encoding='UTF-8')
84 file_handler.setFormatter(_formatter_full) 89​ file_handler.setFormatter(_formatter_full)
85 90​
91​ if not mem_handler:
92​ mem_handler = logging.handlers.MemoryHandler(capacity=1024)
93​ mem_handler.setFormatter(_formatter_full)
94​
86 95​
87def _log_excepthook(*exc_info): 96​def _log_excepthook(*exc_info):
88 '''Called when an exception is not caught''' 97​ '''Called when an exception is not caught'''
89 log.critical(''.join(traceback.format_exception(*exc_info))) 98​ log.critical(''.join(traceback.format_exception(*exc_info)))
90 99​
91 100​
92def _set_verbosity_levels(): 101​def _set_verbosity_levels():
93 '''Configure libtaskotron and other important libraries for maximum desired 102​ '''Configure libtaskotron and other important libraries for maximum desired
Show All 20 Lines122 :param int level_stream: message level of the stream logger. The level
114 definitions are in :mod:`logging`. If ``None``, the default level is 123​ definitions are in :mod:`logging`. If ``None``, the default level is
115 used (i.e. :data:`logging.NOTSET`). 124​ used (i.e. :data:`logging.NOTSET`).
116 ''' 125​ '''
117 _create_handlers() 126​ _create_handlers()
118 _set_verbosity_levels() 127​ _set_verbosity_levels()
119 128​
120 if level_stream is not None: 129​ if level_stream is not None:
121 stream_handler.setLevel(level_stream) 130​ stream_handler.setLevel(level_stream)
131​
kparalUnsubmitted
Not Done

We don't want to limit memory records to just anything above the stream level. The stream level and the file level might be different. Let's not set it at all and leave it with NOTSET, so that it contains everything.

122 rootlogger = logging.getLogger() 132​ rootlogger = logging.getLogger()
123 rootlogger.addHandler(stream_handler) 133​ rootlogger.addHandler(stream_handler)
134​ rootlogger.addHandler(mem_handler)
124 135​
125 sys.excepthook = _log_excepthook 136​ sys.excepthook = _log_excepthook
126 137​
127 138​
128def _set_level(handler, level, conf_name): 139​def _set_level(handler, level, conf_name):
129 '''Set logging level to a handler. Fall back to config defaults if the level 140​ '''Set logging level to a handler. Fall back to config defaults if the level
130 name is invalid. 141​ name is invalid.
131 142​
▲ Show 20 Lines • Show All 92 Lines • ▼ Show 20 Line(s)227 except IOError as e:
224 conf.logdir = conf.tmpdir 235​ conf.logdir = conf.tmpdir
225 conf.log_name = os.path.basename(filelog_path) 236​ conf.log_name = os.path.basename(filelog_path)
226 237​
227 global file_handler 238​ global file_handler
228 rootlogger.removeHandler(file_handler) 239​ rootlogger.removeHandler(file_handler)
229 file_handler = None 240​ file_handler = None
230 _create_handlers(filelog_path=filelog_path) 241​ _create_handlers(filelog_path=filelog_path)
231 _set_level(file_handler, level_file, "log_level_file") 242​ _set_level(file_handler, level_file, "log_level_file")
243​
kparalUnsubmitted
Not Done

I have tested this and it unfortunately forward all records to the target and the target does not filter them according to their level. If you edit taskotron.yaml and set log_level_file: INFO, you'll see that the file still contains initial DEBUG messages. So we need to do record forwarding manually.

244​ # forward all 'missed' messages from memory to file
245​ # there's a method for automatically forwarding all messages from a
246​ # memory handler, but it does not respect target handler logging level.
247​ # we need to do it manually
248​ for record in mem_handler.buffer:
249​ if record.levelno >= file_handler.level:
250​ file_handler.handle(record)
251​
252​ mem_handler.close()
253​ rootlogger.removeHandler(mem_handler)
232 rootlogger.addHandler(file_handler) 254​ rootlogger.addHandler(file_handler)
233 log.debug('File logging enabled with level %s into: %s', 255​ log.debug('File logging enabled with level %s into: %s',
234 logging.getLevelName(file_handler.level), filelog_path) 256​ logging.getLevelName(file_handler.level), filelog_path)
235 else: 257​ else:
236 rootlogger.removeHandler(file_handler) 258​ rootlogger.removeHandler(file_handler)
259​ rootlogger.removeHandler(mem_handler)
237 260​
View Options

libtaskotron/runner.py

Show First 20 Lines • Show All 227 Lines • ▼ Show 20 Line(s)204def process_args(args):
228 args['override'] = override 228​ args['override'] = override
229 229​
230 return args 230​ return args
231 231​
232 232​
233def main(): 233​def main():
234 # Preliminary initialization of logging, so all messages before regular 234​ # Preliminary initialization of logging, so all messages before regular
235 # initialization can be logged to stream. 235​ # initialization can be logged to stream.
236 # FIXME: Remove this once this ticket is resolved: ​
237 # https://phab.qadevel.cloud.fedoraproject.org/T273 ​
238 logger.init_prior_config() 236​ logger.init_prior_config()
239 237​
240 log.info('Execution started at: %s', 238​ log.info('Execution started at: %s',
241 datetime.datetime.utcnow().strftime('%Y-%m-%d %H:%M:%S UTC')) 239​ datetime.datetime.utcnow().strftime('%Y-%m-%d %H:%M:%S UTC'))
242 log.debug('Using libtaskotron %s', libtaskotron.__version__) 240​ log.debug('Using libtaskotron %s', libtaskotron.__version__)
243 241​
244 # parse cmdline 242​ # parse cmdline
245 parser = get_argparser() 243​ parser = get_argparser()
Show All 22 Lines
View Options

testing/functest_logger.py

Show All 23 Lines14class TestLogger():
24 def teardown_method(self, method): 24​ def teardown_method(self, method):
25 '''Run after every method''' 25​ '''Run after every method'''
26 # reset the list of root handlers 26​ # reset the list of root handlers
27 logging.getLogger().handlers = self.root_handlers 27​ logging.getLogger().handlers = self.root_handlers
28 # reset the stream handler level 28​ # reset the stream handler level
29 if logger.stream_handler: 29​ if logger.stream_handler:
30 logger.stream_handler.level = self.stream_level 30​ logger.stream_handler.level = self.stream_level
31 31​
32 ​
33 def test_logfile(self, tmpdir): 32​ def test_logfile(self, tmpdir):
34 '''Messages should be logged to file when enabled''' 33​ '''Messages should be logged to file when enabled'''
35 log_path = tmpdir.join('test.log').strpath 34​ log_path = tmpdir.join('test.log').strpath
36 logger.init(filelog=True, filelog_path=log_path) 35​ logger.init(filelog=True, filelog_path=log_path)
37 36​
38 msg = 'This should appear in the log file' 37​ msg = 'This should appear in the log file'
39 logger.log.debug(msg) 38​ logger.log.debug(msg)
40 logger.file_handler.flush() 39​ logger.file_handler.flush()
▲ Show 20 Lines • Show All 46 Lines • ▼ Show 20 Line(s)84 def test_logfile_missing_dir(self, tmpdir):
87 log_path = tmpdir.join('missing_dir', 'test.log').strpath 86​ log_path = tmpdir.join('missing_dir', 'test.log').strpath
88 87​
89 logger.init(filelog=True, filelog_path=log_path) 88​ logger.init(filelog=True, filelog_path=log_path)
90 msg = 'This should be in a temporary log file' 89​ msg = 'This should be in a temporary log file'
91 logger.log.debug(msg) 90​ logger.log.debug(msg)
92 logger.file_handler.flush() 91​ logger.file_handler.flush()
93 92​
94 self.msg_in_tmp_log(msg, log_path) 93​ self.msg_in_tmp_log(msg, log_path)
94​
95​ def test_memhandler_to_logfile_level(self, tmpdir):
96​ '''When forwarding messages from memory to file, only messages with
97​ appropriate levels should be passed over'''
98​ log_path = tmpdir.join('test.log').strpath
99​ logger.init_prior_config()
100​
101​ # include random strings in the message for better reliability
102​ msg1 = 'A debug message Xai(Deihee8a'
103​ logger.log.debug(msg1)
104​ msg2 = 'An info message aC2pu}i5chai'
105​ logger.log.info(msg2)
106​ msg3 = 'A warn message lai_choow5Ie'
107​ logger.log.warn(msg3)
108​
109​ logger.init(filelog=True, filelog_path=log_path, level_file=logging.WARN)
110​ logger.file_handler.flush()
111​
112​ with open(log_path) as log_file:
113​ lines = log_file.readlines()
114​
115​ # msg1 nor msg2 should not be there, msg3 should be there
116​ assert len([line for line in lines if msg1 in line]) == 0
117​ assert len([line for line in lines if msg2 in line]) == 0
118​ assert len([line for line in lines if msg3 in line]) == 1
View Options

testing/test_logger.py

Show First 20 Lines • Show All 79 Lines • ▼ Show 20 Line(s)79 def test_invalid_level(self, monkeypatch):
80 '''Invalid log level in config file should be reverted to default''' 80​ '''Invalid log level in config file should be reverted to default'''
81 conf = config.get_config() 81​ conf = config.get_config()
82 default_level = conf.log_level_stream 82​ default_level = conf.log_level_stream
83 83​
84 monkeypatch.setattr(conf, 'log_level_stream', 'INVALID') 84​ monkeypatch.setattr(conf, 'log_level_stream', 'INVALID')
85 logger.init() 85​ logger.init()
86 assert logging.getLevelName(logger.stream_handler.level) != 'INVALID' 86​ assert logging.getLevelName(logger.stream_handler.level) != 'INVALID'
87 assert logging.getLevelName(logger.stream_handler.level) == default_level 87​ assert logging.getLevelName(logger.stream_handler.level) == default_level
88​
89​ def test_memhandler(self, monkeypatch):
90​ '''Records should be stored in memhandler between init_prior_config()
91​ and init(), regardless of chosen stream level'''
92​ logger.init_prior_config(level_stream=logging.WARN)
93​
94​ msg = 'Some initialization message'
95​ logger.log.debug(msg)
96​
97​ assert logger.mem_handler.buffer[-1].getMessage() == msg