45

The HttpClient introduced experimentally in Java 9 is now stable in Java 11, but not surprisingly, very few projects seem to actually use it. Documentation is almost non-existing.

One of the most commons asks while making a HTTP call is logging of request/response. How would you do that using the HttpClient, without of course, logging it manually in every single call? Is there an interceptor mechanism like that offered by all other HTTP clients?

5
  • 2
    That API looks like a catastrophe. It doesn't even have a mockable interface. (Not to mention, as you've observed, the apparent lack of any generalizable interceptor mechanism that's been standard on HTTP clients for 20 years in favor of special-cased top-level interfaces.) Commented Nov 8, 2018 at 19:47
  • It's hard to agree with "Documentation is almost non-existing." First of all, there's a good javadoc full of examples. Secondly, there are bunch of webcasts on youtube from the guys who created it, e.g. youtube.com/watch?v=BornfFsSlc8 or youtube.com/watch?v=lAW_NhJ3kqs Commented Nov 13, 2018 at 12:44
  • 4
    @pavel You must be looking at a different one than this javadoc; if that’s “good”, your expectations are pretty low. And webcasts are a weak excuse for good documentation. Commented Nov 13, 2018 at 18:39
  • @AbhijitSarkar, you might be mistaking javadoc for a tutorial/guide/manual. Please define documentation. Commented Nov 13, 2018 at 19:03
  • @pavel how about “useful”, aka “something other than hello world”? Commented Nov 13, 2018 at 20:00

4 Answers 4

43

You can log request and responses by specifying
-Djdk.httpclient.HttpClient.log=requests on the Java command line.

As for testing/mocking you might want to have a look at the offline test: http://hg.openjdk.java.net/jdk/jdk/file/tip/test/jdk/java/net/httpclient/offline/

Depending on what you are looking to achieve you could use a "DelegatingHttpClient" to intercept and log requests and responses too.

Besides the Java API documentation there's also some high level documentation at http://openjdk.java.net/groups/net/httpclient/index.html

Additional note:

The jdk.httpclient.HttpClient.log property is an implementation specific property whose value is a comma separated list which can be configured on the Java command line for diagnosis/debugging purposes with the following values:

-Djdk.httpclient.HttpClient.log=
       errors,requests,headers,
       frames[:control:data:window:all],content,ssl,trace,channel,all
Sign up to request clarification or add additional context in comments.

5 Comments

What are the possible values for jdk.httpclient.HttpClient.log? How did you find out that argument, is it documented somewhere? Please elaborate in your answer.
The additional note sets the wrong property, should be -Djdk.httpclient.HttpClient.log=errors,requests,headers,frames[:control:data:window:all],content,ssl,trace,channel
Seems like it doesn't log the request/response bodies. I guess if it's a GET request, URL will contain all the parameters but for others, this is pretty useless. Bang up job, Oracle!
The possible values for jdk.httpclient.HttpClient.log are mentioned in jdk11 source code in the the class jdk.httpclient.HttpClient.log.Log.java
NOTE: DNS requests are not being logged. To see DNS requests, this tool seems to be handy: genady.net/dns (I have not found any easier to use. Please add comment if there is something nice)
14

If we look at jdk.internal.net.http.common.DebugLogger source code we can see a few loggers using System.Logger, which in turn will useSystem.LoggerFinder to select the logger framework. JUL is the default choice. The logger names are:

  • jdk.internal.httpclient.debug
  • jdk.internal.httpclient.websocket.debug
  • jdk.internal.httpclient.hpack.debug

They can be enabled by setting them as a system property. For example running with -Djdk.internal.httpclient.debug=true will produce:

DEBUG: [main] [147ms] HttpClientImpl(1) proxySelector is sun.net.spi.DefaultProxySelector@6dde5c8c (user-supplied=false)
DEBUG: [main] [183ms] HttpClientImpl(1) ClientImpl (async) send https://http2.github.io/ GET
DEBUG: [main] [189ms] Exchange establishing exchange for https://http2.github.io/ GET,
     proxy=null
DEBUG: [main] [227ms] PlainHttpConnection(?) Initial receive buffer size is: 43690
DEBUG: [main] [237ms] PlainHttpConnection(SocketTube(1)) registering connect event
DEBUG: [HttpClient-1-SelectorManager] [239ms] SelectorAttachment Registering jdk.internal.net.http.PlainHttpConnection$ConnectEvent@354bf356 for 8 (true)
...

6 Comments

I've been looking at that too. Does it use JUL? In that case, I can bridge it to SLF4J.
It will depend on System.LoggerFinder
From the Javadoc, "The system default LoggerFinder implementation uses java.util.logging as the backend framework when the java.logging module is present.". java --list-modules | grep logging shows [email protected], so I guess, the answer to my question "yes it uses JUL unless you mess with it". :)
I ended up switching to OkHttp because the logs were too verbose to be useful. I’ll accept your answer as it applies to my question. Wish the client design allowed for easily plugging in interceptors - logging everything at debug or nothing at all seems silly.
The -Djdk.internal.httpclient.debug logger is primarily intended for JDK developers who fix bugs in the HttpClient implementation, not for users of the API. I wouldn't recommend anybody else to use it. -Djdk.httpclient.HttpClient.log=errors,requests,headers,frames[:control:data:window:all..],content,ssl,trace,channel is probably more suited for users of the API.
|
7

