Differential D347

logging: make stream log formatting simpler, less detailed
ClosedPublic
Actions

Authored by kparal on Apr 21 2015, 3:29 PM.

Details

Reviewers
tflink
mkrizek
jskladan
Commits
rLTRN88a67eff6124: logging: make stream log formatting simpler, less detailed
Summary

All the details like source file, line number or full date are still
in taskotron.log. But on stream it's more pleasant to read a shorter
version, taking less space from the left side.

On stream, the full date is also visible in the Execution started and
Execution finished lines.

This was an idea we had with @mkrizek yesterday.

If we need to grep logs for important messages and the details need to
be there for this purpose, I assume we would grep taskotron.log anyway,
not stream. But maybe I'm wrong?

Before:

$ runtask -i htop-1.0.3-4.fc21 -t koji_build ../task-rpmlint/rpmlint.yml
[libtaskotron:runner.py:241] 2015-04-21 15:21:47 INFO    Execution started at: 2015-04-21 15:21:47 UTC
[libtaskotron:runner.py:242] 2015-04-21 15:21:47 DEBUG   Using libtaskotron 0.3.14
[libtaskotron:runner.py:247] 2015-04-21 15:21:47 DEBUG   Parsed arguments: Namespace(arch=None, debug=False, item='htop-1.0.3-4.fc21', jobid='-1', override=[], task=['../task-rpmlint/rpmlint.yml'], type='koji_build', uuid='20150421_152147_045182')
[libtaskotron:config.py:92] 2015-04-21 15:21:47 DEBUG   Using config file: /etc/taskotron/taskotron.yaml
[libtaskotron:config.py:63] 2015-04-21 15:21:47 DEBUG   Using config profile: development
[libtaskotron:runner.py:51] 2015-04-21 15:21:47 INFO    Task artifacts will be saved in: /var/lib/taskotron/artifacts/20150421_152147_045182
[libtaskotron:koji_utils.py:139] 2015-04-21 15:21:47 INFO    Querying Koji for a list of RPMS for: htop-1.0.3-4.fc21
[libtaskotron:koji_utils.py:202] 2015-04-21 15:21:48 INFO    Fetching 4 RPMs for: htop-1.0.3-4.fc21 (into /var/tmp/taskotron/task-F69sxf)
[libtaskotron:python_directive.py:154] 2015-04-21 15:21:50 INFO    Executing Python: run_rpmlint.run() with args {'workdir': '/var/tmp/taskotron/task-F69sxf', 'koji_build': 'htop-1.0.3-4.fc21'}
htop.armv7hl: E: incorrect-fsf-address /usr/share/doc/htop/COPYING
htop.i686: E: incorrect-fsf-address /usr/share/doc/htop/COPYING
htop.x86_64: E: incorrect-fsf-address /usr/share/doc/htop/COPYING
4 packages and 0 specfiles checked; 3 errors, 0 warnings.
[libtaskotron:resultsdb_directive.py:183] 2015-04-21 15:21:54 INFO    Reporting to ResultsDB is disabled. Once enabled, the following would get reported:
not ok - rpmlint for Koji build htop-1.0.3-4.fc21   # FAIL 
  ---
  item: htop-1.0.3-4.fc21
  outcome: FAILED
  summary: rpmlint FAILED for htop-1.0.3-4.fc21
  type: koji_build
  ...
[libtaskotron:resultsdb_directive.py:184] 2015-04-21 15:21:54 INFO    Hint: Enabling debug output allows you to see unstripped values during variable export.
[libtaskotron:runner.py:267] 2015-04-21 15:21:54 INFO    Execution finished at: 2015-04-21 15:21:54 UTC

After:

