jdk http client wire logging improvements

[xenoterracide]

So this has been a pain to figure out. I need to go add an SO answer I think. looks like the minimum is:

in gradle or maven, doesn't look like application.properties will pick it up. Could this be changed

tasks.withType<Test>().configureEach {
  systemProperty("jdk.httpclient.HttpClient.log", "all") // all propbably isn't what I want, but I get output
}

if using log4j add (maybe this could be added to the starter) log4j-jpl

set this regardless of what the root logger is set to. Note: not having it is a sensible default, but it's not intuitive that if the root logger is set to info that this isn't.

logging.level.jdk.httpclient=info

would be good, imho, to improve documentation around this at the minimum, but perhaps other changes could happen too.

[philwebb]

Sorry @xenoterracide, I'm having a hard time following the description. Can you clarify the problem your having?

[xenoterracide]

@philwebb basically figuring out how to do wire logging with the jdk implementation is a pain, and requires several non obvious and not so google-able steps. I think there may be a code improvement or two that spring boot could take.

Add jpl to the log4j2 starter (is this also needed for slf4j?)
Is it possible to support setting jdk.httpclient.HttpClient.log in "application.properties"? otherwise document build tools...
and document the need to set logging.level.jdk.httpclient=info

[philwebb]

Ahh OK. I think I get it. The HttpClient is part of the JDK so presumable uses java platform logging to actually log stuff. There's a system property called jdk.httpclient.HttpClient.log (documented here) that you can use to turn on more log messages.

Add jpl to the log4j2 starter (is this also needed for slf4j?)

Quite possibly. We have org.apache.logging.log4j:log4j-jul and org.slf4j:jul-to-slf4j but they're for java.util.logging not java platform logging.

and document the need to set logging.level.jdk.httpclient=info

I guess this is needed because of some limitation with the log4j-jpl bridge. You're saying that even if INFO is enabled on the root logger, you also need to explicitly enable it on jdk.httpclient?

[philwebb]

Looks like https://github.com/qos-ch/slf4j/tree/master/slf4j-jdk-platform-logging might be what we want.

[xenoterracide]

