Skip to content
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

[java] reduce log noise at FINE level #12866

Merged
merged 5 commits into from
Oct 6, 2023
Merged

[java] reduce log noise at FINE level #12866

merged 5 commits into from
Oct 6, 2023

Conversation

titusfortner
Copy link
Member

@titusfortner titusfortner commented Oct 4, 2023

Description

  • Change W3CHttpResponseCodec.decode() & DumpHttpExchangeFilter log level to FINER
  • Add PrintPage & fullPageScreenshot to the list of commands that does not log the response (since they are all base64 encoded responses)
  • NEW_SESSION responses are parsed with Capabilities.toString()

Motivation and Context

  • RemoteWebDriver logs most of the important information and intelligently removes responses with Base64 encoded values; W3CHttpResponseCodec.decode & DumpHttpExchangeFilter do not add much information and they destroy the logs.
  • NEW_SESSION response can have Base64 values; the Capabilities classes have a complicated parser to truncate nested values that are > 100 characters. We should use that in the responses as well. I was going to put this behind webdriver.remote.shorten_log_messages system property, but if you want the full values, people can switch to FINEST.

So, this is the first time I realized we have Debug.getDebugLogLevel().

  1. I don't think I like magically toggling FINER messages to INFO when anyone runs anything in debug mode. Really feels like we should let users do the more Java thing here. Who is this for? Why not just set the logging output for the user if they request it? Or set this in our tests instead of all of Selenium?
  2. How about a system property of selenium.webdriver.logger.level?
  3. If we do use this, we should be using it everywhere we are otherwise using FINER

@codecov-commenter
Copy link

codecov-commenter commented Oct 4, 2023

Codecov Report

All modified lines are covered by tests ✅

Comparison is base (4f0ddb2) 56.51% compared to head (55878d5) 56.51%.
Report is 1 commits behind head on trunk.

❗ Current head 55878d5 differs from pull request most recent head ce5d9ff. Consider uploading reports for the commit ce5d9ff to get more accurate results

❗ Your organization needs to install the Codecov GitHub app to enable full functionality.

Additional details and impacted files
@@           Coverage Diff           @@
##            trunk   #12866   +/-   ##
=======================================
  Coverage   56.51%   56.51%           
=======================================
  Files          86       86           
  Lines        5255     5255           
  Branches      187      187           
=======================================
  Hits         2970     2970           
  Misses       2098     2098           
  Partials      187      187           

☔ View full report in Codecov by Sentry.
📢 Have feedback on the report? Share it here.

@pujagani
Copy link
Contributor

pujagani commented Oct 5, 2023

The changes made here, based on the motivation look good to me.
I don't think I understand "I don't think I like magically toggling FINER messages to INFO". How are we doing that? If we are doing this, then I agree with you that it should be in user's control.

@titusfortner
Copy link
Member Author

titusfortner commented Oct 5, 2023

So, for instance, we use getDebugLogLevel() in many places in the code (e.g., BiDi Connection)

This looks to see if the code is being run in debug mode (e.g. IntelliJ debugger), or if system properties are set — https://github.com/SeleniumHQ/selenium/blob/selenium-4.13.0/java/src/org/openqa/selenium/internal/Debug.java#L35

If those conditions are true, it automatically assigns the level for the logs to INFO instead of FINEhttps://github.com/SeleniumHQ/selenium/blob/selenium-4.13.0/java/src/org/openqa/selenium/internal/Debug.java#L47

In some respects I like that it makes it easy to get logs.

Telling users to add:

System.setProperty("selenium.debug", "true")

Is easier than asking them to follow: https://www.selenium.dev/documentation/webdriver/troubleshooting/logging/

But it's ... unexpected and a little creepy. I knew we were auto turning on more logging when the tests were run, I thought it was in our test code, not in Selenium itself. I can see wanting to debug my test code without having all the Selenium noise (especially when running via Server). But also, most Java devs aren't used to JUL, so we aren't doing the most common thing, either.

Really we need to use getDebugLogLevel() everywhere or nowhere instead of mixing like we have now.

@titusfortner titusfortner added this to the 4.14 milestone Oct 5, 2023
@pujagani
Copy link
Contributor

pujagani commented Oct 6, 2023

Thank you for elaborating. I appreciate that. I understand this better and agree with you. Maybe we can track this as a separate issue.

@pujagani
Copy link
Contributor

pujagani commented Oct 9, 2023

Thank you for explaining it in detail. I agree with your point here. Using it only for the test good makes sense I think.

aguspe pushed a commit to aguspe/selenium that referenced this pull request Oct 22, 2023
* [java] reduce log noise at FINE level

* [java] log new session response as a capability if want shorter log messages

* [java] log dump http exchange filter output at lower level

* [java] always use truncation on new session responses
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

Successfully merging this pull request may close these issues.

3 participants