Merge stack traces into a single log event in Open Liberty 22.0.0.6-beta

Ryan Storey on May 12, 2022

announcements , release , beta , monitoring ,

Post available in languages:

Open Liberty 22.0.0.6-beta offers one new beta feature (along with all GA features), which provides new logging functionality to join stack traces in logs so that they are output as a single log event.

The Open Liberty 22.0.0.6-beta includes the following beta feature (along with all GA features):

New Logging functionality to join stack traces in logs

New Logging functionality: merge stack traces into a single log event

When a stack trace is logged in Open Liberty, typically from Throwable.printStackTrace() calls from the application, you can now output the emitted stack trace as a single log event. This update is impactful if you forward your logs downstream to third-party log analysis technologies, such as the Elastic Logstash Kibana (ELK) stack. It affects the console output, console logs , messages log and the trace logs. Prior to this update, each line of the stack trace was printed as a separate event.

Examples:

Console output without the stack traces joined:

[err] java.lang.ArithmeticException: divide by zero
[err]   at com.ibm.demo.MyResource.ex(MyResource.java:86)
[err]   at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
[err]   at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
[err]   at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
[err]   at java.base/java.lang.reflect.Method.invoke(Method.java:566)
[err]   at com.ibm.ws.jaxrs20.server.LibertyJaxRsServerFactoryBean.performInvocation(LibertyJaxRsServerFactoryBean.java:656)
[err]   at [internal classes]
[err]   at javax.servlet.http.HttpServlet.service(HttpServlet.java:686)
[err]   at com.ibm.websphere.jaxrs.server.IBMRestServlet.service(IBMRestServlet.java:96)
[err]   at [internal classes]
[err]   at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
[err]   at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
[err]   at java.base/java.lang.Thread.run(Thread.java:831)

Console output with the stack traces joined:

[err] java.lang.ArithmeticException: divide by zero
        at com.ibm.demo.MyResource.ex(MyResource.java:86)
        at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.base/java.lang.reflect.Method.invoke(Method.java:566)
        at com.ibm.ws.jaxrs20.server.LibertyJaxRsServerFactoryBean.performInvocation(LibertyJaxRsServerFactoryBean.java:656)
        at [internal classes]
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:686)
        at com.ibm.websphere.jaxrs.server.IBMRestServlet.service(IBMRestServlet.java:96)
        at [internal classes]
        at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
        at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
        at java.base/java.lang.Thread.run(Thread.java:831)

messages.log output without the stack traces joined:

2022-04-06, 15:50:22:246 EDT] 00000047 SystemErr                                                    R java.lang.ArithmeticException: divide by zero
[2022-04-06, 15:50:22:247 EDT] 00000047 SystemErr                                                    R         at com.ibm.demo.MyResource.ex(MyResource.java:86)
[2022-04-06, 15:50:22:248 EDT] 00000047 SystemErr                                                    R         at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
[2022-04-06, 15:50:22:249 EDT] 00000047 SystemErr                                                    R         at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
[2022-04-06, 15:50:22:250 EDT] 00000047 SystemErr                                                    R         at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
[2022-04-06, 15:50:22:251 EDT] 00000047 SystemErr                                                    R         at java.base/java.lang.reflect.Method.invoke(Method.java:566)
[2022-04-06, 15:50:22:251 EDT] 00000047 SystemErr                                                    R         at com.ibm.ws.jaxrs20.server.LibertyJaxRsServerFactoryBean.performInvocation(LibertyJaxRsServerFactoryBean.java:656)
...

messages.log output with the stack traces joined:

[2022-04-06, 15:52:38:586 EDT] 00000077 SystemErr                                                    R java.lang.ArithmeticException: divide by zero
        at com.ibm.demo.MyResource.ex(MyResource.java:86)
        at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.base/java.lang.reflect.Method.invoke(Method.java:566)
        at com.ibm.ws.jaxrs20.server.LibertyJaxRsServerFactoryBean.performInvocation(LibertyJaxRsServerFactoryBean.java:656)
        ...

messages.log output without the stack traces joined using JSON logging:

{"type":"liberty_message","host":"LAPTOP-JU4FJ7TJ","ibm_userDir":"C:\/devdir\/LibertiesFeb18\/open-liberty\/dev\/build.image\/wlp\/usr\/","ibm_serverName":"sj","message":"java.lang.ArithmeticException: divide by zero","ibm_threadId":"00000034","ibm_datetime":"2022-04-20T13:41:37.605-0400","module":"SystemErr","loglevel":"SystemErr","ibm_methodName":"","ibm_className":"","ibm_sequence":"1650476497605_0000000000069","ext_thread":"Default Executor-thread-2"}
{"type":"liberty_message","host":"LAPTOP-JU4FJ7TJ","ibm_userDir":"C:\/devdir\/LibertiesFeb18\/open-liberty\/dev\/build.image\/wlp\/usr\/","ibm_serverName":"sj","message":"\tat com.ibm.demo.MyResource.ex(MyResource.java:86)","ibm_threadId":"00000034","ibm_datetime":"2022-04-20T13:41:37.616-0400","module":"SystemErr","loglevel":"SystemErr","ibm_methodName":"","ibm_className":"","ibm_sequence":"1650476497616_000000000006A","ext_thread":"Default Executor-thread-2"}
{"type":"liberty_message","host":"LAPTOP-JU4FJ7TJ","ibm_userDir":"C:\/devdir\/LibertiesFeb18\/open-liberty\/dev\/build.image\/wlp\/usr\/","ibm_serverName":"sj","message":"\tat java.base\/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)","ibm_threadId":"00000034","ibm_datetime":"2022-04-20T13:41:37.626-0400","module":"SystemErr","loglevel":"SystemErr","ibm_methodName":"","ibm_className":"","ibm_sequence":"1650476497626_000000000006B","ext_thread":"Default Executor-thread-2"}
...

messages.log output with the stack traces joined using JSON logging:

