OpenLiberty / open-liberty

Open Liberty is a highly composable, fast to start, dynamic application server runtime environment
https://openliberty.io
Eclipse Public License 2.0
1.14k stars 587 forks source link

OpenLiberty does not log WebApplicationException containing a Response #27967

Closed Kiiv closed 5 months ago

Kiiv commented 5 months ago

Hi,

don't know if it's the right place to talk about that.

When I throw an Exception like IllegalArgumentException in my application, OpenLiberty log it (several times :p) as we could expect it :

[21/03/24 10:48:55:689 CET] 0000003b com.ibm.ws.webcontainer.util.ApplicationErrorUtils           E SRVE0777E: Exception émise par la classe d'application 'com.test.TestResource.testException:18'
java.lang.IllegalArgumentException
    at com.test.TestResource.testException(TestResource.java:18)
    at com.test.TestResource$Proxy$_$$_WeldClientProxy.testException(Unknown Source)
    at sun.reflect.GeneratedMethodAccessor777.invoke(Unknown Source)
    at java.lang.reflect.Method.invoke(Method.java:498)
    at com.ibm.ws.jaxrs20.cdi.component.JaxRsFactoryImplicitBeanCDICustomizer.serviceInvoke(JaxRsFactoryImplicitBeanCDICustomizer.java:350)
    at com.ibm.ws.jaxrs20.server.LibertyJaxRsServerFactoryBean.performInvocation(LibertyJaxRsServerFactoryBean.java:641)
    at com.ibm.ws.jaxrs20.server.LibertyJaxRsInvoker.performInvocation(LibertyJaxRsInvoker.java:160)
    at org.apache.cxf.service.invoker.AbstractInvoker.invoke(AbstractInvoker.java:101)
    at com.ibm.ws.jaxrs20.server.LibertyJaxRsInvoker.invoke(LibertyJaxRsInvoker.java:273)
    at org.apache.cxf.jaxrs.JAXRSInvoker.invoke(JAXRSInvoker.java:213)
    at com.ibm.ws.jaxrs20.server.LibertyJaxRsInvoker.invoke(LibertyJaxRsInvoker.java:444)
    at org.apache.cxf.jaxrs.JAXRSInvoker.invoke(JAXRSInvoker.java:112)
    at org.apache.cxf.interceptor.ServiceInvokerInterceptor$1.run(ServiceInvokerInterceptor.java:59)
    at org.apache.cxf.interceptor.ServiceInvokerInterceptor.handleMessage(ServiceInvokerInterceptor.java:96)
    at org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:308)
    at org.apache.cxf.transport.ChainInitiationObserver.onMessage(ChainInitiationObserver.java:123)
    at org.apache.cxf.transport.http.AbstractHTTPDestination.invoke(AbstractHTTPDestination.java:277)
    at com.ibm.ws.jaxrs20.endpoint.AbstractJaxRsWebEndpoint.invoke(AbstractJaxRsWebEndpoint.java:137)
    at com.ibm.websphere.jaxrs.server.IBMRestServlet.handleRequest(IBMRestServlet.java:146)
    at com.ibm.websphere.jaxrs.server.IBMRestServlet.doGet(IBMRestServlet.java:112)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:686)
    at com.ibm.websphere.jaxrs.server.IBMRestServlet.service(IBMRestServlet.java:96)
    at com.ibm.ws.webcontainer.servlet.ServletWrapper.service(ServletWrapper.java:1258)
    at com.ibm.ws.webcontainer.servlet.ServletWrapper.handleRequest(ServletWrapper.java:746)
    at com.ibm.ws.webcontainer.servlet.ServletWrapper.handleRequest(ServletWrapper.java:443)
    at com.ibm.ws.webcontainer.filter.WebAppFilterManager.invokeFilters(WebAppFilterManager.java:1227)
    at com.ibm.ws.webcontainer.webapp.WebApp.handleRequest(WebApp.java:5059)
    at com.ibm.ws.webcontainer.osgi.DynamicVirtualHost$2.handleRequest(DynamicVirtualHost.java:316)
    at com.ibm.ws.webcontainer.WebContainer.handleRequest(WebContainer.java:1007)
    at com.ibm.ws.webcontainer.osgi.DynamicVirtualHost$2.run(DynamicVirtualHost.java:281)
    at com.ibm.ws.http.dispatcher.internal.channel.HttpDispatcherLink$TaskWrapper.run(HttpDispatcherLink.java:1199)
    at com.ibm.ws.http.dispatcher.internal.channel.HttpDispatcherLink.wrapHandlerAndExecute(HttpDispatcherLink.java:468)
    at com.ibm.ws.http.dispatcher.internal.channel.HttpDispatcherLink.ready(HttpDispatcherLink.java:427)
    at com.ibm.ws.http.channel.internal.inbound.HttpInboundLink.handleDiscrimination(HttpInboundLink.java:566)
    at com.ibm.ws.http.channel.internal.inbound.HttpInboundLink.handleNewRequest(HttpInboundLink.java:500)
    at com.ibm.ws.http.channel.internal.inbound.HttpInboundLink.processRequest(HttpInboundLink.java:360)
    at com.ibm.ws.http.channel.internal.inbound.HttpInboundLink.ready(HttpInboundLink.java:327)
    at com.ibm.ws.tcpchannel.internal.NewConnectionInitialReadCallback.sendToDiscriminators(NewConnectionInitialReadCallback.java:167)
    at com.ibm.ws.tcpchannel.internal.NewConnectionInitialReadCallback.complete(NewConnectionInitialReadCallback.java:75)
    at com.ibm.ws.tcpchannel.internal.WorkQueueManager.requestComplete(WorkQueueManager.java:514)
    at com.ibm.ws.tcpchannel.internal.WorkQueueManager.attemptIO(WorkQueueManager.java:584)
    at com.ibm.ws.tcpchannel.internal.WorkQueueManager.workerRun(WorkQueueManager.java:968)
    at com.ibm.ws.tcpchannel.internal.WorkQueueManager$Worker.run(WorkQueueManager.java:1057)
    at com.ibm.ws.threading.internal.ExecutorServiceImpl$RunnableWrapper.run(ExecutorServiceImpl.java:245)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:750)

