Unrelated log entries are mixed together

[richard-salac]

Zowe Version: 3
z/os Version: 3.1
Description:
Zowe SYSPRINT (from spool) contains log entries that are split and mixed together. See example:

2025-01-16 14:05:56.910 <ZWEAGW1:parallel-5:16842795> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.z.a.s.c.v.CertificateValidator)) No endpoint configured to retrieve trusted certificates. Provide URL via apiml.security.x509.certificatesUrls
2025-01-16 14:05:56.911 <ZWEAGW1:parallel-5:16842795> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.z.a.g.l.DeterministicLoadBalancer)) No authentication present on request, not filtering the service: cachingservice
2025-01-16 14:05:56.911 <ZWEAGW1:parallel-5:16842795> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.z.a.g.c.NettyRoutingFilterApiml)) Using client with keystore true
2025-01-16 14:05:56.926 <ZWEAGW1:reactor-http-nio-2:16842795> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((r.n.h.c.HttpClientConnect)) [a050196b-1, L:/<LOCAL_ADDRESS> - R:<REMOTE_ADDRESS>] Handler is being applied: {uri=https://<APIML_HOST>:40013/cachingservice/api/v1/cache-list/, method=GET}
2025-01-16 14:05:56.939 <ZWEAGW1:reactor-http-nio-2:16842795> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((r.n.h.c.HttpClientOperations)) [a050196b-1, L:/<LOCAL_ADDRESS> - R:<REMOTE_ADDRESS>] Received response (auto-read:false) : RESPONSE(decodeResult: success, version: HTTP/1.1)
HTTP/1.1 200
X-Content-Type-Options: <filtered>
X-XSS-Protection: <filtered>
Cache-Control: <filtered>
Pragma: <filtered>
Expires: <filtered>
2025-01-16 14:05:56.897 <ZWEAZS1:https-jsse-nio-0.0.0.0-40018-exec-8:33620038> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.a.t.u.n.j.JSSESupport)) Error trying to obtain a certificate from the client
X-Frame-Options: <filtered>
javax.net.ssl.SSLPeerUnverifiedException: peer not authenticated
Content-Type: <filtered>
	at java.base/sun.security.ssl.SSLSessionImpl.getPeerCertificates(SSLSessionImpl.java:1041)
Transfer-Encoding: <filtered>
	at org.apache.tomcat.util.net.jsse.JSSESupport.getPeerCertificateChain(JSSESupport.java:107)
Date: <filtered>
	at org.apache.coyote.AbstractProcessor.populateSslRequestAttributes(AbstractProcessor.java:836)
2025-01-16 14:05:56.942 <ZWEAGW1:reactor-http-nio-2:16842795> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((r.n.h.c.HttpClientOperations)) [a050196b-1, L:/<LOCAL_ADDRESS> - R:<REMOTE_ADDRESS>] Received last HTTP packet
	at org.apache.coyote.AbstractProcessor.action(AbstractProcessor.java:497)
2025-01-16 14:05:56.946 <ZWEAGW1:reactor-http-nio-1:16842795> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((r.n.h.c.HttpClientOperations)) [31aedae0-1, L:/<LOCAL_ADDRESS> - R:<APIML_HOST>:40018] Received response (auto-read:false) : RESPONSE(decodeResult: success, version: HTTP/1.1)
	at org.apache.coyote.Request.action(Request.java:523)
HTTP/1.1 204
	at org.apache.catalina.connector.Request.getAttribute(Request.java:851)
Vary: <filtered>
	at org.apache.catalina.connector.Request.getAttributeNames(Request.java:925)
Vary: <filtered>
	at org.apache.catalina.connector.RequestFacade.getAttributeNames(RequestFacade.java:257)
Vary: <filtered>
	at org.springframework.web.servlet.handler.HandlerMappingIntrospector$AttributesPreservingRequest.initAttributes(HandlerMappingIntrospector.java:489)
X-Content-Type-Options: <filtered>
	at org.springframework.web.servlet.handler.HandlerMappingIntrospector$AttributesPreservingRequest.<init>(HandlerMappingIntrospector.java:483)
