RFC: Rethink logging to be more usefull for the user #151

New Issue

ungleich-gitea · 2021-11-20T15:20:17Z

ungleich-gitea commented

2021-11-20 15:20:17 +00:00

Created by: asteven

-v is basically non-existent. But would be the most important logging
-vv is to verbose. We use it to show a trace of code flow.
-vvv (aka debug) is very verbose, close to useless imho.

I propose to change our logging as follows:

level	cli flag	used for
ERROR	default	well for errors ;-)
WARNING	default	well for warnings ;-), altough I don't see much reason to have these
INFO	-v	only target state changes
TRACE	-vv	most of what we currently log as INFO
DEBUG	-vvv	developer written debug log messages
VERBOSE	-vvvv	command lines, arguments, output files, all the stuff that is usually to verbose

Resources

https://stackoverflow.com/a/5278006

Custom log levels in python

In [2]: logging._levelToName
Out[2]: 
{0: 'NOTSET',
 10: 'DEBUG',
 20: 'INFO',
 30: 'WARNING',
 40: 'ERROR',
 50: 'CRITICAL'}

import logging
logging.VERBOSE = 5
logging.addLevelName(logging.VERBOSE, "VERBOSE")
logging.Logger.verbose = lambda inst, msg, *args, **kwargs: inst.log(logging.VERBOSE, msg, *args, **kwargs)
logging.verbose = lambda msg, *args, **kwargs: logging.log(logging.VERBOSE, msg, *args, **kwargs)

logging.TRACE = 15
logging.addLevelName(logging.TRACE, "TRACE")
logging.Logger.trace = lambda inst, msg, *args, **kwargs: inst.log(logging.TRACE msg, *args, **kwargs)
logging.trace = lambda msg, *args, **kwargs: logging.log(logging.TRACE, msg, *args, **kwargs)

*Created by: asteven* -v is basically non-existent. But would be the most important logging -vv is to verbose. We use it to show a trace of code flow. -vvv (aka debug) is very verbose, close to useless imho. I propose to change our logging as follows: | level | cli flag | used for | |---|---|---| | ERROR | default | well for errors ;-) | | WARNING | default | well for warnings ;-), altough I don't see much reason to have these | | INFO | -v | only target state changes | | TRACE | -vv | most of what we currently log as INFO | | DEBUG | -vvv | developer written debug log messages | | VERBOSE | -vvvv | command lines, arguments, output files, all the stuff that is usually to verbose | ### Resources https://stackoverflow.com/a/5278006 ### Custom log levels in python ```python In [2]: logging._levelToName Out[2]: {0: 'NOTSET', 10: 'DEBUG', 20: 'INFO', 30: 'WARNING', 40: 'ERROR', 50: 'CRITICAL'} import logging logging.VERBOSE = 5 logging.addLevelName(logging.VERBOSE, "VERBOSE") logging.Logger.verbose = lambda inst, msg, *args, **kwargs: inst.log(logging.VERBOSE, msg, *args, **kwargs) logging.verbose = lambda msg, *args, **kwargs: logging.log(logging.VERBOSE, msg, *args, **kwargs) logging.TRACE = 15 logging.addLevelName(logging.TRACE, "TRACE") logging.Logger.trace = lambda inst, msg, *args, **kwargs: inst.log(logging.TRACE msg, *args, **kwargs) logging.trace = lambda msg, *args, **kwargs: logging.log(logging.TRACE, msg, *args, **kwargs) ```

ungleich-gitea added the

cleanup

label 2021-11-20 15:20:17 +00:00

ungleich-gitea closed this issue

2021-11-20 15:20:17 +00:00

ungleich-gitea commented

2021-11-20 15:43:56 +00:00

Created by: darko-poljak

Branch better-logging merged to master.

*Created by: darko-poljak* Branch better-logging merged to master.

ungleich-gitea commented

2021-11-20 15:43:57 +00:00

Created by: darko-poljak

@asteven @telmich I redefined cdist logging facility. Take a look: https://github.com/ungleich/cdist/compare/master...darko-poljak:better-logging

If you have no remarks then we can continue with cleaning messages and message levels.

