Tune Apache Commons HttpClient logs to Dropwizard

Question

I am using Dropwizard, and inside some logic triggering requests through Apache Commons HttpClient.

HttpClient prints out very verbose logs, apparently in DEBUG mode.

I tried setting its log level to be the same as the rest of the app, or at least to set it in a config file so that it be easily overridable by command line.

I failed.

I tried following the different pieces of advice here:

adding a commons-logging.properties file inside a main/resources/... folder, and adding logging.loggers."org.apache.commons.httpclient": "INFO" to Dropwizard config file
passing stuff such as org.apache.commons.logging.Log=org.apache.commons.logging.impl.NoOpLog or log4j.logger.org.apache=WARN as command line properties

Finally I just did the following:

Logger.getLogger("org.apache.commons.httpclient").setLevel(Level.ERROR);
Logger.getLogger("httpclient").setLevel(Level.ERROR);

But I find it bad practice, because it makes it impossible to override this log level by command line.

Has anybody solved this issue?

This question and answer probably will be of interest also: https://stackoverflow.com/questions/45243873/dropwizard-admin-change-loglevel-for-all — zloster, May 03 '19 at 12:09

zloster · Answer 1 · 2019-04-30T15:04:56.907

Dropwizard is using logback and slf4j. I can't find references that logback is supporting the log4j configuration instructions directly.

Now on the question: I have a toy Dropwizard project currently using version 1.3.4. I configure simple resource method to execute a GET against external HTTP address. In the config.yml file I have the following:

logging:
#  level: INFO
  level: DEBUG
  loggers:
    com.gitlab.zloster: DEBUG

This configuration gives me a very verbose DEBUG logging for everything:

DEBUG [2019-04-30 14:30:27,035] org.apache.http.client.protocol.RequestAddCookies: CookieSpec selected: ignoreCookies
DEBUG [2019-04-30 14:30:27,035] org.apache.http.client.protocol.RequestAuthCache: Auth cache not set in the context
DEBUG [2019-04-30 14:30:27,035] com.codahale.metrics.httpclient.InstrumentedHttpClientConnectionManager: Connection request: [route: {s}->https://www.dir.bg:443][total kept alive: 0; route allocated: 0 of 1024; total allocated: 1 of 1024]
DEBUG [2019-04-30 14:30:27,035] com.codahale.metrics.httpclient.InstrumentedHttpClientConnectionManager: Connection leased: [id: 2][route: {s}->https://www.dir.bg:443][total kept alive: 0; route allocated: 1 of 1024; total allocated: 2 of 1024]
DEBUG [2019-04-30 14:30:27,035] org.apache.http.impl.execchain.MainClientExec: Opening connection {s}->https://www.dir.bg:443
DEBUG [2019-04-30 14:30:27,039] org.apache.http.impl.conn.DefaultHttpClientConnectionOperator: Connecting to www.dir.bg/194.145.63.12:443
DEBUG [2019-04-30 14:30:27,039] org.apache.http.conn.ssl.SSLConnectionSocketFactory: Connecting socket to www.dir.bg/194.145.63.12:443 with timeout 500
DEBUG [2019-04-30 14:30:27,053] org.apache.http.conn.ssl.SSLConnectionSocketFactory: Enabled protocols: [TLSv1, TLSv1.1, TLSv1.2]
DEBUG [2019-04-30 14:30:27,053] org.apache.http.conn.ssl.SSLConnectionSocketFactory: Enabled cipher suites:[TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA384, TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA384, TLS_RSA_WITH_AES_256_CBC_SHA256, TLS_ECDH_ECDSA_WITH_AES_256_CBC_SHA384, TLS_ECDH_RSA_WITH_AES_256_CBC_SHA384, TLS_DHE_RSA_WITH_AES_256_CBC_SHA256, TLS_DHE_DSS_WITH_AES_256_CBC_SHA256, TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA, TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA, TLS_RSA_WITH_AES_256_CBC_SHA, TLS_ECDH_ECDSA_WITH_AES_256_CBC_SHA, TLS_ECDH_RSA_WITH_AES_256_CBC_SHA, TLS_DHE_RSA_WITH_AES_256_CBC_SHA, TLS_DHE_DSS_WITH_AES_256_CBC_SHA, TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA256, TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA256, TLS_RSA_WITH_AES_128_CBC_SHA256, TLS_ECDH_ECDSA_WITH_AES_128_CBC_SHA256, TLS_ECDH_RSA_WITH_AES_128_CBC_SHA256, TLS_DHE_RSA_WITH_AES_128_CBC_SHA256, TLS_DHE_DSS_WITH_AES_128_CBC_SHA256, TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA, TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA, TLS_RSA_WITH_AES_128_CBC_SHA, TLS_ECDH_ECDSA_WITH_AES_128_CBC_SHA, TLS_ECDH_RSA_WITH_AES_128_CBC_SHA, TLS_DHE_RSA_WITH_AES_128_CBC_SHA, TLS_DHE_DSS_WITH_AES_128_CBC_SHA, TLS_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384, TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256, TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384, TLS_RSA_WITH_AES_256_GCM_SHA384, TLS_ECDH_ECDSA_WITH_AES_256_GCM_SHA384, TLS_ECDH_RSA_WITH_AES_256_GCM_SHA384, TLS_DHE_RSA_WITH_AES_256_GCM_SHA384, TLS_DHE_DSS_WITH_AES_256_GCM_SHA384, TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256, TLS_RSA_WITH_AES_128_GCM_SHA256, TLS_ECDH_ECDSA_WITH_AES_128_GCM_SHA256, TLS_ECDH_RSA_WITH_AES_128_GCM_SHA256, TLS_DHE_RSA_WITH_AES_128_GCM_SHA256, TLS_DHE_DSS_WITH_AES_128_GCM_SHA256, TLS_ECDHE_ECDSA_WITH_3DES_EDE_CBC_SHA, TLS_ECDHE_RSA_WITH_3DES_EDE_CBC_SHA, SSL_RSA_WITH_3DES_EDE_CBC_SHA, TLS_ECDH_ECDSA_WITH_3DES_EDE_CBC_SHA, TLS_ECDH_RSA_WITH_3DES_EDE_CBC_SHA, SSL_DHE_RSA_WITH_3DES_EDE_CBC_SHA, SSL_DHE_DSS_WITH_3DES_EDE_CBC_SHA, TLS_EMPTY_RENEGOTIATION_INFO_SCSV]
DEBUG [2019-04-30 14:30:27,053] org.apache.http.conn.ssl.SSLConnectionSocketFactory: Starting handshake
DEBUG [2019-04-30 14:30:27,060] org.apache.http.conn.ssl.SSLConnectionSocketFactory: Secure session established
DEBUG [2019-04-30 14:30:27,060] org.apache.http.conn.ssl.SSLConnectionSocketFactory:  negotiated protocol: TLSv1.2
DEBUG [2019-04-30 14:30:27,060] org.apache.http.conn.ssl.SSLConnectionSocketFactory:  negotiated cipher suite: TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384
DEBUG [2019-04-30 14:30:27,060] org.apache.http.conn.ssl.SSLConnectionSocketFactory:  peer principal: CN=*.dir.bg, OU=PositiveSSL Wildcard, OU=Domain Control Validated

If I change the configuration to:

logging:
  level: INFO
#  level: DEBUG
  loggers:
    com.gitlab.zloster: DEBUG

I'm getting very clean log:

INFO  [2019-04-30 14:44:30,742] org.eclipse.jetty.setuid.SetUIDListener: Opened application@44fff386{HTTP/1.1,[http/1.1]}{0.0.0.0:8080}
INFO  [2019-04-30 14:44:30,745] org.eclipse.jetty.server.Server: jetty-9.4.z-SNAPSHOT; built: 2018-05-03T15:56:21.710Z; git: daa59876e6f384329b122929e70a80934569428c; jvm 1.8.0_111-8u111-b14-3~12.04-b14
INFO  [2019-04-30 14:44:31,391] io.dropwizard.jersey.DropwizardResourceConfig: The following paths were found for the configured resources:

    GET     /external (com.gitlab.zloster.resources.ExternalResource)
    GET     /moment (com.gitlab.zloster.resources.MomentResource)
    GET     /validate (com.gitlab.zloster.resources.ValidationResource)
    POST    /validate (com.gitlab.zloster.resources.ValidationResource)

INFO  [2019-04-30 14:44:31,395] org.eclipse.jetty.server.handler.ContextHandler: Started i.d.j.MutableServletContextHandler@44598ef7{/,null,AVAILABLE}
INFO  [2019-04-30 14:44:31,413] org.eclipse.jetty.server.AbstractConnector: Started application@44fff386{HTTP/1.1,[http/1.1]}{0.0.0.0:8080}
INFO  [2019-04-30 14:44:31,414] org.eclipse.jetty.server.Server: Started @2757ms
127.0.0.1 - - [30/Apr/2019:14:44:38 +0000] "GET /external HTTP/1.1" 200 65 "-" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:52.0) Gecko/20100101 Firefox/52.0" 368
127.0.0.1 - - [30/Apr/2019:14:44:40 +0000] "GET /external HTTP/1.1" 200 65 "-" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:52.0) Gecko/20100101 Firefox/52.0" 54
127.0.0.1 - - [30/Apr/2019:14:44:46 +0000] "GET /external HTTP/1.1" 200 65 "-" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:52.0) Gecko/20100101 Firefox/52.0" 63

The code is here: https://gitlab.com/zloster/dropwizard-static/commit/16c3dba9ea46f1223d84f975779aec4876bf4507

Tune Apache Commons HttpClient logs to Dropwizard

1 Answers1