Java HttpClient - reducing debug output

Question

I need to load test an application we've been developing, but our console log is constantly spammed with output. From earlier experience, I've learnt that System.out.println( ) is a relatively expensive operation, so I would like to reduce the printing to a minimum.

The printing only occurs when the application attempts a Http-post, but we do 100s of them per second. We use Apache's HttpClient 4.5.2 and HttpCore 4.4.5. The application runs on Tomcat 7.

I've tried a lot of different solutions: removing the Tomcat valves, setting the Tomcat logging level, setting -Djavax.net.debug=none, but nothing seems to remove this. Does anyone know what causes these outputs, and how do I turn them off?

The debug output is shown bellow:

2016-10-11 15:24:42,942 DEBUG [http-bio-8080-exec-3] Connection request: [route: {}->http://localhost:8080][total kept alive: 0; route allocated: 0 of 200; total allocated: 0 of 200]
2016-10-11 15:24:42,956 DEBUG [http-bio-8080-exec-3] Connection leased: [id: 0][route: {}->http://localhost:8080][total kept alive: 0; route allocated: 1 of 200; total allocated: 1 of 200]
2016-10-11 15:24:42,958 DEBUG [http-bio-8080-exec-3] Connecting to localhost:8080
2016-10-11 15:24:42,978 DEBUG [http-bio-8080-exec-3] CookieSpec selected: best-match
2016-10-11 15:24:42,994 DEBUG [http-bio-8080-exec-3] Auth cache not set in the context
2016-10-11 15:24:42,995 DEBUG [http-bio-8080-exec-3] Target auth state: UNCHALLENGED
2016-10-11 15:24:42,996 DEBUG [http-bio-8080-exec-3] Proxy auth state: UNCHALLENGED
2016-10-11 15:24:42,996 DEBUG [http-bio-8080-exec-3] Attempt 1 to execute request
2016-10-11 15:24:42,997 DEBUG [http-bio-8080-exec-3] Sending request: POST /XtService/account/getbalance HTTP/1.1
2016-10-11 15:24:42,997 DEBUG [http-bio-8080-exec-3] >> "POST /XtService/account/getbalance HTTP/1.1[\r][\n]"
2016-10-11 15:24:42,999 DEBUG [http-bio-8080-exec-3] >> "Content-Length: 48[\r][\n]"
2016-10-11 15:24:42,999 DEBUG [http-bio-8080-exec-3] >> "Content-Type: application/x-www-form-urlencoded; charset=UTF-8[\r][\n]"
2016-10-11 15:24:43,000 DEBUG [http-bio-8080-exec-3] >> "Host: localhost:8080[\r][\n]"
2016-10-11 15:24:43,000 DEBUG [http-bio-8080-exec-3] >> "Connection: Keep-Alive[\r][\n]"
2016-10-11 15:24:43,000 DEBUG [http-bio-8080-exec-3] >> "User-Agent: Apache-HttpClient/4.2 (java 1.5)[\r][\n]"
2016-10-11 15:24:43,000 DEBUG [http-bio-8080-exec-3] >> "[\r][\n]"
2016-10-11 15:24:43,001 DEBUG [http-bio-8080-exec-3] >> POST /XtService/account/getbalance HTTP/1.1
2016-10-11 15:24:43,001 DEBUG [http-bio-8080-exec-3] >> Content-Length: 48
2016-10-11 15:24:43,001 DEBUG [http-bio-8080-exec-3] >> Content-Type: application/x-www-form-urlencoded; charset=UTF-8
2016-10-11 15:24:43,001 DEBUG [http-bio-8080-exec-3] >> Host: localhost:8080
2016-10-11 15:24:43,001 DEBUG [http-bio-8080-exec-3] >> Connection: Keep-Alive
2016-10-11 15:24:43,001 DEBUG [http-bio-8080-exec-3] >> User-Agent: Apache-HttpClient/4.2 (java 1.5)
2016-10-11 15:24:43,001 DEBUG [http-bio-8080-exec-3] >> "categoryid=2"
2016-10-11 15:24:43,256 DEBUG [http-bio-8080-exec-3] << "HTTP/1.1 200 OK[\r][\n]"
2016-10-11 15:24:43,259 DEBUG [http-bio-8080-exec-3] << "Server: Apache-Coyote/1.1[\r][\n]"
2016-10-11 15:24:43,260 DEBUG [http-bio-8080-exec-3] << "Pragma: no-cache[\r][\n]"
2016-10-11 15:24:43,260 DEBUG [http-bio-8080-exec-3] << "Cache-Control: no-cache[\r][\n]"
2016-10-11 15:24:43,260 DEBUG [http-bio-8080-exec-3] << "Expires: Thu, 01 Jan 1970 00:00:00 GMT[\r][\n]"
2016-10-11 15:24:43,261 DEBUG [http-bio-8080-exec-3] << "Content-Type: application/json;charset=utf-8[\r][\n]"
2016-10-11 15:24:43,261 DEBUG [http-bio-8080-exec-3] << "Content-Length: 83[\r][\n]"
2016-10-11 15:24:43,261 DEBUG [http-bio-8080-exec-3] << "Date: Tue, 11 Oct 2016 13:24:43 GMT[\r][\n]"
2016-10-11 15:24:43,261 DEBUG [http-bio-8080-exec-3] << "[\r][\n]"
2016-10-11 15:24:43,262 DEBUG [http-bio-8080-exec-3] Receiving response: HTTP/1.1 200 OK
2016-10-11 15:24:43,262 DEBUG [http-bio-8080-exec-3] << HTTP/1.1 200 OK
2016-10-11 15:24:43,263 DEBUG [http-bio-8080-exec-3] << Server: Apache-Coyote/1.1
2016-10-11 15:24:43,263 DEBUG [http-bio-8080-exec-3] << Pragma: no-cache
2016-10-11 15:24:43,263 DEBUG [http-bio-8080-exec-3] << Cache-Control: no-cache
2016-10-11 15:24:43,263 DEBUG [http-bio-8080-exec-3] << Expires: Thu, 01 Jan 1970 00:00:00 GMT
2016-10-11 15:24:43,263 DEBUG [http-bio-8080-exec-3] << Content-Type: application/json;charset=utf-8
2016-10-11 15:24:43,263 DEBUG [http-bio-8080-exec-3] << Content-Length: 83
2016-10-11 15:24:43,263 DEBUG [http-bio-8080-exec-3] << Date: Tue, 11 Oct 2016 13:24:43 GMT
2016-10-11 15:24:43,265 DEBUG [http-bio-8080-exec-3] Connection can be kept alive for 10000 MILLISECONDS
2016-10-11 15:24:43,274 DEBUG [http-bio-8080-exec-3] << "{"status":1,"data":{"RESERVED":569.81}}"
2016-10-11 15:24:43,275 DEBUG [http-bio-8080-exec-3] Connection [id: 0][route: {}->http://localhost:8080] can be kept alive for 10000 MILLISECONDS
2016-10-11 15:24:43,275 DEBUG [http-bio-8080-exec-3] Connection released: [id: 0][route: {}->http://localhost:8080][total kept alive: 1; route allocated: 1 of 200; total allocated: 1 of 200]

You could have a look at : hc.apache.org/httpcomponents-client-ga/logging.html. Nutshell : find which logging implementation is used (e.g. log4J ?), find its config file, and reduce the org.apache.http(.wire) categories. — GPI
– GPI, Commented Oct 11, 2016 at 14:49
Ah, there we had it. Log4J was configured to output wire-debug to console. I've been struggling with this for about two hours now. Thank you. I recommend you post an actual answer so I can tick it :-) — Gikkman
– Gikkman, Commented Oct 11, 2016 at 14:54

GPI · Accepted Answer · 2016-10-11 18:43:22Z

You could have a look at : http://hc.apache.org/httpcomponents-client-ga/logging.html.

Therefore HttpClient utilizes the logging interface provided by the Commons Logging package. Commons Logging provides a simple and generalized log interface to various logging packages. By using Commons Logging, HttpClient can be configured for a variety of different logging behaviours. That means the user will have to make a choice which logging framework to use. By default Commons Logging supports the following logging frameworks:
- Log4J
- java.util.logging
- SimpleLog (internal to Commons Logging)

The vast majority of the output you observe is actually the "wire" logging (that is, the actual HTTP trafic) :

The wire log is used to log all data transmitted to and from servers when executing HTTP requests. The wire log uses the org.apache.http.wire logging category. This log should only be enabled to debug problems, as it will produce an extremely large amount of log data.

In a nutshell : find which logging implementation is used (e.g. log4J ?), find its config file, and reduce the org.apache.http(.wire) categories

Collectives™ on Stack Overflow

Java HttpClient - reducing debug output

1 Answer 1

Comments

Your Answer

Hot Network Questions

Collectives™ on Stack Overflow

1 Answer 1

Comments

Your Answer

Sign up or log in

Post as a guest

Related