$ runtask -i htop-1.0.3-4.fc21 -t koji_build ../task-rpmlint/rpmlint.yml
[libtaskotron] 15:22:07 INFO    Execution started at: 2015-04-21 15:22:07 UTC
[libtaskotron] 15:22:07 DEBUG   Using libtaskotron 0.3.14
[libtaskotron] 15:22:07 DEBUG   Parsed arguments: Namespace(arch=None, debug=False, item='htop-1.0.3-4.fc21', jobid='-1', override=[], task=['../task-rpmlint/rpmlint.yml'], type='koji_build', uuid='20150421_152207_511092')
[libtaskotron] 15:22:07 DEBUG   Using config file: /etc/taskotron/taskotron.yaml
[libtaskotron] 15:22:07 DEBUG   Using config profile: development
[libtaskotron] 15:22:07 INFO    Task artifacts will be saved in: /var/lib/taskotron/artifacts/20150421_152207_511092
[libtaskotron] 15:22:07 INFO    Querying Koji for a list of RPMS for: htop-1.0.3-4.fc21
[libtaskotron] 15:22:08 INFO    Fetching 4 RPMs for: htop-1.0.3-4.fc21 (into /var/tmp/taskotron/task-1cdcn3)
[libtaskotron] 15:22:10 INFO    Executing Python: run_rpmlint.run() with args {'workdir': '/var/tmp/taskotron/task-1cdcn3', 'koji_build': 'htop-1.0.3-4.fc21'}
htop.armv7hl: E: incorrect-fsf-address /usr/share/doc/htop/COPYING
htop.i686: E: incorrect-fsf-address /usr/share/doc/htop/COPYING
htop.x86_64: E: incorrect-fsf-address /usr/share/doc/htop/COPYING
4 packages and 0 specfiles checked; 3 errors, 0 warnings.
[libtaskotron] 15:22:14 INFO    Reporting to ResultsDB is disabled. Once enabled, the following would get reported:
not ok - rpmlint for Koji build htop-1.0.3-4.fc21   # FAIL 
  ---
  item: htop-1.0.3-4.fc21
  outcome: FAILED
  summary: rpmlint FAILED for htop-1.0.3-4.fc21
  type: koji_build
  ...
[libtaskotron] 15:22:14 INFO    Hint: Enabling debug output allows you to see unstripped values during variable export.
[libtaskotron] 15:22:14 INFO    Execution finished at: 2015-04-21 15:22:14 UTC

What do you think?

Test Plan

test suite works, and taskotron.log still contains full output when I run sample checks

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 logging: make stream log formatting simpler, less detailed.Apr 21 2015, 3:29 PM
kparal updated this object.
kparal edited the test plan for this revision. (Show Details)
kparal added reviewers: tflink, mkrizek, jskladan.
kparal added a subscriber: mkrizek.
tflink added a comment.Apr 21 2015, 3:53 PM

Do we even need the [libtaskotron] for stdout? I'm not sure that adds much value to the output if we're not including more information about which file the log message is coming from.

kparal added a comment.Apr 21 2015, 4:22 PM
In D347#6277, @tflink wrote:

Do we even need the [libtaskotron] for stdout? I'm not sure that adds much value to the output if we're not including more information about which file the log message is coming from.

Well, it allows people to distinguish which messages are coming from taskotron, and which messages are from their check or from somewhere else. You can see other sources then [libtaskotron] (at the moment resultsdb_api and koji), if they emit an INFO or above. Or if you specify --debug.

Which actually brings me to a question: if we specify --debug, should we use the simplified format for stream output, or should we switch to the detailed one? I think the detailed one makes more sense in this case. The current patch doesn't do that.

mkrizek added a comment.Apr 22 2015, 6:00 AM
In D347#6279, @kparal wrote:
In D347#6277, @tflink wrote:

Do we even need the [libtaskotron] for stdout? I'm not sure that adds much value to the output if we're not including more information about which file the log message is coming from.

Well, it allows people to distinguish which messages are coming from taskotron, and which messages are from their check or from somewhere else. You can see other sources then [libtaskotron] (at the moment resultsdb_api and koji), if they emit an INFO or above. Or if you specify --debug.

Which actually brings me to a question: if we specify --debug, should we use the simplified format for stream output, or should we switch to the detailed one? I think the detailed one makes more sense in this case. The current patch doesn't do that.

Yeah, the detailed one makes more sense to me. Otherwise looks good.

kparal updated this revision to Diff 937.EditedApr 22 2015, 1:47 PM
  • use full format when running with --debug

Without --debug:

