spring.mvc.log-resolved-exception gets enabled by default.

[cdprete]

Hi.
I'm using Spring Boot 2.6.3 and from the moment I've defined a ResponseEntityExceptionHandler I get an annoying warning log in the console of the type WARN 7072 --- [nio-8080-exec-2] .m.m.a.ExceptionHandlerExceptionResolver : Resolved [<fully-qualified-class-name>: <message>].

The handler is the following:

/**
 * @author Cosimo Damiano Prete
 * @since 09/02/2022
 */
@ControllerAdvice
class WebServiceExceptionHandler extends ResponseEntityExceptionHandler {

    @Valid
    @ExceptionHandler(ClientHttpException.class)
    public ResponseEntity<Object> handleClientHttpException(ClientHttpException ex, WebRequest request) {
        return handleExceptionInternal(ex, ErrorResponse.fromClientHttpException(ex), new HttpHeaders(), ex.statusCode(), request);
    }

    private record ErrorResponse(String code, String defaultMessage) {
        private static <E extends ClientHttpException> ErrorResponse fromClientHttpException(E ex) {
            return new ErrorResponse(ex.clientCode(), ex.getMessage());
        }
    }
}

By putting a breakpoint in the setter of WebMvcProperties I can see it actually gets called with the value true even though I don't have such value set at all in my application.yml file.
Strangely enough, if I explicitly set it to false then it stays like that (probably my props are applied later).

The issue doesn't seem to be caused by the ResponseEntityExceptionHandler, since I get the same also when the handler is defined as

/**
 * @author Cosimo Damiano Prete
 * @since 09/02/2022
 */
@ControllerAdvice
class WebServiceExceptionHandler {

    @ExceptionHandler(ClientHttpException.class)
    ResponseEntity<ErrorResponse> handleClientHttpException(ClientHttpException ex) {
        return new ResponseEntity<>(ErrorResponse.fromClientHttpException(ex), ex.statusCode());
    }

    private record ErrorResponse(String code, String defaultMessage) {
        private static <E extends ClientHttpException> ErrorResponse fromClientHttpException(E ex) {
            return new ErrorResponse(ex.clientCode(), ex.getMessage());
        }
    }
}

I've also tried adding an @Order annotation with highest priority (so that it would trigger my advice first), but it didn't help.

[scottfrederick]

Thanks for the report. I haven't been able to reproduce the resolver handler logging by default with a trivial sample using the code snippets you've provided. It's possible there is other configuration in your application that isn't shown here. If you would like us to spend more time investigating, please provide a complete minimal sample that reproduces the problem. You can share it with us by pushing it to a separate repository on GitHub or by zipping it and attaching it to this issue.

[cdprete]

Hi. My entire configuration is composed by the following 3 files:

application.yaml

spring:
  liquibase.change-log: db/changelog/db.changelog-master.xml
  jpa:
    open-in-view: false
  data.web.pageable:
    one-indexed-parameters: true
    max-page-size: 500
  jackson.default-property-inclusion: non_null
server:
  shutdown: graceful
  servlet:
    jsp.registered: false
    context-path: /p-b

application-dev.yaml (active)

spring.datasource:
  driver-class-name: org.h2.Driver
  url: jdbc:h2:mem:pb-db;DB_CLOSE_ON_EXIT=FALSE

spring.properties

spring.jndi.ignore=true

Also, I'm not setting anything programmatically apart

/**
 * @author Cosimo Damiano Prete
 * @since 31/01/2022
 */
@Configuration
@EnableTransactionManagement
@EnableJpaAuditing(
        auditorAwareRef = PersistenceConfig.AUDITOR_AWARE_BEAN_NAME,
        dateTimeProviderRef = PersistenceConfig.DATE_TIME_PROVIDER_BEAN_NAME
)
public class PersistenceConfig {
    static final String AUDITOR_AWARE_BEAN_NAME = "auditorAware";
    static final String DATE_TIME_PROVIDER_BEAN_NAME = "dateTimeProvider";

    @Bean(name = AUDITOR_AWARE_BEAN_NAME)
    AuditorAware<String> auditorAware() {
        return () -> Optional.of("tbd");
    }

    @Bean(name = DATE_TIME_PROVIDER_BEAN_NAME)
    DateTimeProvider dateTimeProvider() {
        return () -> Optional.of(OffsetDateTime.now(Clock.systemUTC()));
    }
}

and my main class is just

@SpringBootApplication
public class PBApplication {
    public static void main(String[] args) {
        SpringApplication.run(PBApplication.class, args);
    }
}

[scottfrederick]

@cdprete I still l can't reproduce the issue with the information provided. There are additional libraries in your application and possibly other code that isn't shown, and it's not a good use of our time to try to re-create everything you are doing. As requested, please provide a sample demonstrating the problem that we can compile and run ourselves.

[wilkinsona]

@cdprete Are you using DevTools? It enables logging of resolved exceptions by default:

spring-boot/spring-boot-project/spring-boot-devtools/src/main/java/org/springframework/boot/devtools/env/DevToolsPropertyDefaultsPostProcessor.java

