tmt icon indicating copy to clipboard operation
tmt copied to clipboard

Silencing the logger output

Open Athwale opened this issue 2 years ago • 14 comments

Hi, there does not seem to be a way of silencing warning messages from tmt in python.

Run the example below in a test directory with main.fmf with a wrong attribute for example "lik" instead of "link" You will get: warn: /Sanity/experimental-test-will-be-removed-please-ignore-this-case: - 'lik' does not match any of the regexes: '^extra- Despite all attempts at disabling output.'

#!/bin/python3

import tmt
import fmf
import logging

logger = tmt.log.Logger.create()
logger.quiet = True
logger._logger.setLevel(logging.ERROR)
tree = tmt.Tree(tree=fmf.Tree('.'), logger=logger)

for test in tree.tests(logger=logger):
    print(test)

Athwale avatar May 23 '23 11:05 Athwale

Hi @Athwale, is is okay if we use an environment variable to disable the logger output? For example, we add TMT_LOGGER_OUTPUT_ENABLED to tmt, and its default value is true. If it is set as false by user, the warning messages from tmt will be discarded.

idorax avatar May 31 '23 00:05 idorax

I think I know why this doesn't work, it was obvious, yet it took me so much time to find out :/

From tmt.log.Logger._normalize_logger():

    @staticmethod
    def _normalize_logger(logger: logging.Logger) -> logging.Logger:
        ...
        logger.level = logging.DEBUG

Whatever level is set by the user, we set it to DEBUG. For a good reason, though, we need all messages to pass the logger, to get to handlers, because one of the handlers, the one for a logging file, must receive and log all messages. So, filtering by log level on the logger level would not work for us, we probably need to add a filter on the handler level and attach it to the console handler - we still want warnings in a log file, if there's any such file enabled, user just don't want to see them on their terminal.

So it sounds like we have to handle it like we handle quiet, i.e. with a handler-level filter, and drop whatever message is not allowed to be emitted to the console. About that:

@psss what exactly should be the behavior of --quiet? According to its help text, Be quiet. Exit code is just enough for me., that suggests total silence, yet there is print() method that promises to Print a message regardless the quiet mode, which means there are some messages that would get printed out even with --quit. What are these messages, and would errors and warnings fit the definition of this set?

If warnings and errors are supposed to be printed out even with --quiet, then we need something like --total-silence to suppress even warnings and errors. If warnings and errors are not supposed to be printed out with --quiet, then we need to fix our quietness filter to suppress them.

happz avatar May 31 '23 07:05 happz

I want to be able to silence it inside python code which I guess will be a side effect of also having a command line switch for it. If I understand the comments above correctly the environment variable is out of the question and will be replaced with a new switch? Otherwise as long as I can silence it completely from within python either approach works for me.

Athwale avatar Jun 21 '23 08:06 Athwale

This issue is causing a large amount of error output in for example /tests/cockpit/Sanity/upstream-verify-testsuite-wrapper ... warn: /Sanity/upstream-verify-testsuite-wrapper/base/TestUpdates/testUpdateError: - 'plans' does not match any of the regexes: '^extra-' ... Is there still no way of silencing these?

Athwale avatar Aug 31 '23 16:08 Athwale

This issue is causing a large amount of error output in for example /tests/cockpit/Sanity/upstream-verify-testsuite-wrapper ... warn: /Sanity/upstream-verify-testsuite-wrapper/base/TestUpdates/testUpdateError: - 'plans' does not match any of the regexes: '^extra-' ... Is there still no way of silencing these?

Not at this moment, but I can put one together tomorrow, maybe we could squeeze it into 1.27. It should be rather trivial.

happz avatar Aug 31 '23 17:08 happz

Great, thanks.

Athwale avatar Sep 01 '23 10:09 Athwale

Actually, I'm not so sure it's a good idea or a matching solution for the original request. Those warnings are useful, and the original issue is about silencing the logging entirely rather than hiding one kind of logging message.

@psss would you please think about questions raised in https://github.com/teemtee/tmt/issues/2106#issuecomment-1569637401? I can write a --total-silence filter, but the behavior of the code is unclear.

happz avatar Sep 01 '23 10:09 happz

The intention for the --quiet option was to suppress unnecessary informational output. So regarding the exit code is just enough it would be use cases like this:

  • run tests and check if they passed, failed, errored (no output needed)
  • check for existence of a test, plan or story, e.g. tmt test ls --quiet /some/test || tmt test create /some/test...

The print() method is intended for the real output which is always wanted, e.g. tmt test export which does not make any sense without output the exported stuff.