$ runtask -i htop-1.0.3-4.fc21 -t koji_build ../task-rpmlint/rpmlint.yml
[libtaskotron] 13:37:19 INFO    Execution started at: 2015-04-22 13:37:19 UTC
[libtaskotron] 13:37:19 DEBUG   Using libtaskotron 0.3.14
[libtaskotron] 13:37:19 DEBUG   Parsed arguments: Namespace(arch=None, debug=False, item='htop-1.0.3-4.fc21', jobid='-1', override=[], task=['../task-rpmlint/rpmlint.yml'], type='koji_build', uuid='20150422_133719_454718')
[libtaskotron] 13:37:19 DEBUG   Using config file: /etc/taskotron/taskotron.yaml
[libtaskotron] 13:37:19 DEBUG   Using config profile: development
[libtaskotron] 13:37:19 INFO    Task artifacts will be saved in: /var/lib/taskotron/artifacts/20150422_133719_454718
[libtaskotron] 13:37:19 INFO    Querying Koji for a list of RPMS for: htop-1.0.3-4.fc21
[libtaskotron] 13:37:20 INFO    Fetching 4 RPMs for: htop-1.0.3-4.fc21 (into /var/tmp/taskotron/task-jcjZz9)
[libtaskotron] 13:37:22 INFO    Executing Python: run_rpmlint.run() with args {'workdir': '/var/tmp/taskotron/task-jcjZz9', 'koji_build': 'htop-1.0.3-4.fc21'}
htop.armv7hl: E: incorrect-fsf-address /usr/share/doc/htop/COPYING
htop.i686: E: incorrect-fsf-address /usr/share/doc/htop/COPYING
htop.x86_64: E: incorrect-fsf-address /usr/share/doc/htop/COPYING
4 packages and 0 specfiles checked; 3 errors, 0 warnings.
[libtaskotron] 13:37:26 INFO    Reporting to ResultsDB is disabled. Once enabled, the following would get reported:
not ok - rpmlint for Koji build htop-1.0.3-4.fc21   # FAIL 
  ---
  item: htop-1.0.3-4.fc21
  outcome: FAILED
  summary: rpmlint FAILED for htop-1.0.3-4.fc21
  type: koji_build
  ...
[libtaskotron] 13:37:26 INFO    Hint: Enabling debug output allows you to see unstripped values during variable export.
[libtaskotron] 13:37:26 INFO    Execution finished at: 2015-04-22 13:37:26 UTC

With --debug:

$ runtask -i htop-1.0.3-4.fc21 -t koji_build ../task-rpmlint/rpmlint.yml --debug
[libtaskotron] 13:41:18 INFO    Execution started at: 2015-04-22 13:41:18 UTC
[libtaskotron] 13:41:18 DEBUG   Using libtaskotron 0.3.14
[libtaskotron] 13:41:18 DEBUG   Parsed arguments: Namespace(arch=None, debug=True, item='htop-1.0.3-4.fc21', jobid='-1', override=[], task=['../task-rpmlint/rpmlint.yml'], type='koji_build', uuid='20150422_134118_485787')
[libtaskotron] 13:41:18 DEBUG   Using config file: /etc/taskotron/taskotron.yaml
[libtaskotron] 13:41:18 DEBUG   Using config profile: development
[libtaskotron:logger.py:195] 2015-04-22 13:41:18 DEBUG   Stream logging enabled with level: DEBUG
[libtaskotron:logger.py:233] 2015-04-22 13:41:18 DEBUG   File logging enabled with level DEBUG into: /var/log/taskotron/taskotron.log
[libtaskotron:runner.py:44] 2015-04-22 13:41:18 DEBUG   Current workdir: /var/tmp/taskotron/task-XhUwif
[libtaskotron:runner.py:51] 2015-04-22 13:41:18 INFO    Task artifacts will be saved in: /var/lib/taskotron/artifacts/20150422_134118_485787
[libtaskotron:runner.py:114] 2015-04-22 13:41:18 DEBUG   Executing directive: koji
[libtaskotron:koji_utils.py:139] 2015-04-22 13:41:18 INFO    Querying Koji for a list of RPMS for: htop-1.0.3-4.fc21
[libtaskotron:koji_utils.py:202] 2015-04-22 13:41:20 INFO    Fetching 4 RPMs for: htop-1.0.3-4.fc21 (into /var/tmp/taskotron/task-XhUwif)
[libtaskotron:file_utils.py:121] 2015-04-22 13:41:21 DEBUG   Already downloaded: /var/cache/taskotron/htop-1.0.3-4.fc21.armv7hl.rpm
[libtaskotron:file_utils.py:121] 2015-04-22 13:41:21 DEBUG   Already downloaded: /var/cache/taskotron/htop-1.0.3-4.fc21.i686.rpm
[libtaskotron:file_utils.py:121] 2015-04-22 13:41:22 DEBUG   Already downloaded: /var/cache/taskotron/htop-1.0.3-4.fc21.src.rpm
[libtaskotron:file_utils.py:121] 2015-04-22 13:41:22 DEBUG   Already downloaded: /var/cache/taskotron/htop-1.0.3-4.fc21.x86_64.rpm
[libtaskotron:runner.py:114] 2015-04-22 13:41:22 DEBUG   Executing directive: python
[libtaskotron:python_directive.py:154] 2015-04-22 13:41:22 INFO    Executing Python: run_rpmlint.run() with args {'workdir': '/var/tmp/taskotron/task-XhUwif', 'koji_build': 'htop-1.0.3-4.fc21'}
htop.armv7hl: E: incorrect-fsf-address /usr/share/doc/htop/COPYING
htop.i686: E: incorrect-fsf-address /usr/share/doc/htop/COPYING
htop.x86_64: E: incorrect-fsf-address /usr/share/doc/htop/COPYING
4 packages and 0 specfiles checked; 3 errors, 0 warnings.
[libtaskotron:runner.py:128] 2015-04-22 13:41:26 DEBUG   Variable ${rpmlint_output} was exported with value:
TAP version 13
1..1
not ok - rpmlint for Koji build htop-1.0.3-4.fc21   # FAIL 
  ---
  item: htop-1.0.3-4.fc21
  outcome: FAILED
  summary: rpmlint FAILED for htop-1.0.3-4.fc21
  type: koji_build
  ...