On our side, we did not find the logging provided by -Djdk.internal.httpclient.debug readable enough. The solution we came up with is to wrap the HttpClient with a decorator that will be able to intercept the calls and provide logging. Here how it somehow looks (should be done not only for send but sendAsync methods) :

public class HttpClientLoggingDecorator extends HttpClient {

  private static final Logger logger = Logger.getLogger(HttpClientLoggingDecorator.class.getName());

  private final HttpClient client;

  ...

  @Override
  public <T> HttpResponse<T> send(HttpRequest req, HttpResponse.BodyHandler<T> responseBodyHandler)
    throws IOException,
      InterruptedException
  {
    subscribeLoggerToRequest(req);

    HttpResponse<T> response = client.send(req, responseBodyHandler);

    logResponse(response);
    return response;
  }

  private void subscribeLoggerToRequest(HttpRequest req) {
    // define a consumer for how you want to log
    // Consumer<String> bodyConsumer = ...;
    if (req.bodyPublisher().isPresent()) {
      req.bodyPublisher().get().subscribe(new HttpBodySubscriber(bodyConsumer)));
    } else {
      bodyConsumer.accept(NO_REQUEST_BODY);
    }
  }

  private <T> void logResponse(HttpResponse<T> response) {
    // String responseLog = ...;
    logger.info(responseLog);
  }

}

And here is the HttpBodySubscriber:

public class HttpBodySubscriber implements Flow.Subscriber<ByteBuffer> {

  private static final long UNBOUNDED = Long.MAX_VALUE;

  private final Consumer<String> logger;

  public HttpBodySubscriber(Consumer<String> logger) {
    this.logger = logger;
  }

  @Override
  public void onSubscribe(Flow.Subscription subscription) {
    subscription.request(UNBOUNDED);
  }

  @Override
  public void onNext(ByteBuffer item) {
    logger.accept(new String(item.array(), StandardCharsets.UTF_8));
  }

  @Override
  public void onError(Throwable throwable) {
  }

  @Override
  public void onComplete() {
  }

}

5 Comments

I like this, but it's not entirely correct. You need to capture all incoming items via onNext and only log them within onComplete
I'm curious about why it is not entirely correct. With the code provided above, it seems to me that we will log every time some data comes in. Also, if we log only in onComplete, would this mean that we would not log in case of error? My impression is that it depends largely on the logging use case and all those solutions might make sense. EDIT: typo
I should have made my point explicit, my bad. We are using multi-part messages, in that case, onNext will be called multiple times for the same request. The ultimate entire request can be seen on onComplete.
My understanding is the same, yes. Thanks for making it explicit!
The -Djdk.internal.httpclient.debug logger is primarily intended for JDK developers who fix bugs in the HttpClient implementation, not for users of the API. I wouldn't recommend anybody else to use it. -Djdk.httpclient.HttpClient.log=errors,requests,headers,frames[:control:data:window:all..],content,ssl,trace,channel is probably more suited for users of the API.
1

In order to get this working with spring boot I had to do a number of things.

First, since I'm logging via log4j2 I needed log4j-jul and log4j-jpl artifacts. If you're not using spring boot additional steps may be required. note: jul is actually in the spring-boot-starter-log4j2 but jpl is not.

libs.versions.toml

[versions]
spring = "3.+"

[libraries]
spring-bom = { module = "org.springframework.boot:spring-boot-dependencies", version.ref = "spring" }
starter-log4j2 = { module = "org.springframework.boot:spring-boot-starter-log4j2" }
log4j-jpl = { module = "org.apache.logging.log4j:log4j-jpl" }
log4j-jul = { module = "org.apache.logging.log4j:log4j-jul" }

The first was I had to enable http client logging via gradle, this doesn't seem to get picked up via application.properties in gradle.

build.gradle.kts

dependencies {
  runtimeOnly(platform(libs.spring.bom))
  runtimeOnly(libs.starter.log4j2)
  testRuntimeOnly(libs.log4j.jpl)
  modules {
    module("org.springframework.boot:spring-boot-starter-logging") {
      replacedBy(
        "org.springframework.boot:spring-boot-starter-log4j2",
        "Use Log4j2 instead of Logback",
      )
    }
  }
}

tasks.withType<Test>().configureEach {
  systemProperty("jdk.httpclient.HttpClient.log", "all")
}

Then, even if your root logger is set to info.

application.properties

logging.level.jdk.httpclient = info

If you aren't using spring boot, gradle, or log4j2 you'll need to change these in different places.

note: I haven't figured out what logs frames but this was confusing

-Djdk.httpclient.HttpClient.log=
       errors,requests,headers,
       frames[:control:data:window:all],content,ssl,trace,channel,all

you can put frames,all or frames:data,all. This needs to be "first" from the looks of the code (or maybe just on a newline), but the code uses startsWith and then it splits on : or uses frames:all by default. using the square brackets like above seems to confuse the parser.

Even with with this set properly frames was never called and I don't understand when it would be enough to know why.

1 Comment

even though it seems like the best answer on the web, HttpClient still doesn't log the request and response body

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge you have read our privacy policy.

Start asking to get answers

Find the answer to your question by asking.

Ask question

Explore related questions

See similar questions with these tags.