*Created by: darko-poljak* @asteven @telmich I redefined cdist logging facility. Take a look: https://github.com/ungleich/cdist/compare/master...darko-poljak:better-logging If you have no remarks then we can continue with cleaning messages and message levels.

ungleich-gitea commented

2021-11-20 15:43:58 +00:00

Created by: darko-poljak

@asteven As it seems most logging frameworks use TRACE < DEBUG.
SLF4J, Logback, log4j, Apache Commons Logging, Log4Net, NLog, apache httpd as an application example, as mentioned in comment in above reference and for example in https://stackoverflow.com/questions/2031163/when-to-use-the-different-log-levels.
In my opinion tracing execution of each step is finer-grained than debug messages.

I agree with the last proposed log levels.

*Created by: darko-poljak* @asteven As it seems most logging frameworks use TRACE < DEBUG. SLF4J, Logback, log4j, Apache Commons Logging, Log4Net, NLog, apache httpd as an application example, as mentioned in comment in above reference and for example in https://stackoverflow.com/questions/2031163/when-to-use-the-different-log-levels. In my opinion tracing execution of each step is finer-grained than debug messages. I agree with the last proposed log levels.

ungleich-gitea commented

2021-11-20 15:44:00 +00:00

Created by: asteven

What about:

level	cli flag	used for
ERROR	default	well for errors ;-)
WARNING	default	well for warnings ;-)
INFO	-v	only target state changes
VERBOSE	-vv	most of what we currently log as INFO
DEBUG	-vvv	developer written debug log messages
TRACE	-vvvv	command lines, arguments, command output files, all the stuff that is usually to verbose

ERROR and WARNING would always be printed unless explicitly silenced by -q/--quiet.

*Created by: asteven* What about: | level | cli flag | used for | |---|---|---| | ERROR | default | well for errors ;-) | | WARNING | default | well for warnings ;-) | | INFO | -v | only target state changes | | VERBOSE | -vv | most of what we currently log as INFO | | DEBUG | -vvv | developer written debug log messages | | TRACE | -vvvv | command lines, arguments, command output files, all the stuff that is usually to verbose | ERROR and WARNING would always be printed unless explicitly silenced by -q/--quiet.

ungleich-gitea commented

2021-11-20 15:44:01 +00:00

Created by: asteven

@darko-poljak Who said TRACE is finer-grained than DEBUG? There's no law that dictates what log levels are called.

I based the names and order on https://stackoverflow.com/a/5278006 just because it's the most complete, well-founded example I found.

But I don't care that much about the names. Having 4 different/usable logging levels is what I'm after.

Looking at the current logging output:

[15:35:21] crius:~% cdist-hpc config -vv localhost
INFO: cdist: version 9.9.9
INFO: localhost: Running global explorers
INFO: localhost: Running global explorers sequentially
INFO: localhost: Running initial manifest /tmp/tmp6c_zk1fi/421aa90e079fa326b6494f812ad13e79/data/conf/manifest/init
INFO: localhost: Iteration in sequential mode
INFO: localhost: Running manifest and explorers for __file/tmp/cdist-was-here
INFO: localhost: Generating code for __file/tmp/cdist-was-here
INFO: localhost: Executing code for __file/tmp/cdist-was-here
INFO: localhost: Running manifest and explorers for __cdist_config_version/
INFO: localhost: Iteration in sequential mode
INFO: localhost: Running manifest and explorers for __file/etc/cdist-config-versions
INFO: localhost: Generating code for __file/etc/cdist-config-versions
INFO: localhost: Generating code for __cdist_config_version/
INFO: localhost: Iteration in sequential mode
INFO: localhost: Finished successful run in 3.506462335586548 seconds
INFO: cdist: Total processing time for 1 host(s): 3.5103187561035156

Most of those INFO's are actually there to follow the code flow as it runs. For me TRACE is the best name for this. INFO would be natural/logical for the messages that actually INFORM the user about something usefull: e.g. hey dude: we just changed the state of your file /tmp/foobar on host some.target.host

If I run the same in debug mode I get 1000 lines of output. For 2 objects.

