Differential D314

logger: behave nicely as a library, configure resultsdb_api logger
ClosedPublic
Actions

Authored by kparal on Mar 19 2015, 2:14 PM.

Details

Reviewers
tflink
mkrizek
jskladan
Commits
rLTRN4831c9c2adff: logger: behave nicely as a library, configure resultsdb_api logger
Summary

This improves behavior when libtaskotron is not used as the main script,
but as a library. It no longer configures libtaskotron logger to the
DEBUG level by default, but inherits the root logger configuration. That
allows script authors to tune logging verbosity in a central place and
libtaskotron will respect that.

If libtaskotron is used as the main script, we set maximum verbosity and
then control the messages in the handlers.

Resultsdb_api is now also set to maximum verbosity when running as the
main script. This allows us to see resultsdb_api errors and debug
messages during task execution.

This is important to debug issues like these:
http://taskotron-dev.fedoraproject.org/taskmaster/builders/x86_64/builds/3/steps/runtask/logs/taskotron.log

Test Plan

Test suite passes. I also tested resultsdb_api debug messages about invalid json manually. It looks like this:

[libtaskotron:runner.py:114] 2015-03-19 13:11:51 DEBUG   Executing directive: resultsdb
[libtaskotron:resultsdb_directive.py:163] 2015-03-19 13:11:51 DEBUG   TAP output is OK.
[resultsdb_api:resultsdb_api.py:55] 2015-03-19 13:11:51 WARNING Received HTTP failure status code 501 for request: http://localhost:8000/jobs
[resultsdb_api:resultsdb_api.py:59] 2015-03-19 13:11:51 DEBUG   Received invalid JSON data:Expecting value: line 1 column 1 (char 0)
<head>
<title>Error response</title>
</head>
<body>
<h1>Error response</h1>
<p>Error code 501.
<p>Message: Unsupported method ('POST').
<p>Error code explanation: 501 = Server does not support this operation.
</body>

[libtaskotron:logger.py:73] 2015-03-19 13:11:51 CRITICAL Traceback (most recent call last):
  File "/home/kparal/devel/taskotron/env_taskotron/bin/runtask", line 9, in <module>
    load_entry_point('libtaskotron==0.3.12', 'console_scripts', 'runtask')()
  File "/home/kparal/devel/taskotron/libtaskotron/libtaskotron/runner.py", line 263, in main
    task_runner.run()
  File "/home/kparal/devel/taskotron/libtaskotron/libtaskotron/runner.py", line 61, in run
    self.do_actions()
  File "/home/kparal/devel/taskotron/libtaskotron/libtaskotron/runner.py", line 145, in do_actions
    self.do_single_action(action)
  File "/home/kparal/devel/taskotron/libtaskotron/libtaskotron/runner.py", line 123, in do_single_action
    self.envdata)
  File "/home/kparal/devel/taskotron/libtaskotron/libtaskotron/directives/resultsdb_directive.py", line 182, in process
    uuid=env_data['uuid'],
  File "/home/kparal/devel/taskotron/libtaskotron/libtaskotron/directives/resultsdb_directive.py", line 137, in create_resultsdb_job
    uuid=uuid)
  File "/home/kparal/devel/taskotron/resultsdb_api/resultsdb_api.py", line 72, in create_job
    self.__raise_on_error(r)
  File "/home/kparal/devel/taskotron/resultsdb_api/resultsdb_api.py", line 61, in __raise_on_error
    'Invalid JSON (HTTP %s): %s' % (r.status_code, e), r)
ResultsDBapiException: 'Invalid JSON (HTTP 501): Expecting value: line 1 column 1 (char 0)'

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.
kparal retitled this revision from to logger: behave nicely as a library, configure resultsdb_api logger.Mar 19 2015, 2:14 PM
kparal updated this object.
kparal edited the test plan for this revision. (Show Details)
kparal added reviewers: jskladan, mkrizek, tflink.
jskladan accepted this revision.Mar 19 2015, 2:32 PM
jskladan added inline comments.
libtaskotron/logger.py
89

I'd either choose a different name for the method - maybe something like _set_levels (?) or just plain moved the code to init_prior_config.

This revision is now accepted and ready to land.Mar 19 2015, 2:32 PM
tflink added a comment.Mar 19 2015, 2:46 PM

The verbage here took a few reads through to understand what's going on here - was thrown off a bit by the "library" vs. "main program" stuff. I wonder if it'd be clearer to say "using the libtaskotron runner" vs. "using libtaskotron components as an external library".

I also wonder if the logging.getLogger('resultsdb_api').setLevel(logging.DEBUG) call would be better to put in directives which use resultsdb_api instead of hard-coding log level calls in init.