{"type":"liberty_message","host":"LAPTOP-JU4FJ7TJ","ibm_userDir":"C:\/devdir\/LibertiesFeb18\/open-liberty\/dev\/build.image\/wlp\/usr\/","ibm_serverName":"sj","message":"java.lang.ArithmeticException: divide by zero\r\n\tat com.ibm.demo.MyResource.ex(MyResource.java:86)\r\n\tat java.base\/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)\r\n\tat java.base\/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)\r\n\tat java.base\/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)\r\n\tat java.base\/java.lang.reflect.Method.invoke(Method.java:566)\r\n\tat com.ibm.ws.jaxrs20.server.LibertyJaxRsServerFactoryBean.performInvocation(LibertyJaxRsServerFactoryBean.java:656)\r\n\tat com.ibm.ws.jaxrs20.server.LibertyJaxRsInvoker.performInvocation(LibertyJaxRsInvoker.java:160)\r\n\tat org.apache.cxf.service.invoker.AbstractInvoker.invoke(AbstractInvoker.java:101)\r\n\tat com.ibm.ws.jaxrs20.server.LibertyJaxRsInvoker.invoke(LibertyJaxRsInvoker.java:273)\r\n\tat org.apache.cxf.jaxrs.JAXRSInvoker.invoke(JAXRSInvoker.java:213)\r\n\tat com.ibm.ws.jaxrs20.server.LibertyJaxRsInvoker.invoke(LibertyJaxRsInvoker.java:444)\r\n\tat org.apache.cxf.jaxrs.JAXRSInvoker.invoke(JAXRSInvoker.java:112)\r\n\tat org.apache.cxf.interceptor.ServiceInvokerInterceptor$1.run(ServiceInvokerInterceptor.java:59)\r\n\tat org.apache.cxf.interceptor.ServiceInvokerInterceptor.handleMessage(ServiceInvokerInterceptor.java:96)\r\n\tat org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:308)\r\n\tat org.apache.cxf.transport.ChainInitiationObserver.onMessage(ChainInitiationObserver.java:123)\r\n\tat org.apache.cxf.transport.http.AbstractHTTPDestination.invoke(AbstractHTTPDestination.java:277)\r\n\tat com.ibm.ws.jaxrs20.endpoint.AbstractJaxRsWebEndpoint.invoke(AbstractJaxRsWebEndpoint.java:137)\r\n\tat com.ibm.websphere.jaxrs.server.IBMRestServlet.handleRequest(IBMRestServlet.java:146)\r\n\tat com.ibm.websphere.jaxrs.server.IBMRestServlet.doGet(IBMRestServlet.java:112)\r\n\tat javax.servlet.http.HttpServlet.service(HttpServlet.java:686)\r\n\tat com.ibm.websphere.jaxrs.server.IBMRestServlet.service(IBMRestServlet.java:96)\r\n\tat com.ibm.ws.webcontainer.servlet.ServletWrapper.service(ServletWrapper.java:1258)\r\n\tat com.ibm.ws.webcontainer.servlet.ServletWrapper.handleRequest(ServletWrapper.java:746)\r\n\tat com.ibm.ws.webcontainer.servlet.ServletWrapper.handleRequest(ServletWrapper.java:443)\r\n\tat com.ibm.ws.webcontainer.filter.WebAppFilterManager.invokeFilters(WebAppFilterManager.java:1227)\r\n\tat com.ibm.ws.webcontainer.filter.WebAppFilterManager.invokeFilters(WebAppFilterManager.java:1011)\r\n\tat com.ibm.ws.webcontainer.servlet.CacheServletWrapper.handleRequest(CacheServletWrapper.java:75)\r\n\tat com.ibm.ws.webcontainer40.servlet.CacheServletWrapper40.handleRequest(CacheServletWrapper40.java:85)\r\n\tat com.ibm.ws.webcontainer.WebContainer.handleRequest(WebContainer.java:938)\r\n\tat com.ibm.ws.webcontainer.osgi.DynamicVirtualHost$2.run(DynamicVirtualHost.java:281)\r\n\tat com.ibm.ws.http.dispatcher.internal.channel.HttpDispatcherLink$TaskWrapper.run(HttpDispatcherLink.java:1184)\r\n\tat com.ibm.ws.http.dispatcher.internal.channel.HttpDispatcherLink.wrapHandlerAndExecute(HttpDispatcherLink.java:453)\r\n\tat com.ibm.ws.http.dispatcher.internal.channel.HttpDispatcherLink.ready(HttpDispatcherLink.java:412)\r\n\tat com.ibm.ws.http.channel.internal.inbound.HttpInboundLink.handleDiscrimination(HttpInboundLink.java:566)\r\n\tat com.ibm.ws.http.channel.internal.inbound.HttpInboundLink.handleNewRequest(HttpInboundLink.java:500)\r\n\tat com.ibm.ws.http.channel.internal.inbound.HttpInboundLink.processRequest(HttpInboundLink.java:360)\r\n\tat com.ibm.ws.http.channel.internal.inbound.HttpInboundLink.ready(HttpInboundLink.java:327)\r\n\tat com.ibm.ws.tcpchannel.internal.NewConnectionInitialReadCallback.sendToDiscriminators(NewConnectionInitialReadCallback.java:167)\r\n\tat com.ibm.ws.tcpchannel.internal.NewConnectionInitialReadCallback.complete(NewConnectionInitialReadCallback.java:75)\r\n\tat com.ibm.ws.tcpchannel.internal.WorkQueueManager.requestComplete(WorkQueueManager.java:514)\r\n\tat com.ibm.ws.tcpchannel.internal.WorkQueueManager.attemptIO(WorkQueueManager.java:584)\r\n\tat com.ibm.ws.tcpchannel.internal.WorkQueueManager.workerRun(WorkQueueManager.java:968)\r\n\tat com.ibm.ws.tcpchannel.internal.WorkQueueManager$Worker.run(WorkQueueManager.java:1057)\r\n\tat com.ibm.ws.threading.internal.ExecutorServiceImpl$RunnableWrapper.run(ExecutorServiceImpl.java:245)\r\n\tat java.base\/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)\r\n\tat java.base\/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)\r\n\tat java.base\/java.lang.Thread.run(Thread.java:831)","ibm_threadId":"00000060","ibm_datetime":"2022-04-20T13:42:26.365-0400","module":"SystemErr","loglevel":"SystemErr","ibm_methodName":"","ibm_className":"","ibm_sequence":"1650476546365_0000000000099","ext_thread":"Default Executor-thread-38"}

This new functionality is enabled by configuring either a bootstrap property, an environment variable, or through the server.xml file. If configuration is present in all these options, the configuration precedence is the server.xml > environment variable > bootstrap property.

Configuration:

bootstrap.properties:

`com.ibm.ws.logging.stackJoin=true

server.env:

WLP_LOGGING_STACK_JOIN=true

server.xml:

<logging stackJoin="true" />

Try it now

To try out these features, just update your build tools to pull the Open Liberty All Beta Features package instead of the main release. The beta works with Java SE 18, Java SE 17, Java SE 11, and Java SE 8.

If you’re using Maven, here are the coordinates:

<dependency>
  <groupId>io.openliberty.beta</groupId>
  <artifactId>openliberty-runtime</artifactId>
  <version>22.0.0.6-beta</version>
  <type>pom</type>
</dependency>

Or for Gradle:

dependencies {
    libertyRuntime group: 'io.openliberty.beta', name: 'openliberty-runtime', version: '[22.0.0.6-beta,)'
}

Or take a look at our Downloads page.

Your feedback is welcomed

Let us know what you think on our mailing list. If you hit a problem, post a question on StackOverflow. If you hit a bug, please raise an issue.

See all blog posts