[libtaskotron:runner.py:114] 2015-04-22 13:41:26 DEBUG   Executing directive: resultsdb
[libtaskotron:resultsdb_directive.py:170] 2015-04-22 13:41:26 DEBUG   TAP output parsed OK.
[libtaskotron:resultsdb_directive.py:183] 2015-04-22 13:41:26 INFO    Reporting to ResultsDB is disabled. Once enabled, the following would get reported:
not ok - rpmlint for Koji build htop-1.0.3-4.fc21   # FAIL 
  ---
  item: htop-1.0.3-4.fc21
  outcome: FAILED
  summary: rpmlint FAILED for htop-1.0.3-4.fc21
  type: koji_build
  ...
[libtaskotron:resultsdb_directive.py:184] 2015-04-22 13:41:26 INFO    Hint: Enabling debug output allows you to see unstripped values during variable export.
[libtaskotron:runner.py:267] 2015-04-22 13:41:26 INFO    Execution finished at: 2015-04-22 13:41:26 UTC

The first few lines are printed using the simple format, before we actually parse config file and cmdline arguments and find out whether we're running with --debug or not. But I don't think it's much of a problem. Of course I could swap the behavior (print the first few lines with full formatting and then change it to simple if we're not running with --debug).

tflink accepted this revision.Apr 22 2015, 1:51 PM
This revision is now accepted and ready to land.Apr 22 2015, 1:51 PM
Closed by commit rLTRN88a67eff6124: logging: make stream log formatting simpler, less detailed (authored by kparal). · Explain WhyApr 22 2015, 2:01 PM
This revision was automatically updated to reflect the committed changes.

Revision Contents

PathPackages
Mlibtaskotron/logger.py (15 lines)

Diff 938

View Options

libtaskotron/logger.py