kparal updated this revision to Diff 857.Mar 19 2015, 2:57 PM

Address some issues in the review - a method name, and a module docstring explanation.

kparal added a comment.Mar 19 2015, 3:07 PM
In D314#5661, @tflink wrote:

I also wonder if the logging.getLogger('resultsdb_api').setLevel(logging.DEBUG) call would be better to put in directives which use resultsdb_api instead of hard-coding log level calls in init.

Do you have any reason for it? I see several advantages the way it is:

  • It's in a central place and you can easily see every module configuration in a single file. If we set it in different files, it's going to be much harder to get the global picture.
  • We have a very easy way to distinguish library vs runner mode in logger.py. It's going to be more difficult in other modules, we would need to write special checks for it.
  • It needs to be set only once anyway, so the sooner the better and everything in once seems to be more straightforward. We can control the stream/file output levels any time in runtime by setting handler levels. The logger level doesn't need to be touched again.

If I understand this correctly, I'm not hardcoding anything. I'm simply saying "produce all messages and we'll throw away those we don't like later in the handlers". It's not like we would receive debug messages from resultsdb_api to stdout by default (only if you run it with --debug).

tflink accepted this revision.Mar 19 2015, 3:46 PM
In D314#5671, @kparal wrote:
In D314#5661, @tflink wrote:

I also wonder if the logging.getLogger('resultsdb_api').setLevel(logging.DEBUG) call would be better to put in directives which use resultsdb_api instead of hard-coding log level calls in init.

Do you have any reason for it? I see several advantages the way it is:

  • It's in a central place and you can easily see every module configuration in a single file. If we set it in different files, it's going to be much harder to get the global picture.
  • We have a very easy way to distinguish library vs runner mode in logger.py. It's going to be more difficult in other modules, we would need to write special checks for it.
  • It needs to be set only once anyway, so the sooner the better and everything in once seems to be more straightforward. We can control the stream/file output levels any time in runtime by setting handler levels. The logger level doesn't need to be touched again.

    If I understand this correctly, I'm not hardcoding anything. I'm simply saying "produce all messages and we'll throw away those we don't like later in the handlers". It's not like we would receive debug messages from resultsdb_api to stdout by default (only if you run it with --debug).

'hardcode' was probably the wrong word to use here. I'm just not a huge fan of the "here's a library that we may use at some point, make sure it's set to XXX logging level" approach.

that being said, you do have a point about only setting it in one place and setting it early.

kparal added a comment.Mar 19 2015, 4:04 PM
In D314#5676, @tflink wrote:

'hardcode' was probably the wrong word to use here. I'm just not a huge fan of the "here's a library that we may use at some point, make sure it's set to XXX logging level" approach.

After D313, it should be immediately usable and useful. That's why I did it :-)

There's also an alternative approach, just set root logger to DEBUG - resultsdb_api would respect that. The downside is that we then receive large amounts of debug messages from other libraries as well (yamlish, python-requests, etc), and I'm not sure we want it. So for this moment it seemed easier to just handpick those we definitely want, instead of filtering out those we don't want, or accepting simply everything. But that can be changed very easily, so if you or anyone else want to see more contents in the debug log, just say a word.

Closed by commit rLTRN4831c9c2adff: logger: behave nicely as a library, configure resultsdb_api logger (authored by kparal). · Explain WhyMar 19 2015, 4:06 PM
This revision was automatically updated to reflect the committed changes.

Revision Contents

PathPackages
Mlibtaskotron/logger.py (24 lines)

Diff 859

View Options

libtaskotron/logger.py