[21/03/24 10:48:55:696 CET] 0000003b com.ibm.ws.webcontainer.webapp                               E SRVE0315E: Une exception s'est produite : java.lang.Throwable: java.lang.IllegalArgumentException
    at com.ibm.ws.webcontainer.webapp.WebApp.handleRequest(WebApp.java:5117)
    at com.ibm.ws.webcontainer.osgi.DynamicVirtualHost$2.handleRequest(DynamicVirtualHost.java:316)
    at com.ibm.ws.webcontainer.WebContainer.handleRequest(WebContainer.java:1007)
    at com.ibm.ws.webcontainer.osgi.DynamicVirtualHost$2.run(DynamicVirtualHost.java:281)
    at com.ibm.ws.http.dispatcher.internal.channel.HttpDispatcherLink$TaskWrapper.run(HttpDispatcherLink.java:1199)
    at com.ibm.ws.http.dispatcher.internal.channel.HttpDispatcherLink.wrapHandlerAndExecute(HttpDispatcherLink.java:468)
    at com.ibm.ws.http.dispatcher.internal.channel.HttpDispatcherLink.ready(HttpDispatcherLink.java:427)
    at com.ibm.ws.http.channel.internal.inbound.HttpInboundLink.handleDiscrimination(HttpInboundLink.java:566)
    at com.ibm.ws.http.channel.internal.inbound.HttpInboundLink.handleNewRequest(HttpInboundLink.java:500)
    at com.ibm.ws.http.channel.internal.inbound.HttpInboundLink.processRequest(HttpInboundLink.java:360)
    at com.ibm.ws.http.channel.internal.inbound.HttpInboundLink.ready(HttpInboundLink.java:327)
    at com.ibm.ws.tcpchannel.internal.NewConnectionInitialReadCallback.sendToDiscriminators(NewConnectionInitialReadCallback.java:167)
    at com.ibm.ws.tcpchannel.internal.NewConnectionInitialReadCallback.complete(NewConnectionInitialReadCallback.java:75)
    at com.ibm.ws.tcpchannel.internal.WorkQueueManager.requestComplete(WorkQueueManager.java:514)
    at com.ibm.ws.tcpchannel.internal.WorkQueueManager.attemptIO(WorkQueueManager.java:584)
    at com.ibm.ws.tcpchannel.internal.WorkQueueManager.workerRun(WorkQueueManager.java:968)
    at com.ibm.ws.tcpchannel.internal.WorkQueueManager$Worker.run(WorkQueueManager.java:1057)
    at com.ibm.ws.threading.internal.ExecutorServiceImpl$RunnableWrapper.run(ExecutorServiceImpl.java:245)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:750)