Show All 29 Lines
30#: the main logger for libtaskotron library, easily accessible from all our 30​#: the main logger for libtaskotron library, easily accessible from all our
31#: modules 31​#: modules
32log = logging.getLogger('libtaskotron') 32​log = logging.getLogger('libtaskotron')
33log.addHandler(logging.NullHandler()) # this is needed when running in library mode 33​log.addHandler(logging.NullHandler()) # this is needed when running in library mode
34 34​
35# set logging time to UTC/GMT 35​# set logging time to UTC/GMT
36logging.Formatter.converter = time.gmtime 36​logging.Formatter.converter = time.gmtime
37 37​
38_fmt = '[%(name)s:%(filename)s:%(lineno)d] '\ 38​_fmt_full = '[%(name)s:%(filename)s:%(lineno)d] '\
39 '%(asctime)s %(levelname)-7s %(message)s' 39​ '%(asctime)s %(levelname)-7s %(message)s'
40_datefmt = '%Y-%m-%d %H:%M:%S' 40​_fmt_simple = '[%(name)s] %(asctime)s %(levelname)-7s %(message)s'
41_formatter = logging.Formatter(fmt=_fmt, datefmt=_datefmt) 41​_datefmt_full = '%Y-%m-%d %H:%M:%S'
42​_datefmt_simple = '%H:%M:%S'
43​_formatter_full = logging.Formatter(fmt=_fmt_full, datefmt=_datefmt_full)
44​_formatter_simple = logging.Formatter(fmt=_fmt_simple, datefmt=_datefmt_simple)
42 45​
43#: our current stream handler sending logged messages to stderr 46​#: our current stream handler sending logged messages to stderr
44stream_handler = None 47​stream_handler = None
45 48​
46#: our current syslog handler sending logged messages to syslog 49​#: our current syslog handler sending logged messages to syslog
47syslog_handler = None 50​syslog_handler = None
48 51​
49#: our current file handler sending logged messages to file log 52​#: our current file handler sending logged messages to file log
Show All 14 Lines66 :param str filelog_path: path to the log file where :data:`file_handler`
64 should emit messages. If this is ``None``, then 67​ should emit messages. If this is ``None``, then
65 :data:`file_handler` is not created. 68​ :data:`file_handler` is not created.
66 :raise socket.error: if syslog handler creation failed 69​ :raise socket.error: if syslog handler creation failed
67 ''' 70​ '''
68 global stream_handler, syslog_handler, file_handler 71​ global stream_handler, syslog_handler, file_handler
69 72​
70 if not stream_handler: 73​ if not stream_handler:
71 stream_handler = logging.StreamHandler() 74​ stream_handler = logging.StreamHandler()
72 stream_handler.setFormatter(_formatter) 75​ stream_handler.setFormatter(_formatter_simple)
73 76​
74 if syslog and not syslog_handler: 77​ if syslog and not syslog_handler:
75 syslog_handler = logging.handlers.SysLogHandler(address='/dev/log', 78​ syslog_handler = logging.handlers.SysLogHandler(address='/dev/log',
76 facility=logging.handlers.SysLogHandler.LOG_LOCAL4) 79​ facility=logging.handlers.SysLogHandler.LOG_LOCAL4)
77 80​
78 if not file_handler and filelog_path: 81​ if not file_handler and filelog_path:
79 file_handler = logging.FileHandler(filelog_path, encoding='UTF-8') 82​ file_handler = logging.FileHandler(filelog_path, encoding='UTF-8')
80 file_handler.setFormatter(_formatter) 83​ file_handler.setFormatter(_formatter_full)
81 84​
82 85​
83def _log_excepthook(*exc_info): 86​def _log_excepthook(*exc_info):
84 '''Called when an exception is not caught''' 87​ '''Called when an exception is not caught'''
85 log.critical(''.join(traceback.format_exception(*exc_info))) 88​ log.critical(''.join(traceback.format_exception(*exc_info)))
86 89​
87 90​
88def _set_verbosity_levels(): 91​def _set_verbosity_levels():
▲ Show 20 Lines • Show All 91 Lines • ▼ Show 20 Line(s)182 if filelog_path is None:
180 filelog_path = os.path.join(conf.logdir, conf.log_name) 183​ filelog_path = os.path.join(conf.logdir, conf.log_name)
181 184​
182 _create_handlers() 185​ _create_handlers()
183 rootlogger = logging.getLogger() 186​ rootlogger = logging.getLogger()
184 sys.excepthook = _log_excepthook 187​ sys.excepthook = _log_excepthook
185 188​
186 if stream: 189​ if stream:
187 _set_level(stream_handler, level_stream, "log_level_stream") 190​ _set_level(stream_handler, level_stream, "log_level_stream")
191​ if stream_handler.level <= logging.DEBUG:
192​ stream_handler.setFormatter(_formatter_full)
188 rootlogger.addHandler(stream_handler) 193​ rootlogger.addHandler(stream_handler)
189 log.debug("Stream logging enabled with level: %s", 194​ log.debug("Stream logging enabled with level: %s",
190 logging.getLevelName(stream_handler.level)) 195​ logging.getLevelName(stream_handler.level))
191 else: 196​ else:
192 rootlogger.removeHandler(stream_handler) 197​ rootlogger.removeHandler(stream_handler)
193 198​
194 if syslog: 199​ if syslog:
195 _create_handlers(syslog=True) 200​ _create_handlers(syslog=True)
Show All 36 Lines