Logback does not log ConstraintViolationException in Spring Boot's @ExceptionHandler

Viewed 666

I am doing some validation on a query parameter in my Spring Boot web service. In this case it is a parameter that does not match the regex [0-9]{3}. So in the service method, there is a validation:

@Pattern(regexp="[0-9]{3}") @Valid @RequestParam(value = "AngivelseFrekvensForholdUnderkontoArtKode", required = false) String angivelseFrekvensForholdUnderkontoArtKode

(angivelseFrekvensForholdUnderkontoArtKode is just the name of the query parameter)

I am working on a log manager that basically just prints log messages using logback and slf4j.

I have a writeInternalError(exception) in my log manager class which nicely logs an exception when told to:

public void writeInternalError(Exception exception) {
    logger.error(exception.getClass().getName(), kv("LogType", exception), kv("LogMessage", exception));
}

except for when the ConstraintViolationException is caught by the @ExceptionHandler in my @ControllerAdvice. No errors are shown, and a Spring log is outputted instead of my expected custom log. When I debug, the logger.error() seems to be executed and no errors are shown.

I have made a quick fix method where I manually extract the information of the exception, but I want to use the same logging method for all exceptions:

public void writeTracelog(Exception exception) {
    logger.error(exception.getClass().getName(), kv("LogType", "exception"), kv("ErrorMessage", exception.getMessage()), kv("StackTrace", exception.getStackTrace()));
}

The expected and unexpected logs I get are:

// The Spring log message shown instead of my custom error message:
{
    "@timestamp": "2021-06-10T12:13:40.730+02:00",
    "@version": "1",
    "message": "Resolved [javax.validation.ConstraintViolationException: call29f0dab4A3094a30A1cdE29c01f28af8.angivelseFrekvensForholdUnderkontoArtKode: must match \"[0-9]{3}\"]",
    "logger_name": "org.springframework.web.servlet.mvc.method.annotation.ExceptionHandlerExceptionResolver",
    "thread_name": "http-nio-8082-exec-1",
    "level": "WARN",
    "level_value": 30000
}

// How the log is supposed to look like
{
    "@timestamp": "2021-06-10T14:35:18.257+02:00",
    "@version": "1",
    "message": "javax.validation.ConstraintViolationException",
    "logger_name": "ClsLogManager",
    "thread_name": "http-nio-8082-exec-1",
    "level": "ERROR",
    "level_value": 40000,
    "LogType": "exception",
    "LogMessage": {
        "cause": null,
        "stackTrace": [...],
        "constraintViolations": null,
        "message": "call29f0dab4A3094a30A1cdE29c01f28af8.angivelseFrekvensForholdUnderkontoArtKode: must match \"[0-9]",
        "suppressed": [],
        "localizedMessage": "call29f0dab4A3094a30A1cdE29c01f28af8.angivelseFrekvensForholdUnderkontoArtKode: must match \"[0-9]"
    }
}

When I call writeInternalError() with any other exception, the log is nicely output. I have tried different ways of logging to see what works and what does not as you can see in the handler in the @ControllerAdvice

@ControllerAdvice
public class RestResponseEntityExceptionHandler extends ResponseEntityExceptionHandler {

    @ExceptionHandler(ConstraintViolationException.class)
    protected ResponseEntity<Object> handleConflict(ConstraintViolationException ex, HttpServletRequest request) {
        ...
        // Get the invalid parameter from the ConstraintViolationException

        if (invalidParameter.equalsIgnoreCase("angivelseFrekvensForholdUnderkontoArtKode")) {
            errorMessage = setErrorMessage(request, "422.9", HttpStatus.UNPROCESSABLE_ENTITY.value(), invalidValue);
            clsLogManager.writeTracelog(ex); // Outputs customized unwanted log
            clsLogManager.writeInternalError(new ConstraintViolationException(null)); // Outputs exception in the format I want
            clsLogManager.writeInternalError(ex); // Outputs nothing
            responseEntity = writeToAuditlog(request, inputHeaders, errorMessage); // Outputs an info log as it supposed to

            return responseEntity; // Outputs the ExceptionHandlerExceptionResolver message after the return
        }
        // Do something else in case of another error
    }
}

It looks like the logger cannot handle the exception, but why doesn't it tell me why, in case that is true, and why is the ExceptionHandlerExceptionResolver doing it instead?

Update:

I looked into ExceptionHandlerExceptionResolver as saver suggested, and found out that the log comes from AbstractHandlerExceptionResolver's logException(). My custom logger class' method gets called before logException(), but it still doesn't print anything. Can it be because it is a ConstraintViolationException that contains the field constraintViolations and that the logger does not know how to handle this?

There is a setWarnLogCategory method that I guess I can switch off if I don't want the Spring log. I just can't find out how. The javadocs for logException in AbstractHandlerExceptionResolver indicate that there is a property for this, but I don't know how to set it.

2 Answers

Update:

The issue is in method subAppend(E event) in OutputStreamAppender that class is parent of ConsoleAppender and in line of encoding: byte[] byteArray = this.encoder.encode(event); Encoder tried serialize ConstraintViolationException exception and jackson fails with error: HV000116: getParameterIndex() may only be invoked for nodes of type ElementKind.PARAMETER.

enter image description here

And as result of encoding is empty byte array in case of exception and this is reason why nothing is logged in console. See below:

enter image description here

I don't have a quick fix for that right now.

Old proposal:

I recommend to debug method doResolveHandlerMethodException in ExceptionHandlerExceptionResolver class and you can see there is only one place when spring boot logger can log message with warning level and that logger will work only in case when something happened during invoking handler method for exception (For example: incorrect type of parameter in handler method and so on). You will see the reason why your handler method wasn't called. enter image description here

Please pay attention to case when class ConstraintViolationException can be located in two different packages:

  • javax.validation.ConstraintViolationException
  • org.hibernate.exception.ConstraintViolationException

of course in our case we should use ConstraintViolationException from javax.validation package

Those exceptions are handled in one of the base methods of ResponseEntityExceptionHandler. You need to override it.

Related