maybe, although if you're using log4j the artifact is log4j-jpl it's already available in the dependency list, just not added in the log4j starter. Unless the plan would be to jlp -> jul -> slf4j -> log4j in my case... (note: I was told that jlp might already proxy through jul, but I'm not certain of that...).

There's a system property called jdk.httpclient.HttpClient.log (documented here) that you can use to turn on more log messages.

yes, but... as far as I know you can't set that in application.properties. I tried. I'm not certain that can be changed. Otherwise maybe documenting, or linking the official would be nice.

I guess this is needed because of some limitation with the log4j-jpl bridge. You're saying that even if INFO is enabled on the root logger, you also need to explicitly enable it on jdk.httpclient?

yes, or at least logging.level.jdk=info but probably better to be explicit. I think this is a sane default, but it was surprising to me. I really don't know why though. The log4j documentation doesn't mention it.

[wilkinsona]

As described in the JEP for the Platform Logging API, platform logging is routed into JUL by default. We already have things set up to route JUL into Logback of Log4j2 so it should work out of the box with Boot's default logging configuration. Some experimentation shows this to be the case with both Logback and Log4j2. With -Djdk.httpclient.HttpClient.log=all set, copious amounts of INFO level logging is produced by the jdk.httpclient.HttpClient logger.

When log4j-jpl is on the classpath, JUL is taken out of the picture for Platform Logging and it's routed directly into Log4j2 instead. This also works for me with only the system property set – I haven't seen a need to set the level of the jdk.httpclient.HttpClient logger.

Similar to log4j-jpl and Log4j2, when using Logback and slf4j-jdk-platform-logging, JUL is taken out of the picture for platform logging. In this case it's routed into SLF4J and from there on into Logback. This too works for me when only setting the system property to enable the JDK HTTP client's logging.

As far as I can tell, the only thing that has to be done here is to turn on the HTTP client's logging and things will then work as expected. I'm not sure that we should document how to turn on the HTTP client's logging as it's a JDK feature that's already described in the javadoc since Java 20 and in the developer guide since at least Java 17. Furthermore, Boot itself only has minimal support for Framework's JdkClientHttpRequestFactory and it won't be used by default with a Boot-built RestTemplate or RestClient. As such, if this is to be documented anywhere in addition to the JDK's own documentation, I think Framework would be a better place.

Beyond this, would could consider adding slf4j-jdk-platform-logging and log4j-jpl to the relevant logging starters. This wouldn't change much, if anything, in terms of functionality, but it should make logging slightly more efficient as it will no longer be routed through JUL and will, instead, go straight into SLF4J or Log4j2.

[xenoterracide]

When log4j-jpl is on the classpath, JUL is taken out of the picture for Platform Logging and it's routed directly into Log4j2 instead. This also works for me with only the system property set – I haven't seen a need to set the level of the jdk.httpclient.HttpClient logger.

I've been getting this consistently... and I just figured out why. I was seeing info logs, so I thought they were enabled, turns out it's the "we can't disable these before application.properties" is parsed issue. Another profile was disabling them.

Similar to log4j-jpl and Log4j2, when using Logback and slf4j-jdk-platform-logging, JUL is taken out of the picture for platform logging. In this case it's routed into SLF4J and from there on into Logback. This too works for me when only setting the system property to enable the JDK HTTP client's logging.

so... I thought I tested removing this... I'm not certain how, but it is working without this change. this is on my list of gradle cache somewhere, potential for Idea screwing it up high if I only tested through Idea's gradle runner.

-Djdk.httpclient.HttpClient.log=all

is it impossible to make a change to set this this via application.properties? it can be set after the jvm is started. I think that would be a great improvement.

package org.example.jdkhttpclient;

import static org.assertj.core.api.Assertions.assertThat;

import java.net.http.HttpClient;
import org.junit.jupiter.api.Test;
import org.springframework.beans.factory.ObjectFactory;
import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.boot.test.context.SpringBootTest;
import org.springframework.boot.test.context.TestConfiguration;
import org.springframework.boot.test.web.server.LocalServerPort;
import org.springframework.context.annotation.Bean;
import org.springframework.context.annotation.Lazy;
import org.springframework.http.HttpStatus;
import org.springframework.http.client.JdkClientHttpRequestFactory;
import org.springframework.web.client.RestClient;

@SpringBootTest(webEnvironment = SpringBootTest.WebEnvironment.RANDOM_PORT)
class JdkHttpClientApplicationTests {
  
  static {
    System.setProperty("jdk.httpclient.HttpClient.log", "all");
  }

  @Autowired
  ObjectFactory<RestClient> oauthTestClient;

  @Test
  void contextLoads() {
    var greeting = oauthTestClient.getObject().get().uri("/").retrieve().toEntity(JdkHttpClientApplication.Greeting.class);

    assertThat(greeting.getStatusCode()).isEqualTo(HttpStatus.OK);
  }

  @TestConfiguration
  static class TestConfig {

    @Bean
    @Lazy
    RestClient oauthTestClient(@LocalServerPort int port) {
      return RestClient.builder()
        .requestFactory(
          new JdkClientHttpRequestFactory(HttpClient.newBuilder().followRedirects(HttpClient.Redirect.NEVER).build())
        )
        .baseUrl("http://localhost:" + port)
        .build();
    }
  }

}

[wilkinsona]

-Djdk.httpclient.HttpClient.log=all

is it impossible to make a change to set this this via application.properties

It's not impossible, but I'm also not sure it's something that we should do.

I don't think we'd want to hardcode knowledge of jdk.httpclient.HttpClient.log. There are many system properties that someone might want to set and it doesn't feel scalable to hardcode knowledge of them into Boot. One option to avoid hardcoding would be to do something like Gradle does with systemProp.* values in gradle.properties and transfer the value of something like systemProp.jdk.httpclient.HttpClient.log in the Spring environment to the jdk.httpclient.HttpClient.log system property.

One problem with this approach is that not all system properties will work unless they're present when the JVM's launched. Gradle avoids this to some extent when it forks its daemon and can control its command line but we do not have that option.

There's also Boot's relaxed binding and support for things like environment variables to consider. We wouldn't be able to turn something like systemProp.jdk.httpclient.http-client.log or SYSTEM_PROP_JDK_HTTPCLIENT_HTTP_CLIENT_LOG into the intended System property. We already have this problem with spring.jpa.hibernate.properties.* that trips people up from time to time.

Let's see what the outcome of the team's discussion is.

[philwebb]

We discussed this today and we don't think setting the system property from application.properties is something we should do. It seems like the other items in this issue have been solved as well so I'm going to close this one.