Inconsistent error logging of thrown exceptions in quarkus-resteasy-reactive-jackson

[AndreasPetersen]

Describe the bug

Exceptions thrown during REST requests with the quarkus-resteasy-reactive-jackson server are inconsistent.

• Unchecked exceptions are logged twice
• Checked exceptions are logged once
• WebApplicationExceptions are not logged at all

With quarkus-resteasy-jackson, the classic REST server, all types of exceptions were logged once.

If I add a ExceptionMapper<WebApplicationException> or @ServerExceptionMapper then I can make a mapper that logs the WebApplicationException. However, this does not work if the WebApplicationException was thrown from a ContainerRequestFilter with a response. Odly enough it works if you throw a WebApplicationException without providing a response:

Response response = Response.status(500).entity("WebApplicationException with responsefrom container request filter").build();
throw new WebApplicationException(response);

Will not produce a log from the ExceptionMapper<WebApplicationException> , whereas:

throw new WebApplicationException("WebApplicationException from container request filter");

will.

Expected behavior

Same behaviour as with RestEasy Classic: Each type of exception is logged exactly once.

Actual behavior

Unchecked exceptions are logged twice

2023-03-17 14:07:01,604 ERROR [io.qua.ver.htt.run.QuarkusErrorHandler] (executor-thread-0) HTTP Request to /unchecked failed, error id: e84f0101-8ca0-413e-926c-ddc56c2fda93-4: java.lang.RuntimeException: unchecked exception
	at org.acme.ExceptionResource.uncheckedException(ExceptionResource.java:16)
	at org.acme.ExceptionResource$quarkusrestinvoker$uncheckedException_55aaa27236a8cdedd4b721513153332cc8d64044.invoke(Unknown Source)
	at org.jboss.resteasy.reactive.server.handlers.InvocationHandler.handle(InvocationHandler.java:29)
	at io.quarkus.resteasy.reactive.server.runtime.QuarkusResteasyReactiveRequestContext.invokeHandler(QuarkusResteasyReactiveRequestContext.java:114)
	at org.jboss.resteasy.reactive.common.core.AbstractResteasyReactiveContext.run(AbstractResteasyReactiveContext.java:145)
	at io.quarkus.vertx.core.runtime.VertxCoreRecorder$14.runWith(VertxCoreRecorder.java:576)
	at org.jboss.threads.EnhancedQueueExecutor$Task.run(EnhancedQueueExecutor.java:2449)
	at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1478)
	at org.jboss.threads.DelegatingRunnable.run(DelegatingRunnable.java:29)
	at org.jboss.threads.ThreadLocalResettingRunnable.run(ThreadLocalResettingRunnable.java:29)
	at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
	at java.base/java.lang.Thread.run(Thread.java:833)

2023-03-17 14:07:01,605 ERROR [org.jbo.res.rea.com.cor.AbstractResteasyReactiveContext] (executor-thread-0) Request failed: java.lang.RuntimeException: unchecked exception
	at org.acme.ExceptionResource.uncheckedException(ExceptionResource.java:16)
	at org.acme.ExceptionResource$quarkusrestinvoker$uncheckedException_55aaa27236a8cdedd4b721513153332cc8d64044.invoke(Unknown Source)
	at org.jboss.resteasy.reactive.server.handlers.InvocationHandler.handle(InvocationHandler.java:29)
	at io.quarkus.resteasy.reactive.server.runtime.QuarkusResteasyReactiveRequestContext.invokeHandler(QuarkusResteasyReactiveRequestContext.java:114)
	at org.jboss.resteasy.reactive.common.core.AbstractResteasyReactiveContext.run(AbstractResteasyReactiveContext.java:145)
	at io.quarkus.vertx.core.runtime.VertxCoreRecorder$14.runWith(VertxCoreRecorder.java:576)
	at org.jboss.threads.EnhancedQueueExecutor$Task.run(EnhancedQueueExecutor.java:2449)
	at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1478)
	at org.jboss.threads.DelegatingRunnable.run(DelegatingRunnable.java:29)
	at org.jboss.threads.ThreadLocalResettingRunnable.run(ThreadLocalResettingRunnable.java:29)
	at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
	at java.base/java.lang.Thread.run(Thread.java:833)

Checked exceptions are logged once

2023-03-17 14:06:57,104 ERROR [org.jbo.res.rea.com.cor.AbstractResteasyReactiveContext] (executor-thread-0) Request failed: java.io.IOException: checked exception
	at org.acme.ExceptionResource.checkedException(ExceptionResource.java:26)
	at org.acme.ExceptionResource$quarkusrestinvoker$checkedException_780ec08352b2210b33877338dd8e247443b2486e.invoke(Unknown Source)
	at org.jboss.resteasy.reactive.server.handlers.InvocationHandler.handle(InvocationHandler.java:29)
	at io.quarkus.resteasy.reactive.server.runtime.QuarkusResteasyReactiveRequestContext.invokeHandler(QuarkusResteasyReactiveRequestContext.java:114)
	at org.jboss.resteasy.reactive.common.core.AbstractResteasyReactiveContext.run(AbstractResteasyReactiveContext.java:145)
	at io.quarkus.vertx.core.runtime.VertxCoreRecorder$14.runWith(VertxCoreRecorder.java:576)
	at org.jboss.threads.EnhancedQueueExecutor$Task.run(EnhancedQueueExecutor.java:2449)
	at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1478)
	at org.jboss.threads.DelegatingRunnable.run(DelegatingRunnable.java:29)
	at org.jboss.threads.ThreadLocalResettingRunnable.run(ThreadLocalResettingRunnable.java:29)
	at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
	at java.base/java.lang.Thread.run(Thread.java:833)