[22:08:23] crius:~% cdist-hpc config -vvv localhost 
DEBUG: cdist: Namespace(beta=False, command='config', conf_dir=None, debug=False, dry_run=False, func=<bound method Config.commandline of <class 'cdist.config.Config'>>, host=['localhost'], hostfile=None, jobs=None, manifest=None, out_path=None, parallel=False, remote_copy=None, remote_exec=None, remote_out_path=None, verbose=3)
INFO: cdist: version 9.9.9
DEBUG: cdist: Base root path for target host "localhost" is "/tmp/tmp3k9ygy3q/421aa90e079fa326b6494f812ad13e79"
DEBUG: localhost: remote_exec for host "localhost": ssh -o User=root -o ControlPath=/tmp/tmp3_bj01rz/s  -o ControlMaster=auto  -o ControlPersist=10
DEBUG: localhost: remote_copy for host "localhost": scp -o User=root -o ControlPath=/tmp/tmp3_bj01rz/s  -o ControlMaster=auto  -o ControlPersist=10
DEBUG: localhost: derived host_name for host "localhost": localhost.localdomain
DEBUG: localhost: derived host_fqdn for host "localhost": localhost.localdomain
DEBUG: localhost: target_host: ('localhost', 'localhost.localdomain', 'localhost.localdomain')
DEBUG: localhost: Local mkdir: /tmp/tmp3k9ygy3q/421aa90e079fa326b6494f812ad13e79/data
DEBUG: localhost: Local mkdir: /tmp/tmp3k9ygy3q/421aa90e079fa326b6494f812ad13e79/data/conf
DEBUG: localhost: Local mkdir: /tmp/tmp3k9ygy3q/421aa90e079fa326b6494f812ad13e79/data/explorer

... several more Local mkdir's

DEBUG: localhost: Checking conf_dir /home/sar/vcs/cdist/cdist/conf ...
DEBUG: localhost: Linking /home/sar/vcs/cdist/cdist/conf/explorer/memory to /tmp/tmp3k9ygy3q/421aa90e079fa326b6494f812ad13e79/data/conf/explorer/memory ...
DEBUG: localhost: Linking /home/sar/vcs/cdist/cdist/conf/explorer/lsb_release to /tmp/tmp3k9ygy3q/421aa90e079fa326b6494f812ad13e79/data/conf/explorer/lsb_release ...
DEBUG: localhost: Linking /home/sar/vcs/cdist/cdist/conf/explorer/interfaces to /tmp/tmp3k9ygy3q/421aa90e079fa326b6494f812ad13e79/data/conf/explorer/interfaces ...
DEBUG: localhost: Linking /home/sar/vcs/cdist/cdist/conf/explorer/runlevel to /tmp/tmp3k9ygy3q/421aa90e079fa326b6494f812ad13e79/data/conf/explorer/runlevel ...

... 170 more lines Linking ...

DEBUG: localhost: Checking conf_dir /home/sar/.cdist ...
DEBUG: localhost: Checking conf_dir  ...
DEBUG: localhost: Linking /home/sar/files/lorem to /tmp/tmp3k9ygy3q/421aa90e079fa326b6494f812ad13e79/data/conf/files/lorem ...

... again 30 lines of Linking

DEBUG: localhost: Checking conf_dir /home/sar/.cdist-hpc ...
DEBUG: localhost: Linking /home/sar/.cdist-hpc/explorer/init-system to /tmp/tmp3k9ygy3q/421aa90e079fa326b6494f812ad13e79/data/conf/explorer/init-system ...

... another 380 lines of Linking

DEBUG: localhost: Linking emulator: /home/sar/.virtualenvs/cdist/bin/cdist to /tmp/tmp3k9ygy3q/421aa90e079fa326b6494f812ad13e79/data/bin/__zfs
...

... and another 300 or so lines of Linking emulator