1# -*- coding: utf-8 -*- 1​# -*- coding: utf-8 -*-
2# Copyright 2009-2014, Red Hat, Inc. 2​# Copyright 2009-2014, Red Hat, Inc.
3# License: GPL-2.0+ <http://spdx.org/licenses/GPL-2.0+> 3​# License: GPL-2.0+ <http://spdx.org/licenses/GPL-2.0+>
4# See the LICENSE file for more details on Licensing 4​# See the LICENSE file for more details on Licensing
5 5​
6​''' Configure logging in libtaskotron.
7​
8​There are two modes how to operate - as an external library, or as the main
9​script runner:
10​
11​* In the external library mode, we try not to change any global defaults, not
12​ touch the root logger, and not attach any handlers. The main script author
13​ should be in control of all these things.
14​* In the main script runner mode, we control everything - we configure the root
15​ logger, attach handlers to it, and set verbosity of this and any other library
16​ as we see fit.
17​'''
18​
6from __future__ import absolute_import 19​from __future__ import absolute_import
7import sys 20​import sys
8import os 21​import os
9import tempfile 22​import tempfile
10import logging 23​import logging
11import logging.handlers 24​import logging.handlers
12import traceback 25​import traceback
13import time 26​import time
14 ​
15# you must not import libtaskotron.config here because of cyclic dependencies 27​# you must not import libtaskotron.config here because of cyclic dependencies
16 28​
17# http://docs.python.org/2/howto/logging.html#configuring-logging-for-a-library 29​# http://docs.python.org/2/howto/logging.html#configuring-logging-for-a-library
18#: the main logger for libtaskotron library, easily accessible from all our 30​#: the main logger for libtaskotron library, easily accessible from all our
19#: modules 31​#: modules
20log = logging.getLogger('libtaskotron') 32​log = logging.getLogger('libtaskotron')
21log.setLevel(logging.DEBUG) # need to set level, otherwise root level is inherited ​
22log.addHandler(logging.NullHandler()) # this is needed when running in library mode 33​log.addHandler(logging.NullHandler()) # this is needed when running in library mode
23 34​
24# set logging time to UTC/GMT 35​# set logging time to UTC/GMT
25logging.Formatter.converter = time.gmtime 36​logging.Formatter.converter = time.gmtime
26 37​
27_fmt = '[%(name)s:%(filename)s:%(lineno)d] '\ 38​_fmt = '[%(name)s:%(filename)s:%(lineno)d] '\
28 '%(asctime)s %(levelname)-7s %(message)s' 39​ '%(asctime)s %(levelname)-7s %(message)s'
29_datefmt = '%Y-%m-%d %H:%M:%S' 40​_datefmt = '%Y-%m-%d %H:%M:%S'
Show All 40 Lines78 if not file_handler and filelog_path:
70 file_handler.setFormatter(_formatter) 81​ file_handler.setFormatter(_formatter)
71 82​
72 83​
73def _log_excepthook(*exc_info): 84​def _log_excepthook(*exc_info):
74 '''Called when an exception is not caught''' 85​ '''Called when an exception is not caught'''
75 log.critical(''.join(traceback.format_exception(*exc_info))) 86​ log.critical(''.join(traceback.format_exception(*exc_info)))
76 87​
77 88​
89​def _set_verbosity_levels():
jskladanUnsubmitted
Not Done

I'd either choose a different name for the method - maybe something like _set_levels (?) or just plain moved the code to init_prior_config.

90​ '''Configure libtaskotron and other important libraries for maximum
91​ verbosity. The actual verbosity is then adjusted in our handlers. This
92​ should be only called when running as the main script.'''
93​ log.setLevel(logging.DEBUG)
94​ logging.getLogger('resultsdb_api').setLevel(logging.DEBUG)
95​
96​
78def init_prior_config(level_stream=None): 97​def init_prior_config(level_stream=None):
79 '''Initialize Taskotron logging with default values which do not rely on 98​ '''Initialize Taskotron logging with default values which do not rely on
80 a config file. Only stream logging is enabled here. This is used before the 99​ a config file. Only stream logging is enabled here. This is used before the
81 config file is loaded. After that a proper initialization should take place 100​ config file is loaded. After that a proper initialization should take place
82 through the :func:`init` method. 101​ through the :func:`init` method.
83 102​
84 Note: Since this touches the root logger, it should be called only when 103​ Note: Since this touches the root logger, it should be called only when
85 Taskotron is run as the main program (through its runner), not when it is 104​ Taskotron is run as the main program (through its runner), not when it is
86 used as a library. 105​ used as a library.
87 106​
88 :param int level_stream: message level of the stream logger. The level 107​ :param int level_stream: message level of the stream logger. The level
89 definitions are in :mod:`logging`. If ``None``, the default level is 108​ definitions are in :mod:`logging`. If ``None``, the default level is
90 used (i.e. :data:`logging.NOTSET`). 109​ used (i.e. :data:`logging.NOTSET`).
91 ''' 110​ '''
92 _create_handlers() 111​ _create_handlers()
112​ _set_verbosity_levels()
93 113​
94 if level_stream is not None: 114​ if level_stream is not None:
95 stream_handler.setLevel(level_stream) 115​ stream_handler.setLevel(level_stream)
96 rootlogger = logging.getLogger() 116​ rootlogger = logging.getLogger()
97 rootlogger.addHandler(stream_handler) 117​ rootlogger.addHandler(stream_handler)
98 118​
99 sys.excepthook = _log_excepthook 119​ sys.excepthook = _log_excepthook
100 120​
▲ Show 20 Lines • Show All 109 Lines • Show Last 20 Lines