I'd say, that --quiet could cover turning of warnings as well (for the terminal, not for the debug log as @happz mentioned earlier), as it sounds natural to both use cases above: I don't care about any warnings, I just want to know how the things are.

psss avatar Sep 08 '23 16:09 psss

The original problem I still have is that I run the script on dozens or even hundreds of tests. And That produces tens of thousands of lines of output I can not get rid off, even though I do not need that output. In those cases I would run the script once with output enabled and then disable it for example.

Athwale avatar Sep 08 '23 16:09 Athwale

The intention for the --quiet option was to suppress unnecessary informational output. So regarding the exit code is just enough it would be use cases like this:

  • run tests and check if they passed, failed, errored (no output needed)
  • check for existence of a test, plan or story, e.g. tmt test ls --quiet /some/test || tmt test create /some/test...

The print() method is intended for the real output which is always wanted, e.g. tmt test export which does not make any sense without output the exported stuff.

Ok, then I see two issues we should address:

  • print() vs click.echo() - if print() is how tmt is supposed to emit output, then we should replace click.echo() calls with print().
  • print() now sends its messages through the logging subsystem, which is incorrect. If this function is for output, it needs to go to stdout. I'd still like to keep it a member of a Logger instance, but it needs to be fixed to not use logging - I suppose it would call click.echo() under the hood.

I'd say, that --quiet could cover turning of warnings as well (for the terminal, not for the debug log as @happz mentioned earlier), as it sounds natural to both use cases above: I don't care about any warnings, I just want to know how the things are.

I guess the important question boils down to the following: should --quiet apply to both streams tmt sends data to users, stdout for output and stderr for logging (errors, warnings, -vvv...)? Is tmt test export --quiet expected to be completely silent? The original issue seems to be mostly about warnings, IIUIC the fixed --quiet would indeed silence those, but how about the stdout and actual output?

I can make patches to address all the issues mentioned above, no problem, I just want to get it right :)

happz avatar Sep 09 '23 09:09 happz

print() vs click.echo() - if print() is how tmt is supposed to emit output, then we should replace click.echo() calls with print().

Yeap, makes sense to clean this up. Seems that currently click.echo() is used only on three places.

print() now sends its messages through the logging subsystem, which is incorrect. If this function is for output, it needs to go to stdout. I'd still like to keep it a member of a Logger instance, but it needs to be fixed to not use logging - I suppose it would call click.echo() under the hood.

Hm, looks like our Logger.print() method is actually never used in the code. So... if it does not bring any benefits, shall we just drop it instead?

I guess the important question boils down to the following: should --quiet apply to both streams tmt sends data to users, stdout for output and stderr for logging (errors, warnings, -vvv...)? Is tmt test export --quiet expected to be completely silent?

I'd say that tmt test export --quiet should not show any warnings (or additional information about progress or whatever details) but still send the exported data to stdout.

psss avatar Oct 05 '23 08:10 psss

print() vs click.echo() - if print() is how tmt is supposed to emit output, then we should replace click.echo() calls with print().

Yeap, makes sense to clean this up. Seems that currently click.echo() is used only on three places.

Yeah, but echo, imported from click, is called 180 times ;)

print() now sends its messages through the logging subsystem, which is incorrect. If this function is for output, it needs to go to stdout. I'd still like to keep it a member of a Logger instance, but it needs to be fixed to not use logging - I suppose it would call click.echo() under the hood.

Hm, looks like our Logger.print() method is actually never used in the code. So... if it does not bring any benefits, shall we just drop it instead?

I'd fix Logger.print to go to stdout, and replace echo in our codebase with Logger.print. This makes most sense to me: we would own output to both stdout and stderr, having a (thin) wrapper over click.echo would give us a chance to manipulate output as needed, e.g. to honor colorization when composing messages.

I guess the important question boils down to the following: should --quiet apply to both streams tmt sends data to users, stdout for output and stderr for logging (errors, warnings, -vvv...)? Is tmt test export --quiet expected to be completely silent?

I'd say that tmt test export --quiet should not show any warnings (or additional information about progress or whatever details) but still send the exported data to stdout.

Ack, so it's just the logging, and stdout would remain unaffected.

happz avatar Oct 05 '23 08:10 happz

I see something has been merged above. So can I silence the logger now?

Athwale avatar Apr 05 '24 16:04 Athwale

I see something has been merged above. So can I silence the logger now?

Sorry, not yet, the issue fell under the table :( I'll resurrect it, there is still work left to finish.

happz avatar May 06 '24 07:05 happz

This should be covered by #2909.

psss avatar Jul 19 '24 08:07 psss