Repository navigation
Custom loglevel is not working at keywords "Page Should Contain" and "Page Should Not Contain" #316
Description
For example when using loglevel='DEBUG' in a FAIL case the page source is not printed.
You can see this in test/acceptance/keywords/content_assertions.robot, Page Should Contain With Custom Log Level.
Activity
ombre42 commentedon Aug 22, 2014
I understand the test case may be failing, but did you check the log to see if the source was logged? I would be surprised if it isn't, but not surprised if it is in a different index than the expected for statuschecker. For me it is coming in at index 7 with WebDriver 2.41.0 using a clone of your fork. From the docs, with statuschecker there is no way to say you don't care what the index of the log message is. This is a bit of an architectural problem with this project's acceptance tests that check log messages.
It passes on ff (after changing doc to be LOG 2.1:7 DEBUG REGEXP...) but fails on IE even though it ought to pass - its like the token to make the regexp case insensitive is not working.
IE:
My env: Python 2.7.3 32-bit on Windows 7, RF 2.8.5, WD 2.41.0.
ombre42 commentedon Aug 22, 2014
I decided to give a negative index for the message and it worked! So regardless of how many messages are logged by the underlying code (Selenium or its dependencies), this should match against the last debug message.
-2 because -1 is the traceback that's always there if the keyword failed.-2 because 0 is the traceback and -1 is the FAIL message if the keyword failed. Because the indicies in statuschecker are 1-based, index 0 is -1 in the Python world. I think this must be an undocumented feature.
HelioGuilherme66 commentedon Aug 22, 2014
It seems that you looked for the tests with default loglevel. Those are producing the page source OK. Please see if "Page Should Contain non existing text loglevel=DEBUG" shows the HTML result.
About the regex case sensitiveness, there are no problems here in my Linux env (I changed to HTML and still passes):
LOG 2:1 Current page contains text 'needle'. LOG 4.1:1 REGEXP: (?i)<HTML .*
To compare with your env, I used: Python 2.7.5 64-bit on Windows 7, RF 2.8.5, WD 2.42.1 (also with WD downgraded to 2.41.0) (IEDriver is 32-bit with IE11).
My usual env is: Python 2.7.5 64-bit on Fedora Core 19, RF 2.8.5, WD 2.42.1 (Firefox 31, Chromedriver v2.8.240825, Chrome 36.0.1985.143) (also use remote driver v2.42.2, with Core v2.42.2 for Opera/9.80 (X11; Linux x86_64) Presto/2.12.388 Version/12.16 )
ombre42 commentedon Aug 23, 2014
I think we are having a failure of communication, and I appreciate your effort. I do not see the text
loglevel=DEBUGappear in the file, so I am unsure exactly what you are telling me to try.I cloned your fork and ran
python run_tests.py python ff -t "Page Should Contain With Custom Log Level". The HTML is logged in that scenario, but does fail due to incorrect message index.Are you saying to run the test after altering it, for example to use named arguments instead of positional?
For the message index issue, @eweitz has corrected that in #317
Thanks for telling me the test passes on your machine with all caps - I will investigate that.
In investigating your issue, I did notice that the logging silently fails with an invalid logging level like 'DEBUG' instead of DEBUG. That certainly could be improved.
HelioGuilherme66 commentedon Aug 24, 2014
Now I see why we are having different results!
The default runlevel of run_tests.py is DEBUG. To reproduce the bug you must run like this:
python run_tests.py python ff -t "Page Should Contain With Custom Log Level" -L INFO(In the tests/README.txt I wrote
python run_tests.py python firefox -L INFO, because when I first started to clear the false negative there was a lot of "expected INFO and got DEBUG".)I hope you can reproduce it now (using positional or named loglevel):
KEYWORD: Selenium2Library.Page Should Contain non existing text, loglevel=DEBUG Expand All
Documentation:
Verifies that current page contains
text.Start / End / Elapsed: 20140824 18:18:45.645 / 20140824 18:18:45.668 / 00:00:00.023
18:18:45.668 FAIL Page should have contained text 'non existing text' but did not
ombre42 commentedon Aug 25, 2014
Selenium2Library is logging the page source, but Robot Framework filters out the message because the log level is below the logging level of the execution.
If you have run this at level INFO:
BuiltIn.Log ${EXECDIR} DEBUGthe message does not appear in the test log either.
I do not think that ignoring the argument passed in and automatically increasing the log level to the level RF is running at is a good idea.
If you want the source to be logged at a higher level, you could use a variable to set the loglevel like loglevel=${DEBUG_OR_CURRENT_LEVEL}. This variable could be set on the command line, in a listener or a setup keyword.
I view this as a documentation issue. We should add clarification on this to
Page Should Containsimilar to BuiltIn.Log:Valid levels are TRACE, DEBUG, INFO (default), HTML, and WARN. Messages below the current active log level are ignored.HelioGuilherme66 commentedon Aug 25, 2014
So, the test should be changed to test custom loglevel=HTML or loglevel=WARN.
I think that is an useful feature to have a DEBUG loglevel for a keyword running at INFO.
These two tests are the only ones failing the acceptance tests. Should we change them?
Thanks.
ombre42 commentedon Aug 25, 2014
From what I can see, @eweitz already fixed this test by changing the message index. If you are talking about getting the acceptance tests to pass while running at log level INFO, I do not see the motivation for this. If that's what you mean, could you explain?
HelioGuilherme66 commentedon Aug 26, 2014
I was just trying to get the Travis CI builds green for Selenium2Library. The test is expecting custom loglevel DEBUG (and there are much more tests expecting INFO), if we run with loglevel DEBUG, then we will not be testing the custom loglevel.
This is the original test. You need to decide if the acceptance tests should run in loglevel DEBUG or INFO. I think that INFO is the usual loglevel for most of the S2L users, so we should test in that level.
If you decide to have them in loglevel DEBUG, then, all the post run log checking tests should be adapted. Also the custom loglevel in these two tests should be changed to TRACE, since is lower than the current loglevel (which I disagree in this limitation on custom loglevel).
Hope is clear now.
Thanks.
pekkaklarck commentedon Aug 26, 2014
@HelioGuilherme66, I think tests are run using
--loglevel DEBUGby default to be able to test messages logged on the debug level. Otherwise all those messages would simply be ignored by Robot and couldn't be tested. I think there are even some keywords in the library itself that log something on the debug level, and testing those messages requires using--loglevel DEBUG(orTRACE, but that's an overkill and adds noise). If tests fail when you explicitly use--loglevel INFO, which overrides the default level set byrun_tests.py, it's not a surprise that some tests fail.ombre42 commentedon Aug 26, 2014
Everything pekka said is true. run_tests.py is hard-coded to execute at log level DEBUG. When you override it they way you did, your are causing the loglevel argument to be specified more than once and RF goes by the last one I guess.
You say that you disagree with the current behavior, and I see that it can be undesirable. I would like to know what behavior would be better, because I cannot think of any.
The reason I do not like the idea of automatically increasing the loglevel to the current level if the value of loglevel is below the current is:
If you have ideas on how to improve it please share.
pekkaklarck commentedon Aug 26, 2014
Changing the default level tests use to DEBUG:INFO might actually be a good idea.
HelioGuilherme66 commentedon Aug 26, 2014
Well, let me summarize my thoughts and findings.
In conclusion: TEST CASE: "Page Should Not Contain With Custom Log Level" fails at post log analysis due to the bug of keyword "Page Should Not Contain | text | loglevel=DEBUG" which is not outputting log at DEBUG level.
Sorry for the long text. Below is the test result:
.---
TEST CASE: Page Should Not Contain With Custom Log Level
Full Name: firefox Acceptance Tests.Keywords.Content Assertions.Page Should Not Contain With Custom Log Level
Documentation:
LOG 2.1:1 Page should not have contained text 'needle'
Tags: assertions, Regression
Start / End / Elapsed: 20140826 22:43:34.390 / 20140826 22:43:34.435 / 00:00:00.045
Status: FAIL (critical)
Message: Keyword 'Selenium2Library.Page Should Not Contain' (index 2.1) message 1 has wrong level. Expected: INFO Actual: FAIL
SETUP: resource.Go to Front Page
Start / End / Elapsed: 20140826 22:43:34.391 / 20140826 22:43:34.417 / 00:00:00.026
KEYWORD: Selenium2Library.Go To ${FRONT PAGE}
Documentation:
Navigates the active browser instance to the provided URL.
Start / End / Elapsed: 20140826 22:43:34.392 / 20140826 22:43:34.417 / 00:00:00.025
22:43:34.392 INFO Opening url 'http://localhost:7000/html/'
KEYWORD: BuiltIn.Run Keyword And Expect Error Page should not have contained text 'needle', Page Should Not Contain, needle, DEBUG
Documentation:
Runs the keyword and checks that the expected error occurred.
Start / End / Elapsed: 20140826 22:43:34.418 / 20140826 22:43:34.435 / 00:00:00.017
KEYWORD: Selenium2Library.Page Should Not Contain needle, DEBUG
Documentation:
Verifies the current page does not contain
text.Start / End / Elapsed: 20140826 22:43:34.418 / 20140826 22:43:34.435 / 00:00:00.017
22:43:34.434 FAIL Page should not have contained text 'needle'
pekkaklarck commentedon Aug 27, 2014
@HelioGuilherme66 I looked at the code of the related keywords and I couldn't find anything weird. I don't have time now to actually run the tests (don't have environment setup), but I would be very surprised if
would be buggy. What you need to understand is that if you execute the above using
--loglevel INFO, Robot Framework itself will, as designed, ignore the message logged on DEBUG level. If you execute it using--loglevel DEBUG, likerun_tests.pydoes by default, the message should definitely be there. If you are certain it won't work like that, I can test this myself later.Notice also that the new https://bitbucket.org/robotframework/statuschecker supports REGEXP and GLOB matches with log messages. I assume that the old statuschecker.py script still apparently used by Se2Lib doesn't. That shouldn't really matter in this case, though.
ombre42 commentedon Aug 29, 2014
If you went back to the minimum version of Selenium required, the problem with the indexes should have gone away. Selenium changed their http libraries when becoming Python3 compatible and it change the number of messages logged. The CI build always grabs the latest Selenium from PyPI.
We will just have to adjust the tests as Selenium changes.
We could try and modify the statuschecker so that we optionally ignore position within a keyword, e.g.
LOG 2.1:* REGEXP...I think there is a lot more work to do before we think about doing anything like that. And besides, then we might not notice if there is some radical change to what Selenium is logging.
Anyways, I put a mention in BUILD.rst about this and improved the documentation for Page Should Contain which many of the keywords taking a loglevel argument link to.
pekkaklarck commentedon Aug 29, 2014
If new features are needed to StatusChecker, please report them to https://bitbucket.org/robotframework/statuschecker/. Obviously should then also took this tool into use in Se2Lib instead of the old script. If that is done, should decide do we want to vendor the latest version or let devs install with with pip. Anyway, that's a topic for a separate issue.