Should "job.log" include literally everything?

[clebergnu]

While working on #4547, where it's suggested that a different logging names (such as tasks) be used for enabling/disabling specific information I came across a few problems.

While my PoC version works in the sense that you can include information to be shown on the command line, say:

$ avocado --show=avocado.core.task run --test-runner=nrunner /bin/true 
avocado.core.task: Initialized: <Worker spawner="<avocado.plugins.spawners.process.ProcessSpawner object at 0x7f1dcc119a50>" max_triaging=8 max_running=1 task_timeout=None>
avocado.core.task: Task "1-/bin/true": requested -> triaging
avocado.core.task: Task "1-/bin/true": requirements OK
avocado.core.task: Task "1-/bin/true": triaging -> ready
avocado.core.task: Task "1-/bin/true": started OK
avocado.core.task: Task "1-/bin/true": ready -> started
avocado.core.task: Task "1-/bin/true": started -> finished (FINISHED)

What I find annoying is that, because of job.output.loglevel and the current approach of including everything into the job logger (and thus into job.log), this debugging information would always be included in the job.log file.

I thought of a few solutions to this, including:

1. Changing the default job.output.loglevel value to INFO (instead of DEBUG)
2. Adding explicit filters (so that everything matching, say avocado.core, would not be shown show by default)

The problem with 1 is it would impact tests doing logging.debug(). But, given the proposed behavior for job.log and nrunner to not duplicate the test's log content into the job's log, I can look into separating this distinction. What I mean is that the test would remain at a DEBUG log level, while the job would be bumped to INFO.

The problem with 2 is that it would add exception scenarios, which are both hard to understand and maintain.

Anyway, any feedback and further ideas are appreciated here. Thanks!

[richtja]

Hi @clebergnu, I don't see a problem here. My opinion is that this should be inside the job.log file, because it is important information about Task lifecycle. But if we decided that it's not necessary to have it there, I would create child logger of job logger and set Logger.propagate to false based on the show attribute.

[willianrampazzo]

I like option 1. I find, just like you, annoying that Avocado's default log level is DEBUG on that file.

Maybe, an extension to your idea is to separate the log streams in job.info and job.debug files. This will still make the content go to the files, but we can use some flag to enable or disable it. As I see the use of some kind of debug mechanism increasing on the development side, separating the stream would make it easier to debug.

[willianrampazzo]

and after I replied I saw this: https://github.com/avocado-framework/avocado/pull/4557/files#diff-6d198b466ed62e97a52e92fc4b39533b040cc421a4c0e0352dafe07140c79a18R70-R78

:D

[beraldoleal]

1. Changing the default job.output.loglevel value to INFO (instead of DEBUG)

I don' t see a problem here even with the drawbacks. If tests are doing logging.debug() this means that is debugging only and IMO is safe to turn off debug by default.

2. Adding explicit filters (so that everything matching, say avocado.core, would not be shown show by default)

Not sure here. I would prefer to change core log messages that should not be shown to debug messages and use option 1.

One constant complaint that we have today, it that is not straightforward to find errors in our logs. So I have a feeling that splitting this file or removing stuff from there is going to make this even worst.

So, in summary, I'm moving some non-critical messages to debug (i.e core/development related) and disable debug by default.

[pevogam]

This seems at least partially related to #4564 where we discussed what to include in the job.log.

I have a few questions regarding the first proposal (setting the log level to INFO):

1. Where do we store debug information about a test then? It is still available in the test's own debug.log, correct?
2. We might have different understandings about what debug means but on the VT side and some of our tests that set up entire networks of vms that could take many minutes, having debugging information once a test completes is essential for not having to rerun the test again just to see the information it would have originally collected. If we want some information not to be included in the job.log can't we simply use log level <10 like 9 or lower?