Caused by: java.lang.IllegalArgumentException
    at com.test.TestResource.testException(TestResource.java:18)
    at com.test.TestResource$Proxy$_$$_WeldClientProxy.testException(Unknown Source)
    at sun.reflect.GeneratedMethodAccessor777.invoke(Unknown Source)
    at java.lang.reflect.Method.invoke(Method.java:498)
    at com.ibm.ws.jaxrs20.cdi.component.JaxRsFactoryImplicitBeanCDICustomizer.serviceInvoke(JaxRsFactoryImplicitBeanCDICustomizer.java:350)
    at com.ibm.ws.jaxrs20.server.LibertyJaxRsServerFactoryBean.performInvocation(LibertyJaxRsServerFactoryBean.java:641)
    at com.ibm.ws.jaxrs20.server.LibertyJaxRsInvoker.performInvocation(LibertyJaxRsInvoker.java:160)
    at org.apache.cxf.service.invoker.AbstractInvoker.invoke(AbstractInvoker.java:101)
    at com.ibm.ws.jaxrs20.server.LibertyJaxRsInvoker.invoke(LibertyJaxRsInvoker.java:273)
    at org.apache.cxf.jaxrs.JAXRSInvoker.invoke(JAXRSInvoker.java:213)
    at com.ibm.ws.jaxrs20.server.LibertyJaxRsInvoker.invoke(LibertyJaxRsInvoker.java:444)
    at org.apache.cxf.jaxrs.JAXRSInvoker.invoke(JAXRSInvoker.java:112)
    at org.apache.cxf.interceptor.ServiceInvokerInterceptor$1.run(ServiceInvokerInterceptor.java:59)
    at org.apache.cxf.interceptor.ServiceInvokerInterceptor.handleMessage(ServiceInvokerInterceptor.java:96)
    at org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:308)
    at org.apache.cxf.transport.ChainInitiationObserver.onMessage(ChainInitiationObserver.java:123)
    at org.apache.cxf.transport.http.AbstractHTTPDestination.invoke(AbstractHTTPDestination.java:277)
    at com.ibm.ws.jaxrs20.endpoint.AbstractJaxRsWebEndpoint.invoke(AbstractJaxRsWebEndpoint.java:137)
    at com.ibm.websphere.jaxrs.server.IBMRestServlet.handleRequest(IBMRestServlet.java:146)
    at com.ibm.websphere.jaxrs.server.IBMRestServlet.doGet(IBMRestServlet.java:112)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:686)
    at com.ibm.websphere.jaxrs.server.IBMRestServlet.service(IBMRestServlet.java:96)
    at com.ibm.ws.webcontainer.servlet.ServletWrapper.service(ServletWrapper.java:1258)
    at com.ibm.ws.webcontainer.servlet.ServletWrapper.handleRequest(ServletWrapper.java:746)
    at com.ibm.ws.webcontainer.servlet.ServletWrapper.handleRequest(ServletWrapper.java:443)
    at com.ibm.ws.webcontainer.filter.WebAppFilterManager.invokeFilters(WebAppFilterManager.java:1227)
    at com.ibm.ws.webcontainer.webapp.WebApp.handleRequest(WebApp.java:5059)
    ... 20 more

But when I throw a WebApplicationException with a Response already set, OpenLiberty does not log anything. Using the same test code but replacing IllegalArgumentException by ForbiddenException, there no information logged by the application server.

I know that ExceptionMapper are not called if the exception already as a Response but I would expect the application server would be able to log this kind of error anyway. For now, there is no stack available to find where this kind of exception occurs.

Tested with a very simple Rest Resource :

@ApplicationScoped
@Path("/testException")
public class TestResource {

  @GET
  public String testException() {
    // throw new ForbiddenException();
    throw new IllegalArgumentException();
  }
}

Do I miss something or is it working as expected ?

Diagnostic information:

jim-krueger commented 5 months ago

I believe what you are experiencing is expected behavior and that CXF intentionally does not log that exception, but maps it to the response. Are you now receiving any information about the exception in the response?

Kiiv commented 5 months ago

Nop, nothing about the original exception is sent in the response. I got only the response code and eventually the entity if I set one by myself in the Response object passed to the ForbiddenException.

jim-krueger commented 5 months ago

Please run with the following trace enabled and attach a zip of the server's logs directory: com.ibm.ws.jaxrs=all:com.ibm.websphere.jaxrs=all:org.apache.cxf.*=all

Kiiv commented 5 months ago

Here you are. Thanks for your support !

logs.zip

jim-krueger commented 5 months ago

Thanks. Can you please confirm that your client is receiving a Response with status code 403? Thanks

Kiiv commented 5 months ago

Yes, I confirm that my client receive a status code 403 as expected.

jim-krueger commented 5 months ago

Hi, After reviewing this and looking a bit in the code I have confirmed that this is functioning as designed. See: CustomExceptionMapperRegister customExceptionMapper.setPrintStackTrace(false); // set to 'false' to avoid printing response errors to Messages.log

This code sets the PrintStackTrace to false for Liberty's default CustomWebApplicationExceptionMapper.

You can work around this by creating your own custom exception mapper for WebApplicationExceptions. Something similar to:

@Provider
public class MyCustomExceptionMapper implements ExceptionMapper<WebApplicationException>  {

    public Response toResponse(WebApplicationException ex) {
        ex.printStackTrace();
        Response r = ex.getResponse();
        return r;
    }
}

Hopefully this helps.

jim-krueger commented 5 months ago

Closing this issue. Please re-open if it requires additional attention.

Kiiv commented 5 months ago

Thanks for your detailed analysis !

I think I'll have to go for a custom WebApplicationExceptionMapper extending your own CustomWebApplicationExceptionMapper to not break your error code mapping.

Kiiv commented 4 months ago

Hi,

I come back to give feedback and discuss one more case.

So, as expected, I was able to add a log message for WebApplicationException by adding a custom ExceptionMapper for them.

Unfortunately, there is a case where the ExceptionMapper is not called. As stated in the Jax-rs specification, if the Response contained in the WebApplicationException already as an entity, the container must not call the ExceptionMapper :

Chapter 3.3.4 of the jax-rs 2.2.1 specification

Instances of WebApplicationException and its subclasses MUST be mapped to a response as follows. 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 subclass, 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.

In that case, I think I can't do anything on my own. It's probably working as expected but I'm very curious about the choice to not log this kind of exception.