DEBUG: localhost: Object marker .cdist-xiufkxhx saved in /tmp/tmp3k9ygy3q/421aa90e079fa326b6494f812ad13e79/data/object_marker
DEBUG: localhost: Remote rmdir: /var/lib/cdist
DEBUG: localhost: Remote run: ['ssh', '-o', 'User=root', '-o', 'ControlPath=/tmp/tmp3_bj01rz/s', '-o', 'ControlMaster=auto', '-o', 'ControlPersist=10', 'localhost', 'rm', '-rf', '/var/lib/cdist']
DEBUG: localhost: Remote stdout: b''
DEBUG: localhost: Remote mkdir: /var/lib/cdist
DEBUG: localhost: Remote run: ['ssh', '-o', 'User=root', '-o', 'ControlPath=/tmp/tmp3_bj01rz/s', '-o', 'ControlMaster=auto', '-o', 'ControlPersist=10', 'localhost', 'mkdir', '-p', '/var/lib/cdist']
DEBUG: localhost: Remote stdout: b''

and another 500 lines or so for remote rmdir/mkdir transfer, exec ...

All the 'Linking foo to bar' and 'linking emulator' messages are just useless noise.
We have tests to verify that the code works. If it can link one emulator the same code will also be able to link the other 500. And if it fails for one, we have exceptions for that.

All the Remote run: 'long string of code' are also just noise. Sometimes usefull to have to troubleshoot a very specific problem. But for a initial debug - useless.

