Skip to content

Prevent HttpClient 4.x from spamming the log with DEBUG messages from .wire and .content loggers when using logback-spring.xml #32976

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
OndraZizka opened this issue Nov 2, 2022 · 5 comments

Comments

@OndraZizka
Copy link

OndraZizka commented Nov 2, 2022

Spring Boot 2.7.5
spring-boot-starter-logging 2.7.5

When running tests, HttpClient 4.x in RestTemplate spams the log with so many entries that it makes the test suite fail in GitLab CI.

The setup is quite standard. The project had no extra logging setup until the tries to prevent this issue.
Below are the files on the classpath (a Maven project, in src/main/resources)

Trying different loggers (org.apache.http.headers should be the right one) for the version used by RestTemplate in Framework 5.3)
logback-spring.xml:

    <root level="INFO">        <appender-ref ref="STDERR" />    </root>

    <logger name="org.springframework" level="TRACE"/>
    <logger name="org.apache.hc.client5" level="INFO"/>

    <logger name="org.apache" level="INFO" />
    <logger name="org.apache.http.headers" level="INFO" />
    <logger name="org.apache.http.wire" level="INFO" />
    <logger name="httpclient" level="INFO" />
    <logger name="httpclient.wire.header" level="INFO" />
    <logger name="httpclient.wire.content" level="INFO" />

Trying to set it in a different way:
application.properties:

logging.level.org.apache.http=info
logging.level.org.apache.http.headers=info
logging.level.org.apache.http.content=info

Trying in case httpclient logs through log4j:
log4j.properties:

log4j.logger.httpclient.wire.header=INFO
log4j.logger.httpclient.wire.content=INFO

log4j.logger.org.apache.hc.client5.http.wire=INFO
log4j.logger.http.wire=INFO
log4j.logger.org.apache=WARN
log4j.logger.httpclient=WARN

Trying to change the logger in case httpclient logs through log4j
commons-logging.properties:

org.apache.commons.logging.Log=org.apache.logging.slf4j.SLF4JLogger

But none of this worked. Still, the output is spammed with things like

15:23:52.131 [main] DEBUG org.apache.hc.client5.http.wire - http-outgoing-1 << "[0xfffffff9][0x5][0x4]P[0xffffffd6][0x5]p[0x6]@[0x18][0x0]...

Since I am following the documentation of Spring Boot and Spring Framework regarding logging, these should work.
But primarily, turning this off should be a matter of Spring Boot itself, even programatically, since it uses an obsolete logging library which is not supported since 2020.

Not sure if anyone is going to fix this since Framework 6.x will use HttpClient 5.x, for which the logging configuration works. But it would be great, as this is a blocker.

EDIT Eventually, one thing worked: Renaming logback-spring.xml to logback.xml. It seems that somehow, propagating the config to whatever layer HttpClient uses, needs to happen in the earlier logging setup stage. So that's what needs to be fixed, if possible, or documented, if not.

@spring-projects-issues spring-projects-issues added the status: waiting-for-triage An issue we've not yet triaged label Nov 2, 2022
@OndraZizka OndraZizka changed the title Prevent HttpClient 4.x from spamming the log with DEBUG messages from .wire and .content loggers Prevent HttpClient 4.x from spamming the log with DEBUG messages from .wire and .content loggers when using logback-spring.xml Nov 2, 2022
@wilkinsona
Copy link
Member

Unfortunately, I cannot reproduce the behaviour that you have described. For example, we have smoke tests that use Spring Framework's RestTemplate backed by the Apache HTTP client and no HTTP client related logging is output.

Eventually, one thing worked: Renaming logback-spring.xml to logback.xml

This would suggest that the logging is being performed before the SpringApplication under test has been started. At this time, Logback will use its default configuration which results in everything being logged at debug. A logback-test.xml file in src/test/resources is the recommended way to address this.

If the above does not help and you would like us to spend some more time investigating, please spend some time providing a complete yet minimal sample that reproduces the problem. You can share it with us by pushing it to a separate repository on GitHub or by zipping it up and attaching it to this issue.

@wilkinsona wilkinsona added the status: waiting-for-feedback We need additional information before we can continue label Nov 2, 2022
@OndraZizka
Copy link
Author

Ok, I will investigate more. The @SpringBootTest starts the context and then launches a Browser through Selenium and loads a page and clicks around. Can the scenario you suggest also apply in this situation?
Although: This is happening a CI pipeline and I can't see the whole output as it hits GitLab's limits I can't change, so it's possible that the test setup is affected by something I can't see. I will get back when I know.

@spring-projects-issues spring-projects-issues added status: feedback-provided Feedback has been provided and removed status: waiting-for-feedback We need additional information before we can continue labels Nov 2, 2022
@wilkinsona
Copy link
Member

Can the scenario you suggest also apply in this situation?

No, I don't think so. Logback's defaults only apply until @SpringBootTest starts the context. As part of the context being started, Spring Boot's logging configuration is applied which will set the root log level to info.

@wilkinsona wilkinsona added status: waiting-for-feedback We need additional information before we can continue and removed status: feedback-provided Feedback has been provided labels Nov 2, 2022
@spring-projects-issues
Copy link
Collaborator

If you would like us to look at this issue, please provide the requested information. If the information is not provided within the next 7 days this issue will be closed.

@spring-projects-issues spring-projects-issues added the status: feedback-reminder We've sent a reminder that we need additional information before we can continue label Nov 9, 2022
@spring-projects-issues
Copy link
Collaborator

Closing due to lack of requested feedback. If you would like us to look at this issue, please provide the requested information and we will re-open the issue.

@spring-projects-issues spring-projects-issues removed status: waiting-for-feedback We need additional information before we can continue status: feedback-reminder We've sent a reminder that we need additional information before we can continue status: waiting-for-triage An issue we've not yet triaged labels Nov 16, 2022
@wilkinsona wilkinsona closed this as not planned Won't fix, can't repro, duplicate, stale Nov 16, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

3 participants