X-XSS-Protection: <filtered>
	at org.springframework.web.servlet.handler.HandlerMappingIntrospector.setCache(HandlerMappingIntrospector.java:216)
Cache-Control: <filtered>
	at org.springframework.web.servlet.handler.HandlerMappingIntrospector.lambda$createCacheFilter$3(HandlerMappingIntrospector.java:193)
Pragma: <filtered>
	at org.springframework.web.filter.CompositeFilter$VirtualFilterChain.doFilter(CompositeFilter.java:113)
Expires: <filtered>
	at org.springframework.web.filter.CompositeFilter.doFilter(CompositeFilter.java:74)
Strict-Transport-Security: <filtered>
	at org.springframework.security.config.annotation.web.configuration.WebMvcSecurityConfiguration$CompositeFilterChainProxy.doFilter(WebMvcSecurityConfiguration.java:230)
Date: <filtered>
	at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:362)
Keep-Alive: <filtered>
	at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:278)
Connection: <filtered>
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:164)
2025-01-16 14:05:56.946 <ZWEAGW1:reactor-http-nio-1:16842795> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.s.w.r.f.c.ExchangeFunctions)) [73650fee
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:140)
] [31aedae0-1] Response 204 NO_CONTENT
	at org.springframework.web.filter.ServerHttpObservationFilter.doFilterInternal(ServerHttpObservationFilter.java:113)
2025-01-16 14:05:56.946 <ZWEAGW1:reactor-http-nio-1:16842795> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((r.n.h.c.HttpClientOperations)) [31aedae0-1, L:/<LOCAL_ADDRESS> - R:<APIML_HOST>:40018] Received last HTTP packet
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:116)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:164)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:140)
	at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:201)
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:116)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:164)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:140)
	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:167)
	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:90)
	at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:483)
	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:115)
	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:93)
	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:74)
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:344)
	at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:384)
	at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:63)
	at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:905)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1741)
	at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:52)
	at org.apache.tomcat.util.threads.Threa
dPoolExecutor.runWorker(ThreadPoolExecutor.java:1190)
	at org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:659)
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:63)
	at java.base/java.lang.Thread.run(Thread.java:857)
2025-01-16 14:05:56.898 <ZWEAZS1:https-jsse-nio-0.0.0.0-40018-exec-8:33620038> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.s.s.w.FilterChainProxy)) Securing POST /zaas/api/v1/auth/access-token/validate
2025-01-16 14:05:56.899 <ZWEAZS1:https-jsse-nio-0.0.0.0-40018-exec-8:33620038> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.s.s.w.a.AnonymousAuthenticationFilter)) Set SecurityContextHolder to anonymous SecurityContext
2025-01-16 14:05:56.899 <ZWEAZS1:https-jsse-nio-0.0.0.0-40018-exec-8:33620038> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.s.s.w.FilterChainProxy)) Secured POST /zaas/api/v1/auth/access-token/validate
2025-01-16 14:05:56.902 <ZWEAZS1:https-jsse-nio-0.0.0.0-40018-exec-8:33620038> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.z.a.z.c.CachingServiceClient)) readAllMaps url: https://<APIML_HOST>:40010/cachingservice/api/v1/cache-list/
2025-01-16 14:05:58.723 <ZWEAGW1:https-jsse-nio-0.0.0.0-40010-exec-4:16842795> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.s.s.w.s.u.m.OrServerWebExchangeMatcher)) Trying to match using PathMatcherServ

Some log entries can span multiple lines and such are randomly interleaved with others. The example above is a compilation of following log entries:

APIML GW:

