Skip to content

Change of logging does not work under some conditions #3336

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
skhomuti opened this issue Oct 14, 2019 · 5 comments
Closed

Change of logging does not work under some conditions #3336

skhomuti opened this issue Oct 14, 2019 · 5 comments

Comments

@skhomuti
Copy link

Hello!
We use logging a lot when calling some keywords. Since version 3.1, some of these places have stopped working. I was not able to reproduce the problem with a small example, so please help with finding the cause. I assume the reason may be a change in #2839
image

@pekkaklarck
Copy link
Member

pekkaklarck commented Oct 14, 2019

The fix for #2839 delays logging messages when timeouts are used. I guess it could be possible that log level changes before messages actually are logged. It would require a pretty interesting setup, though, and it might also be pretty complicated to fix. Anyway, cannot really comment more until you can provide a simple executable example demonstrating the issue.

@skhomuti
Copy link
Author

Timeouts are what I missed. Thank. Now a very simple example demonstrates this problem.

test.robot

*** Settings ***
Library    Lib
*** Test Cases ***
Case 1
    [Timeout]    1 min
    Keyword Without Logging

Lib.py

from robot.libraries.BuiltIn import BuiltIn


class Lib:

    def keyword_without_logging(self):
        prev_log_level = BuiltIn().set_log_level('NONE')
        BuiltIn().log('Some info message')
        BuiltIn().set_log_level(prev_log_level)

image

@pekkaklarck
Copy link
Member

The reason this occurs is that messages that are logged during timeouts (after #2839 was fixed) are delayed and forwarded to various loggers (output.xml, syslog, listeners, ...) only after the executed keyword finishes. Loggers have different log levels and make decision about actually logging or not logging messages independently. With the current design loggers make the decision about logging (when timeouts are enabled) after the keyword finishes and the active log level with output.xml may be different than when the message actually was logged by the keyword.

Unfortunately changing this would not be easy. It would basically re-implementing the fix for #2839 so that delaying messages would be moved from our top-level logger to the logger responsible on writing output.xml. Then other loggers would get messages immediately, and the output.xml logger could make the decision about either dropping or delaying the message based on the current log level. Now that I think about this, this would be a better solution to #2839 than the current one. Only the output.xml logger actually needs to delay these messages as the original problem with #2839 was corrupting output.xml. Other loggers, especially listeners, getting messages immediately would be better.

Because the change would be somewhat big, and I don't consider the problem too sever, I cannot promise when I'd have time to fix it. It certainly won't be included into the scope of the already overdue RF 3.2 unless someone else is interested to look at it.

One possible way to avoid this problem would me marking the keyword executing other keywords as "run keyword variant". Unfortunately the API to do so is pretty awkward and the whole functionality isn't too well documented. We have issue #2190 about enhancing the API (and the docs), but although it's scoped for RF 3.2 there's a risk it will still be dropped. That issue ought to contain enough information about that API to test does it help in this case.

@skhomuti
Copy link
Author

I tried using register_run_keyword. This works for a normal keyword call, but in the case of a call from a python function, the behavior remains the same.
A typical use case in our project looks like this:

    def some_keyword(self):
        with ModifyLogLevel('ERROR'):
            methods_with_trash_logs()
        methods_with_useful_logs()

@pekkaklarck
Copy link
Member

This was reported again as #5395. The problem has now been fixed and the fix will be in the forthcoming RF 7.3.

I should have closed the new issue as a duplicate of this issue, but I had totally forgotten about this one. Now that the other is already closed, I think it's best to close this one as its dupe. Anyway, what really matters is that the problems has been finally fixed.

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