WebApplicationExceptions are not logged at all

Nothing to show here :)

How to Reproduce?

I've added a reproducer with examples here: https://github.com/AndreasPetersen/quarkus-resteasy-reactive-error-logging

It contains three REST endpoints, one for each case. In addition, there is a ExceptionMapper that you can activate by adding @Provider on the class. Likewise, there is are some ContainerRequestFilters throwing exceptions that can be activated by adding @Provider as well.

Output of uname -a or ver

Microsoft Windows [Version 10.0.19044.2604]

Output of java -version

openjdk version "17.0.2" 2022-01-18
OpenJDK Runtime Environment Temurin-17.0.2+8 (build 17.0.2+8)
OpenJDK 64-Bit Server VM Temurin-17.0.2+8 (build 17.0.2+8, mixed mode, sharing)

GraalVM version (if different from Java)

No response

Quarkus version or git rev

2.16.4

Build tool (ie. output of mvnw --version or gradlew --version)

Welcome to Gradle 8.0.2!

Here are the highlights of this release:

• Improvements to the Kotlin DSL
• Fine-grained parallelism from the first build with configuration cache
• Configurable Gradle user home cache cleanup

For more details see https://docs.gradle.org/8.0.2/release-notes.html

---

Gradle 8.0.2

Build time: 2023-03-03 16:41:37 UTC
Revision: 7d6581558e226a580d91d399f7dfb9e3095c2b1d

Kotlin: 1.8.10
Groovy: 3.0.13
Ant: Apache Ant(TM) version 1.10.11 compiled on July 10 2021
JVM: 11.0.17 (Eclipse Adoptium 11.0.17+8)
OS: Windows 10 10.0 amd64

Additional information

No response

[quarkus-bot]

/cc @FroMage (resteasy-reactive), @Sgitario (resteasy-reactive), @evanchooly (kotlin), @geoand (jackson,kotlin,resteasy-reactive), @gsmet (jackson), @stuartwdouglas (resteasy-reactive)

[geoand]

Thanks, I'll have a look

[geoand]

#31975 updated RESTEasy Reactive to be more consistent with logging exceptions.

I do not consider RESTEasy Classic's behavior of logging WebApplicationException the correct default behavior (as these are application triggered exceptions meant to control the HTTP response), so they are logged in debug by default.

[AndreasPetersen]

#31975 updated RESTEasy Reactive to be more consistent with logging exceptions.

I do not consider RESTEasy Classic's behavior of logging WebApplicationException the correct default behavior (as these are application triggered exceptions meant to control the HTTP response), so they are logged in debug by default.

I think that's fair. In our case, we would like to log WebApplicationExceptions as an error. We can do that by providing an ExceptionMapper as shown here. However, like I mentioned, the behaviour here is strangely different depending on whether or not the thrown WebApplicationException was constructed with a Response or not.

Alternatively, would it be possible to control the log level of the new log statement?

[geoand]

Alternatively, would it be possible to control the log level of the new log statement?

Do you mean through a configuration property?

[AndreasPetersen]

Alternatively, would it be possible to control the log level of the new log statement?

Do you mean through a configuration property?

If possible, that would be great

[geoand]

It's possible, but probably best looked at in light of a complete solution for configuring RESTEasy Reactive logging.

Mind opening an issue for that?

[AndreasPetersen]

Mind opening an issue for that?

Sure.

What about the inconsistent ExceptionMapper? I wasn't sure if that was fixed in #31975?

[geoand]

I am not sure that's actually the wrong behavior or not. Does that use case work in RESTEasy Classic?

[geoand]

I see that RESTEasy Classic does invoke the exception mapper, but to be honest that seems weird to me, because it makes the Response carried by the WebApplicationException complete useless...

[geoand]

Reading the spec, I see:

Instances of WebApplicationException and its subclasses MUST be mapped to a response as fol-
lows. If the response property of the exception does not contain an entity and an exception mapping
provider (see Section 4.4) is available for WebApplicationException or the corresponding sub-
class, an implementation MUST use the provider to create a new Response instance, otherwise the
response property is used directly. The resulting Response instance is then processed according to
Section 3.3.3

Now one could argue that this only applies to JAX-RS Resources, not filters, but I still think that what RESTEasy Reactive does makes more sense.

[AndreasPetersen]

Why does the ExceptionMapper map the WebApplicationException when a Response is not passed to its constructor, but not when a Response is passed to its constructor? In the case where they are thrown from a filter with RESTEasy Reactive.

[geoand]

When a Response is provided, it signals that the user has provided the whole response (which recall is the whole idea behind an ExceptionMapper).

[AndreasPetersen]

So the only way to log such WebApplicationExceptions would be to log it before throwing, or the newly introduced log statement here?

[geoand]

Correct