Skip to content

Messages logged when timeouts are active do not respect current log level #5395

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Closed
Snooz82 opened this issue Apr 3, 2025 · 2 comments
Closed

Comments

@Snooz82
Copy link
Member

Snooz82 commented Apr 3, 2025

Hi Peke,

When using BuiltIn().set_log_level("NONE") during a keyword execution in the keyword implementation or in run_keyword of a dynamic library, this has no effect on the logging happening subsequently in that keyword.

Concrete use case is, that i want to set a suite variable in run_keyword when an error happens, but that setting of the variable shall not be logged.
So i set the log level to None and then to the original back, after setting the variable.

Unfortunately the setting of the variable is still being loggen, IF a [Timeout] is in use.

Image

Image

See the Reproduction.zip to do reproduce.

Reproduction.zip

afaik if a timeout is active, the actual keyword call is in a thread and therefore it does not effect the log_level?

@pekkaklarck pekkaklarck added this to the v7.3 milestone Apr 4, 2025
@pekkaklarck pekkaklarck self-assigned this Apr 4, 2025
@pekkaklarck pekkaklarck changed the title Setting Log_Level inside a keyword has no effect if Test Timeout is set. Messages logged when timeouts are active do not respect current log level Apr 4, 2025
@pekkaklarck
Copy link
Member

Interesting bug. The reason why it occurred was this:

  • When using timeouts, logging is delayed to avoid output file corruption (Logging when timeouts are enabled may corrupt output #2839). In practice messages that are logged are stored until the keyword ends and logged only then.
  • Delaying is done by the internal LOGGER object that relays messages to all loggers (output file, console output, listeners, ...).
  • Each individual logger decides what to to with the messages only at the end of the keyword when delayed messages are forwarded to them. At that time the log level can be different to what it was when the messages was logged originally.

Delaying messages makes sense, #2839 had a critical priority for a reason, but the current approach to do that in the central LOGGER makes no sense. The problem that causes #2839 only affects the output file, so we should delay messages there. Then it is easy to first check the log level and store only those messages that should be actually logged.

pekkaklarck added a commit that referenced this issue Apr 30, 2025
Previous messages weren't restored meaning that messages could be
lost. The unused variable also made linters unhappy.

This code attemps to avoid problems with timeouts interrupting writing
to output files. The current code was written to fix #5395 and is
basically a rewrite of the fix for #2839. As #5417 explains, there are
still problems and bigger changes are needed.
@pekkaklarck pekkaklarck marked this as a duplicate of #3336 May 7, 2025
@pekkaklarck
Copy link
Member

This issue had been reported already in 2019 (#3336), but back then I thought fixing it would be much more complicated than it was. The logging related code has been heavily refactored since then and it could be that it would have been harder then, though.

This issue also has exactly the same root cause as #3644 and that problem has now been fixed as well. I'll still add tests to validate that, though.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

2 participants