35

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?

Bobulous
  • 12,967
  • 4
  • 37
  • 68
Abhijit Sarkar
  • 21,927
  • 20
  • 110
  • 219
  • 1
    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.) – chrylis -cautiouslyoptimistic- Nov 08 '18 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. https://www.youtube.com/watch?v=BornfFsSlc8 or https://www.youtube.com/watch?v=lAW_NhJ3kqs – pavel Nov 13 '18 at 12:44
  • 3
    @pavel You must be looking at a different one than [this](https://docs.oracle.com/en/java/javase/11/docs/api/java.net.http/java/net/http/HttpClient.html) javadoc; if that’s “good”, your expectations are pretty low. And webcasts are a weak excuse for good documentation. – Abhijit Sarkar Nov 13 '18 at 18:39
  • @AbhijitSarkar, you might be mistaking javadoc for a tutorial/guide/manual. Please define documentation. – pavel Nov 13 '18 at 19:03
  • @pavel how about “useful”, aka “something other than hello world”? – Abhijit Sarkar Nov 13 '18 at 20:00

3 Answers3

34

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
Darwin
  • 4,686
  • 2
  • 30
  • 22
daniel
  • 2,665
  • 1
  • 8
  • 18
  • 8
    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. – Abhijit Sarkar Nov 09 '18 at 21:29
  • 1
    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 – Mike Slinn Jul 08 '19 at 16:35
  • 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! – Abhijit Sarkar Jul 16 '20 at 02:53
  • The possible values for jdk.httpclient.HttpClient.log are mentioned in jdk11 source code in the the class jdk.httpclient.HttpClient.log.Log.java – user674669 Dec 24 '20 at 14:46
  • NOTE: DNS requests are not being logged. To see DNS requests, this tool seems to be handy: http://www.genady.net/dns/ (I have not found any easier to use. Please add comment if there is something nice) – Lubo Feb 28 '22 at 06:18
13

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)
...
Karol Dowbecki
  • 43,645
  • 9
  • 78
  • 111
  • I've been looking at that too. Does it use JUL? In that case, I can bridge it to SLF4J. – Abhijit Sarkar Nov 08 '18 at 20:16
  • It will depend on [System.LoggerFinder](https://docs.oracle.com/javase/9/docs/api/java/lang/System.LoggerFinder.html) – Karol Dowbecki Nov 08 '18 at 20:18
  • 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 `java.logging@11.0.1`, so I guess, the answer to my question "yes it uses JUL unless you mess with it". :) – Abhijit Sarkar Nov 08 '18 at 20:25
  • 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. – Abhijit Sarkar Nov 09 '18 at 03:21
  • 1
    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. – daniel Jan 12 '21 at 18:08
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() {
  }

}
Born2Smile
  • 2,918
  • 1
  • 18
  • 20
  • 1
    I like this, but it's not entirely correct. You need to capture _all_ incoming items via `onNext` and only log them within `onComplete` – Eugene Apr 16 '20 at 17:56
  • 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 – Maxime Carbonneau-Leclerc Apr 17 '20 at 19:38
  • 1
    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`. – Eugene Apr 17 '20 at 19:40
  • My understanding is the same, yes. Thanks for making it explicit! – Maxime Carbonneau-Leclerc Apr 17 '20 at 19:47
  • 2
    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. – daniel Jan 12 '21 at 18:06