Line 73 in 067a8dd

properties.put("spring.mvc.log-resolved-exception", "true");

The complete sample that Scott has requested a couple of times would have answered this definitively.

[cdprete]

Hi @wilkinsona.
Yes, I do have DevTools enabled.
I'll test this later and notify you if removing the dev tools resolves the issue. If it doesn't solve the issue, I'll try to anonymize the code so that I can post it as example.

That said, I think this should properly be documented ;)

[wilkinsona]

There's already a section in the reference docs about DevTools' property defaults, including a link to the class to which I linked above. #29406 is tracking inlining the default properties in the documentation in place of the link to DevToolsPropertyDefaultsPostProcessor.

[cdprete]

HI.
I've sent an invitation both of you @scottfrederick and @wilkinsona for accessing the repository :)
Even if I remove the dependency to the devtools, the issue remains.
Moreover, the DB_CLOSE_ON_EXIT=FALSE seems to be ignored, but maybe they have different causes...

[wilkinsona]

Thanks for the access to the repository. Unfortunately, it doesn't reproduce the behaviour that you have described. With the dependency on DevTools in place, I can see that org.springframework.boot.autoconfigure.web.servlet.WebMvcProperties.setLogResolvedException(boolean) is called with true as expected. When I remove the dependency on DevTools, the method is no longer called and the default of false is used.

If you'd like us to spend any more time on this, we'll need a sample that reproduces the problem that you have described. It should also be as minimal as possible to reproduce your specific problem. It took me some time to get your sample to run as I had to, for example, update the DB configuration. I'm afraid I won't have time to look at such an unnecessarily complex sample next time.

[cdprete]

Hi.
How did you exactly remove the dependency to the dev tools? Just from the pom.xml?

[wilkinsona]

Yes. I removed it from the pom.xml, double-checked that my IDE had updated the classpath to remove the dependency, and then ran the application again.

[cdprete]

That's very strange...
I created a new project to test this and I cannot reproduce the behaviour. I think I need to check all the dependencies or so.

For what concern the DB, the warning is

2022-02-11 18:45:46.144  WARN 14476 --- [ionShutdownHook] o.s.b.f.support.DisposableBeanAdapter    : Invocation of destroy method failed on bean with name 'inMemoryDatabaseShutdownExecutor': org.h2.jdbc.JdbcSQLNonTransientConnectionException: Database is already closed (to disable automatic closing at VM shutdown, add ";DB_CLOSE_ON_EXIT=FALSE" to the db URL) [90121-200]

but it happens only with the devtools enabled.

[wilkinsona]

DevTools automatically shuts down the database on each restart (close of the context) to ensure that it can then be recreated and any schema.sql and data.sql scripts can be applied. In other words, the warning you are seeing is to be expected (and is benign) given your configuration and use of DevTools.

[cdprete]

In my "example", I was able to narrow down the issue further.
The infamous log happens only on the form-data multipart request.

org.springframework.web.servlet.handler.AbstractHandlerExceptionResolver#resolveException gets called 3 times and on the third time doResolveException returns an empty but not null ModelAndView.
Then, org.springframework.web.servlet.handler.AbstractHandlerExceptionResolver#logException on line 149 is called which does the logging.

[wilkinsona]

If you can provide a minimal sample that reproduces that behaviour, we can take another look. It should be something that's as small as possible to reproduce the problem and include a test or some simple instructions that show how to do so.

[cdprete]

@wilkinsona the demo is here https://github.com/cdprete/github_spring_boot_issue_29706

[wilkinsona]

Thanks for the minimal sample. Unlike in your original description, the exception is being logged by DefaultHandlerExceptionResolver:

2022-02-11 20:47:35.281  WARN 81983 --- [nio-8080-exec-1] .w.s.m.s.DefaultHandlerExceptionResolver : Resolved [org.springframework.http.converter.HttpMessageNotReadableException: JSON parse error: Cannot coerce empty String ("") to `com.cdprete.demo.DemoDto$DemoEnum` value (but could if coercion was enabled using `CoercionConfig`); nested exception is com.fasterxml.jackson.databind.exc.InvalidFormatException: Cannot coerce empty String ("") to `com.cdprete.demo.DemoDto$DemoEnum` value (but could if coercion was enabled using `CoercionConfig`)<EOL> at [Source: (PushbackInputStream); line: 1, column: 23] (through reference chain: com.cdprete.demo.DemoDto["values"]->java.util.ArrayList[0]->com.cdprete.demo.DemoDto$DemoInnerDto["value"])]

log-resolved-exception property is working as documented:

Whether to enable warn logging of exceptions resolved by a "HandlerExceptionResolver", except for "DefaultHandlerExceptionResolver".

See #14936 for some additional details.

You may want to add an @ExceptionHandler for HttpMessageNotReadableException to customize its exception handling and avoid this logging.

[cdprete]

Oh, that's true. The handler is different.
Then it had to be the DevTools :)

Thanks for the feedbacks ;)