*Created by: asteven* @darko-poljak Who said TRACE is finer-grained than DEBUG? There's no law that dictates what log levels are called. I based the names and order on https://stackoverflow.com/a/5278006 just because it's the most complete, well-founded example I found. But I don't care that much about the names. Having 4 different/usable logging levels is what I'm after. Looking at the current logging output: ``` [15:35:21] crius:~% cdist-hpc config -vv localhost INFO: cdist: version 9.9.9 INFO: localhost: Running global explorers INFO: localhost: Running global explorers sequentially INFO: localhost: Running initial manifest /tmp/tmp6c_zk1fi/421aa90e079fa326b6494f812ad13e79/data/conf/manifest/init INFO: localhost: Iteration in sequential mode INFO: localhost: Running manifest and explorers for __file/tmp/cdist-was-here INFO: localhost: Generating code for __file/tmp/cdist-was-here INFO: localhost: Executing code for __file/tmp/cdist-was-here INFO: localhost: Running manifest and explorers for __cdist_config_version/ INFO: localhost: Iteration in sequential mode INFO: localhost: Running manifest and explorers for __file/etc/cdist-config-versions INFO: localhost: Generating code for __file/etc/cdist-config-versions INFO: localhost: Generating code for __cdist_config_version/ INFO: localhost: Iteration in sequential mode INFO: localhost: Finished successful run in 3.506462335586548 seconds INFO: cdist: Total processing time for 1 host(s): 3.5103187561035156 ``` Most of those INFO's are actually there to follow the code flow as it runs. For me TRACE is the best name for this. INFO would be natural/logical for the messages that actually INFORM the user about something usefull: e.g. hey dude: we just changed the state of your file /tmp/foobar on host some.target.host If I run the same in debug mode I get 1000 lines of output. For 2 objects. ``` [22:08:23] crius:~% cdist-hpc config -vvv localhost DEBUG: cdist: Namespace(beta=False, command='config', conf_dir=None, debug=False, dry_run=False, func=<bound method Config.commandline of <class 'cdist.config.Config'>>, host=['localhost'], hostfile=None, jobs=None, manifest=None, out_path=None, parallel=False, remote_copy=None, remote_exec=None, remote_out_path=None, verbose=3) INFO: cdist: version 9.9.9 DEBUG: cdist: Base root path for target host "localhost" is "/tmp/tmp3k9ygy3q/421aa90e079fa326b6494f812ad13e79" DEBUG: localhost: remote_exec for host "localhost": ssh -o User=root -o ControlPath=/tmp/tmp3_bj01rz/s -o ControlMaster=auto -o ControlPersist=10 DEBUG: localhost: remote_copy for host "localhost": scp -o User=root -o ControlPath=/tmp/tmp3_bj01rz/s -o ControlMaster=auto -o ControlPersist=10 DEBUG: localhost: derived host_name for host "localhost": localhost.localdomain DEBUG: localhost: derived host_fqdn for host "localhost": localhost.localdomain DEBUG: localhost: target_host: ('localhost', 'localhost.localdomain', 'localhost.localdomain') DEBUG: localhost: Local mkdir: /tmp/tmp3k9ygy3q/421aa90e079fa326b6494f812ad13e79/data DEBUG: localhost: Local mkdir: /tmp/tmp3k9ygy3q/421aa90e079fa326b6494f812ad13e79/data/conf DEBUG: localhost: Local mkdir: /tmp/tmp3k9ygy3q/421aa90e079fa326b6494f812ad13e79/data/explorer ``` ... several more Local mkdir's ``` DEBUG: localhost: Checking conf_dir /home/sar/vcs/cdist/cdist/conf ... DEBUG: localhost: Linking /home/sar/vcs/cdist/cdist/conf/explorer/memory to /tmp/tmp3k9ygy3q/421aa90e079fa326b6494f812ad13e79/data/conf/explorer/memory ... DEBUG: localhost: Linking /home/sar/vcs/cdist/cdist/conf/explorer/lsb_release to /tmp/tmp3k9ygy3q/421aa90e079fa326b6494f812ad13e79/data/conf/explorer/lsb_release ... DEBUG: localhost: Linking /home/sar/vcs/cdist/cdist/conf/explorer/interfaces to /tmp/tmp3k9ygy3q/421aa90e079fa326b6494f812ad13e79/data/conf/explorer/interfaces ... DEBUG: localhost: Linking /home/sar/vcs/cdist/cdist/conf/explorer/runlevel to /tmp/tmp3k9ygy3q/421aa90e079fa326b6494f812ad13e79/data/conf/explorer/runlevel ... ``` ... 170 more lines Linking ... ``` DEBUG: localhost: Checking conf_dir /home/sar/.cdist ... DEBUG: localhost: Checking conf_dir ... DEBUG: localhost: Linking /home/sar/files/lorem to /tmp/tmp3k9ygy3q/421aa90e079fa326b6494f812ad13e79/data/conf/files/lorem ... ``` ... again 30 lines of Linking ``` DEBUG: localhost: Checking conf_dir /home/sar/.cdist-hpc ... DEBUG: localhost: Linking /home/sar/.cdist-hpc/explorer/init-system to /tmp/tmp3k9ygy3q/421aa90e079fa326b6494f812ad13e79/data/conf/explorer/init-system ... ``` ... another 380 lines of Linking ``` DEBUG: localhost: Linking emulator: /home/sar/.virtualenvs/cdist/bin/cdist to /tmp/tmp3k9ygy3q/421aa90e079fa326b6494f812ad13e79/data/bin/__zfs ... ``` ... and another 300 or so lines of Linking emulator ``` DEBUG: localhost: Object marker .cdist-xiufkxhx saved in /tmp/tmp3k9ygy3q/421aa90e079fa326b6494f812ad13e79/data/object_marker DEBUG: localhost: Remote rmdir: /var/lib/cdist DEBUG: localhost: Remote run: ['ssh', '-o', 'User=root', '-o', 'ControlPath=/tmp/tmp3_bj01rz/s', '-o', 'ControlMaster=auto', '-o', 'ControlPersist=10', 'localhost', 'rm', '-rf', '/var/lib/cdist'] DEBUG: localhost: Remote stdout: b'' DEBUG: localhost: Remote mkdir: /var/lib/cdist DEBUG: localhost: Remote run: ['ssh', '-o', 'User=root', '-o', 'ControlPath=/tmp/tmp3_bj01rz/s', '-o', 'ControlMaster=auto', '-o', 'ControlPersist=10', 'localhost', 'mkdir', '-p', '/var/lib/cdist'] DEBUG: localhost: Remote stdout: b'' ``` and another 500 lines or so for remote rmdir/mkdir transfer, exec ... All the 'Linking foo to bar' and 'linking emulator' messages are just useless noise. We have tests to verify that the code works. If it can link one emulator the same code will also be able to link the other 500. And if it fails for one, we have exceptions for that. All the Remote run: 'long string of code' are also just noise. Sometimes usefull to have to troubleshoot a very specific problem. But for a initial debug - useless.