2025-01-16 14:05:56.910 <ZWEAGW1:parallel-5:16842795> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.z.a.s.c.v.CertificateValidator)) No endpoint configured to retrieve trusted certificates. Provide URL via apiml.security.x509.certificatesUrls
2025-01-16 14:05:56.911 <ZWEAGW1:parallel-5:16842795> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.z.a.g.l.DeterministicLoadBalancer)) No authentication present on request, not filtering the service: cachingservice
2025-01-16 14:05:56.911 <ZWEAGW1:parallel-5:16842795> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.z.a.g.c.NettyRoutingFilterApiml)) Using client with keystore true
2025-01-16 14:05:56.926 <ZWEAGW1:reactor-http-nio-2:16842795> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((r.n.h.c.HttpClientConnect)) [a050196b-1, L:/<LOCAL_ADDRESS> - R:<REMOTE_ADDRESS>] Handler is being applied: {uri=https://<APIML_HOST>:40013/cachingservice/api/v1/cache-list/, method=GET}
2025-01-16 14:05:56.939 <ZWEAGW1:reactor-http-nio-2:16842795> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((r.n.h.c.HttpClientOperations)) [a050196b-1, L:/<LOCAL_ADDRESS> - R:<REMOTE_ADDRESS>] Received response (auto-read:false) : RESPONSE(decodeResult: success, version: HTTP/1.1)
HTTP/1.1 200 
X-Content-Type-Options: <filtered>
X-XSS-Protection: <filtered>
Cache-Control: <filtered>
Pragma: <filtered>
Expires: <filtered>
X-Frame-Options: <filtered>
Content-Type: <filtered>
Transfer-Encoding: <filtered>
Date: <filtered>
2025-01-16 14:05:56.942 <ZWEAGW1:reactor-http-nio-2:16842795> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((r.n.h.c.HttpClientOperations)) [a050196b-1, L:/<LOCAL_ADDRESS> - R:<REMOTE_ADDRESS>] Received last HTTP packet
2025-01-16 14:05:56.946 <ZWEAGW1:reactor-http-nio-1:16842795> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((r.n.h.c.HttpClientOperations)) [31aedae0-1, L:/<LOCAL_ADDRESS> - R:<APIML_HOST>:40018] Received response (auto-read:false) : RESPONSE(decodeResult: success, version: HTTP/1.1)
HTTP/1.1 204 
Vary: <filtered>
Vary: <filtered>
Vary: <filtered>
X-Content-Type-Options: <filtered>
X-XSS-Protection: <filtered>
Cache-Control: <filtered>
Pragma: <filtered>
Expires: <filtered>
Strict-Transport-Security: <filtered>
Date: <filtered>
Keep-Alive: <filtered>
Connection: <filtered>
2025-01-16 14:05:56.946 <ZWEAGW1:reactor-http-nio-1:16842795> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.s.w.r.f.c.ExchangeFunctions)) [73650fee] [31aedae0-1] Response 204 NO_CONTENT
2025-01-16 14:05:56.946 <ZWEAGW1:reactor-http-nio-1:16842795> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((r.n.h.c.HttpClientOperations)) [31aedae0-1, L:/<LOCAL_ADDRESS> - R:<APIML_HOST>:40018] Received last HTTP packet
2025-01-16 14:05:58.723 <ZWEAGW1:https-jsse-nio-0.0.0.0-40010-exec-4:16842795> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.s.s.w.s.u.m.OrServerWebExchangeMatcher)) Trying to match using PathMatcherServerWebExchangeMatcher{pattern='/gateway/api/v1/registry', method=null}

APIML ZAAS:

2025-01-16 14:05:56.897 <ZWEAZS1:https-jsse-nio-0.0.0.0-40018-exec-8:33620038> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.a.t.u.n.j.JSSESupport)) Error trying to obtain a certificate from the client
javax.net.ssl.SSLPeerUnverifiedException: peer not authenticated
	at java.base/sun.security.ssl.SSLSessionImpl.getPeerCertificates(SSLSessionImpl.java:1041)
	at org.apache.tomcat.util.net.jsse.JSSESupport.getPeerCertificateChain(JSSESupport.java:107)
	at org.apache.coyote.AbstractProcessor.populateSslRequestAttributes(AbstractProcessor.java:836)
	at org.apache.coyote.AbstractProcessor.action(AbstractProcessor.java:497)
	at org.apache.coyote.Request.action(Request.java:523)
	at org.apache.catalina.connector.Request.getAttribute(Request.java:851)
	at org.apache.catalina.connector.Request.getAttributeNames(Request.java:925)
	at org.apache.catalina.connector.RequestFacade.getAttributeNames(RequestFacade.java:257)
	at org.springframework.web.servlet.handler.HandlerMappingIntrospector$AttributesPreservingRequest.initAttributes(HandlerMappingIntrospector.java:489)
	at org.springframework.web.servlet.handler.HandlerMappingIntrospector$AttributesPreservingRequest.<init>(HandlerMappingIntrospector.java:483)
	at org.springframework.web.servlet.handler.HandlerMappingIntrospector.setCache(HandlerMappingIntrospector.java:216)
	at org.springframework.web.servlet.handler.HandlerMappingIntrospector.lambda$createCacheFilter$3(HandlerMappingIntrospector.java:193)
	at org.springframework.web.filter.CompositeFilter$VirtualFilterChain.doFilter(CompositeFilter.java:113)
	at org.springframework.web.filter.CompositeFilter.doFilter(CompositeFilter.java:74)
	at org.springframework.security.config.annotation.web.configuration.WebMvcSecurityConfiguration$CompositeFilterChainProxy.doFilter(WebMvcSecurityConfiguration.java:230)
	at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:362)
	at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:278)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:164)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:140)
	at org.springframework.web.filter.ServerHttpObservationFilter.doFilterInternal(ServerHttpObservationFilter.java:113)
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:116)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:164)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:140)
	at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:201)
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:116)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:164)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:140)
	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:167)
	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:90)
	at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:483)
	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:115)
	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:93)
	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:74)
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:344)
	at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:384)
	at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:63)
	at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:905)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1741)
	at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:52)
	at org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1190)
	at org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:659)
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:63)
	at java.base/java.lang.Thread.run(Thread.java:857)
2025-01-16 14:05:56.898 <ZWEAZS1:https-jsse-nio-0.0.0.0-40018-exec-8:33620038> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.s.s.w.FilterChainProxy)) Securing POST /zaas/api/v1/auth/access-token/validate
2025-01-16 14:05:56.899 <ZWEAZS1:https-jsse-nio-0.0.0.0-40018-exec-8:33620038> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.s.s.w.a.AnonymousAuthenticationFilter)) Set SecurityContextHolder to anonymous SecurityContext
2025-01-16 14:05:56.899 <ZWEAZS1:https-jsse-nio-0.0.0.0-40018-exec-8:33620038> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.s.s.w.FilterChainProxy)) Secured POST /zaas/api/v1/auth/access-token/validate
2025-01-16 14:05:56.902 <ZWEAZS1:https-jsse-nio-0.0.0.0-40018-exec-8:33620038> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.z.a.z.c.CachingServiceClient)) readAllMaps url: https://<APIML_HOST>:40010/cachingservice/api/v1/cache-list/
2025-01-16 14:05:58.741 <ZWEAZS1:https-jsse-nio-0.0.0.0-40018-exec-1:33620038> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.s.s.w.FilterChainProxy)) Securing DELETE /zaas/api/v1/auth/access-token/revoke/tokens/user

Impact:
When logs are mixed together, it is very difficult to analyze them. In some cases, like when two messages of the same kind are mixed together (stack traces, certificate dumps, http dumps) it is impossible to distinguish which lines belongs together.

Expectated output:
Logs are not mixed together, multiline log entries are printed as a whole.

Steps to reproduce:
This issue does not seem to be related to any particular setup. In our case, we run APIML integration tests with debug enabled.

Notes:
It looks like a bug of log manager which operates on a per-line basis.

[JoeNemo]

This is the unified log from the launchers point-of-view, and has all streams merged. There may be per-component (e.g. APIML) logs also captured and stored in a component-specific place, and the APIML config doc should say where. There is a proposal and prototype for allowing launcher logs to have per-component subdivision, using SYSOUT DDName's, but it has never gone into to roadmap or quarterly plan.