ungleich-gitea commented

2021-11-20 15:44:02 +00:00

Created by: asteven

@telmich there is nothing wrong with creating custom logging levels. What the end user cares about is INFO (the new one) and ERROR. Everything else is basically just for us/internal use. We can do whatever we want with our logging. After all this is totally self contained within cdist.

*Created by: asteven* @telmich there is nothing wrong with creating custom logging levels. What the end user cares about is INFO (the new one) and ERROR. Everything else is basically just for us/internal use. We can do whatever we want with our logging. After all this is totally self contained within cdist.

ungleich-gitea commented

2021-11-20 15:44:04 +00:00

Created by: telmich

ok with me

*Created by: telmich* ok with me

ungleich-gitea commented

2021-11-20 15:44:05 +00:00

Created by: darko-poljak

@asteven @telmich The following?

ERROR = 40 (cdist level -1)
WARNING = 30 (cdist level 0, default - for simplicity for now WARNING and ERROR are united in lowest and default level)
INFO = 20 (cdist level 1, -v)
DEBUG = 10 (cdist level 2, -vv)
TRACE = 5 (cdist level 3, -vvv)

*Created by: darko-poljak* @asteven @telmich The following? ERROR = 40 (cdist level -1) WARNING = 30 (cdist level 0, default - for simplicity for now WARNING and ERROR are united in lowest and default level) INFO = 20 (cdist level 1, -v) DEBUG = 10 (cdist level 2, -vv) TRACE = 5 (cdist level 3, -vvv)

ungleich-gitea commented

2021-11-20 15:44:06 +00:00

Created by: darko-poljak

@telmich There is no TRACE log level. I would also remove VERBOSE_INFO and add only TRACE.

*Created by: darko-poljak* @telmich There is no TRACE log level. I would also remove VERBOSE_INFO and add only TRACE.

ungleich-gitea commented

2021-11-20 15:44:07 +00:00

Created by: telmich

Just my 2 cent: if python already defines 5 log levels, I suggest to use them.

I don't see an advantage in creating custom levels - prove me wrong, but simplicity usually wins.

*Created by: telmich* Just my 2 cent: if python already defines 5 log levels, I suggest to use them. I don't see an advantage in creating custom levels - prove me wrong, but simplicity usually wins.

ungleich-gitea commented

2021-11-20 15:44:09 +00:00

Created by: darko-poljak

@asteven

I would do it in this order, to go with convention (e.g. TRACE is finer-grained than DEBUG).
I also took inspiration from nping
https://nmap.org/book/nping-man-output-options.html

ERROR = 40 (cdist level -1, -v-1)
WARNING = 30 (cdist level 0, default, -v0)
INFO = 20 (cdist level 1, -v, -v1)
VERBOSE_INFO = 15 (cdist level 2, -vv, -v2)
DEBUG = 10 (cdist level 3, -vvv, -v3)
TRACE = 5 (cdist level 4, -vvvv, -v4)

So we can change -v parameter to -v[<level>].
-v alone increases level to INFO, and so on.
Or leave it as is with no way to turn WARNING off and only go with ERROR.
But I know only for one WARN currently in use: if lookup for host name and fqdn fails or
has no result.

*Created by: darko-poljak* @asteven I would do it in this order, to go with convention (e.g. TRACE is finer-grained than DEBUG). I also took inspiration from nping https://nmap.org/book/nping-man-output-options.html ERROR = 40 (cdist level -1, -v-1) WARNING = 30 (cdist level 0, default, -v0) INFO = 20 (cdist level 1, -v, -v1) VERBOSE_INFO = 15 (cdist level 2, -vv, -v2) DEBUG = 10 (cdist level 3, -vvv, -v3) TRACE = 5 (cdist level 4, -vvvv, -v4) So we can change -v parameter to `-v[<level>]`. -v alone increases level to INFO, and so on. Or leave it as is with no way to turn WARNING off and only go with ERROR. But I know only for one WARN currently in use: if lookup for host name and fqdn fails or has no result.

Sign in to join this conversation.