Aggregated Zowe log from spool SYSPRINT is missing some messages

[richard-salac]

Zowe Version: 3
z/os Version: 3.1

Description:
Zowe SYSPRINT (from spool) is missing some log messages. APIML loggers are configured to produce all log messages to both a file and STDOUT.

The aggregated Zowe log in spool SYSPRINT is missing some messages present in the APIML log files.

2025-01-16 14:42:07.970 <ZWEAGW1:https-jsse-nio-0.0.0.0-40010-exec-5: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}
2025-01-16 14:42:07.970 <ZWEAGW1:https-jsse-nio-0.0.0.0-40010-exec-5:16842795> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.s.s.w.s.u.m.PathPatternParserServerWebExchangeMatcher)) Request 'DELETE /gateway/api/v1/auth/access-token/revoke/tokens/user' doesn't match 'null /gateway/api/v1/registry'
2025-01-16 14:42:07.970 <ZWEAGW1:https-jsse-nio-0.0.0.0-40010-exec-5: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}
2025-01-16 14:42:07.970 <ZWEAGW1:https-jsse-nio-0.0.0.0-40010-exec-5:16842795> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.s.s.w.s.u.m.PathPatternParserServerWebExchangeMatcher)) Request 'DELETE /gateway/api/v1/auth/access-token/revoke/tokens/user' doesn't match 'null /gateway/api/v1/registry/**'
2025-01-16 14:42:07.970 <ZWEAGW1:https-jsse-nio-0.0.0.0-40010-exec-5:16842795> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.s.s.w.s.u.m.OrServerWebExchangeMatcher)) Trying to match using PathMatcherServerWebExchangeMatcher{pattern='/gateway/services', method=null}
2025-01-16 14:42:07.970 <ZWEAGW1:https-jsse-nio-0.0.0.0-40010-exec-5:16842795> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.s.s.w.s.u.m.PathPatternParserServerWebExchangeMatcher)) Request 'DELETE /gateway/api/v1/auth/access-token/revoke/tokens/user' doesn't match 'null /gateway/services'
2025-01-16 14:42:07.970 <ZWEAGW1:https-jsse-nio-0.0.0.0-40010-exec-5:16842795> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.s.s.w.s.u.m.OrServerWebExchangeMatcher)) Trying to match using PathMatcherServerWebExchangeMatcher{pattern='/gateway/services/**', method=null}
2025-01-16 14:42:07.971 <ZWEAGW1:https-jsse-nio-0.0.0.0-40010-exec-5:16842795> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.s.s.w.s.u.m.PathPatternParserServerWebExchangeMatcher)) Request 'DELETE /gateway/api/v1/auth/access-token/revoke/tokens/user' doesn't match 'null /gateway/services/**'
2025-01-16 14:42:07.971 <ZWEAGW1:https-jsse-nio-0.0.0.0-40010-exec-5:16842795> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.s.s.w.s.u.m.OrServerWebExchangeMatcher)) Trying to match using PathMatcherServerWebExchangeMatcher{pattern='/gateway/api/v1/services', method=null}
2025-01-16 14:42:07.971 <ZWEAGW1:https-jsse-nio-0.0.0.0-40010-exec-5:16842795> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.s.s.w.s.u.m.PathPatternParserServerWebExchangeMatcher)) Request 'DELETE /gateway/api/v1/auth/access-token/revoke/tokens/user' doesn't match 'null /gateway/api/v1/services'
2025-01-16 14:42:07.971 <ZWEAGW1:https-jsse-nio-0.0.0.0-40010-exec-5:16842795> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.s.s.w.s.u.m.OrServerWebExchangeMatcher)) Trying to match using PathMatcherServerWebExchangeMatcher{pattern='/gateway/api/v1/services/**', method=null}
2025-01-16 14:42:07.971 <ZWEAGW1:https-jsse-nio-0.0.0.0-40010-exec-5:16842795> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.s.s.w.s.u.m.PathPatternParserServerWebExchangeMatcher)) Request 'DELETE /gateway/api/v1/auth/access-token/revoke/tokens/user' doesn't match 'null /gateway/api/v1/services/**'
2025-01-16 14:42:07.971 <ZWEAGW1:https-jsse-nio-0.0.0.0-40010-exec-5:16842795> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.s.s.w.s.u.m.OrServerWebExchangeMatcher)) Trying to match using PathMatcherServerWebExchangeMatcher{pattern='/gateway/conformance/**', method=null}
2025-01-16 14:42:07.971 <ZWEAGW1:https-jsse-nio-0.0.0.0-40010-exec-5:16842795> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.s.s.w.s.u.m.PathPatternParserServerWebExchangeMatcher)) Request 'DELETE /gateway/api/v1/auth/access-token/revoke/tokens/user' doesn't match 'null /gateway/conformance/**'
2025-01-16 14:42:07.971 <ZWEAGW1:https-jsse-nio-0.0.0.0-40010-exec-5:16842795> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.s.s.w.s.u.m.OrServerWebExchangeMatcher
)) Trying to match using PathMatcherServerWebExchangeMatcher{pattern='/gateway/api/v1/conformance/**', method=null}
2025-01-16 14:42:07.971 <ZWEAGW1:https-jsse-nio-0.0.0.0-40010-exec-5:16842795> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.s.s.w.s.u.m.PathPatternParserServerWebExchangeMatcher)) Request 'DELETE /gateway/api/v1/auth/access-token/revoke/tokens/user' doesn't match 'null /gateway/api/v1/conformance/**'
2025-01-16 14:42:07.971 <ZWEAGW1:https-jsse-nio-0.0.0.0-40010-exec-5:16842795> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.s.s.w.s.u.m.OrServerWebExchangeMatcher)) Trying to match using PathMatcherServerWebExchangeMatcher{pattern='/gateway/validate', method=null}
2025-01-16 14:42:07.971 <ZWEAGW1:https-jsse-nio-0.0.0.0-40010-exec-5:16842795> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.s.s.w.s.u.m.PathPatternParserServerWebExchangeMatcher)) Request 'DELETE /gateway/api/v1/auth/access-token/revoke/tokens/user' doesn't match 'null /gateway/validate'
2025-01-16 14:42:07.971 <ZWEAGW1:https-jsse-nio-0.0.0.0-40010-exec-5:16842795> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.s.s.w.s.u.m.OrServerWebExchangeMatcher)) Trying to match using PathMatcherServerWebExchangeMatcher{pattern='/gateway/api/v1/validate', method=null}
2025-01-16 14:42:07.971 <ZWEAGW1:https-jsse-nio-0.0.0.0-40010-exec-5:16842795> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.s.s.w.s.u.m.PathPatternParserServerWebExchangeMatcher)) Request 'DELETE /gateway/api/v1/auth/access-token/revoke/tokens/user' doesn't match 'null /gateway/api/v1/validate'
2025-01-16 14:42:07.971 <ZWEAGW1:https-jsse-nio-0.0.0.0-40010-exec-5:16842795> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.s.s.w.s.u.m.OrServerWebExchangeMatcher)) Trying to match using PathMatcherServerWebExchangeMatcher{pattern='/application/**', method=null}
2025-01-16 14:42:07.971 <ZWEAGW1:https-jsse-nio-0.0.0.0-40010-exec-5:16842795> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.s.s.w.s.u.m.PathPatternParserServerWebExchangeMatcher)) Request 'DELETE /gateway/api/v1/auth/access-token/revoke/tokens/user' doesn't match 'null /application/**'
2025-01-16 14:42:07.971 <ZWEAGW1:https-jsse-nio-0.0.0.0-40010-exec-5:16842795> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.s.s.w.s.u.m.OrServerWebExchangeMatcher)) No matches found
2025-01-16 14:42:07.971 <ZWEAGW1:https-jsse-nio-0.0.0.0-40010-exec-5:16842795> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.z.a.g.x.X509Util$1)) Subject DN is 'CN=user, OU=IT, O=Broadcom Inc, L=Prague, ST=Czechia, C=CZ'
2025-01-16 14:42:07.971 <ZWEAGW1:https-jsse-nio-0.0.0.0-40010-exec-5:16842795> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.z.a.g.x.X509Util$1)) Extracted Principal name is 'user'
2025-01-16 14:42:07.972 <ZWEAGW1:parallel-3:16842795> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.s.s.w.s.u.m.OrServerWebExchangeMatcher)) Trying to match using PathMatcherServerWebExchangeMatcher{pattern='/logout', method=POST}
2025-01-16 14:42:07.972 <ZWEAGW1:parallel-3:16842795> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.s.s.w.s.u.m.PathPatternParserServerWebExchangeMatcher)) Request 'DELETE /gateway/api/v1/auth/access-token/revoke/tokens/user' doesn't match 'POST /logout'
2025-01-16 14:42:07.972 <ZWEAGW1:parallel-3:16842795> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.s.s.w.s.u.m.OrServerWebExchangeMatcher)) No matches found
2025-01-16 14:42:07.972 <ZWEAGW1:parallel-3:16842795> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.s.w.r.f.s.s.RouterFunctionMapping)) [61f5aed9] Mapped to org.zowe.apiml.gateway.config.AuthEndpointConfig$$Lambda$1023/0x00000000e56c7048@e5d7d595
2025-01-16 14:42:07.973 <ZWEAGW1:parallel-3:16842795> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.z.a.g.l.DeterministicLoadBalancer)) No authentication present on request, not filtering the service: zaas
2025-01-16 14:42:07.973 <ZWEAGW1:parallel-3:16842795> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.s.w.r.f.c.ExchangeFunctions)) [8642790a] HTTP DELETE https://mvsde66.lvn.broadcom.net:40018/zaas/api/v1/auth/access-token/revoke/tokens/user
2025-01-16 14:42:07.974 <ZWEAGW1:reactor-http-nio-2:16842795> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((r.n.h.c.HttpClientCon
nect)) [c04657c6-2, L:/10.175.80.135:13390 - R:mvsde66.lvn.broadcom.net/10.175.80.135:40018] Handler is being applied: {uri=https://mvsde66.lvn.broadcom.net:40018/zaas/api/v1/auth/access-token/revoke/tokens/user, method=DELETE}
2025-01-16 14:42:07.996 <ZWEAGW1:reactor-http-nio-2:16842795> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((r.n.h.c.HttpClientOperations)) [c04657c6-2, L:/10.175.80.135:13390 - R:mvsde66.lvn.broadcom.net/10.175.80.135:40018] Received response (auto-read:false) : RESPONSE(decodeResult: success, version: HTTP/1.1)

<HTTP Dump - 9 lines>

2025-01-16 14:42:07.978 <ZWEAZS1:https-jsse-nio-0.0.0.0-40018-exec-10:33620038> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.s.s.w.FilterChainProxy)) Securing DELETE /zaas/api/v1/auth/access-token/revoke/tokens/user
Strict-Transport-Security: <filtered>
2025-01-16 14:42:07.979 <ZWEAZS1:https-jsse-nio-0.0.0.0-40018-exec-10:33620038> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.z.a.s.c.v.CertificateValidator)) The whole certificate chain is trusted.
Content-Type: <filtered>
2025-01-16 14:42:07.979 <ZWEAZS1:https-jsse-nio-0.0.0.0-40018-exec-10:33620038> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.z.a.s.c.f.CategorizeCertsFilter)) Found client certificate in header, adding it to the request. Subject DN: CN=user,OU=IT,O=Broadcom Inc,L=Prague,ST=Czechia,C=CZ
Transfer-Encoding: <filtered>
2025-01-16 14:42:07.980 <ZWEAZS1:https-jsse-nio-0.0.0.0-40018-exec-10:33620038> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.z.a.s.c.f.CategorizeCertsFilter)) Filtering certificates: client.auth.X509Certificate -> [[
2025-01-16 14:42:07.996 <ZWEAGW1:reactor-http-nio-2:16842795> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.s.w.r.f.c.ExchangeFunctions)) [8642790a] [c04657c6-2] Response 500 INTERNAL_SERVER_ERROR
2025-01-16 14:42:07.997 <ZWEAGW1:reactor-http-nio-2:16842795> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((r.n.h.c.HttpClientOperations)) [c04657c6-2, L:/10.175.80.135:13390 - R:mvsde66.lvn.broadcom.net/10.175.80.135:40018] Received last HTTP packet

<CERTIFICATE DUMP - cca 150 lines>

<JAVA STACKTRACE - cca 170 lines>

2025-01-16 14:42:26.026 <ZWEAZS1:DiscoveryClient-InstanceInfoReplicator-%d:33620038> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.z.a.z.s.l.Providers)) z/OSMF registered with the Discovery Service and propagated to ZAAS: true

In this time frame, APIML GW produced following logs:

2025-01-16 14:42:07.970 <ZWEAGW1:https-jsse-nio-0.0.0.0-40010-exec-5: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}
2025-01-16 14:42:07.970 <ZWEAGW1:https-jsse-nio-0.0.0.0-40010-exec-5:16842795> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.s.s.w.s.u.m.PathPatternParserServerWebExchangeMatcher)) Request 'DELETE /gateway/api/v1/auth/access-token/revoke/tokens/user' doesn't match 'null /gateway/api/v1/registry'
2025-01-16 14:42:07.970 <ZWEAGW1:https-jsse-nio-0.0.0.0-40010-exec-5: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}
2025-01-16 14:42:07.970 <ZWEAGW1:https-jsse-nio-0.0.0.0-40010-exec-5:16842795> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.s.s.w.s.u.m.PathPatternParserServerWebExchangeMatcher)) Request 'DELETE /gateway/api/v1/auth/access-token/revoke/tokens/user' doesn't match 'null /gateway/api/v1/registry/**'
2025-01-16 14:42:07.970 <ZWEAGW1:https-jsse-nio-0.0.0.0-40010-exec-5:16842795> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.s.s.w.s.u.m.OrServerWebExchangeMatcher)) Trying to match using PathMatcherServerWebExchangeMatcher{pattern='/gateway/services', method=null}
2025-01-16 14:42:07.970 <ZWEAGW1:https-jsse-nio-0.0.0.0-40010-exec-5:16842795> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.s.s.w.s.u.m.PathPatternParserServerWebExchangeMatcher)) Request 'DELETE /gateway/api/v1/auth/access-token/revoke/tokens/user' doesn't match 'null /gateway/services'
2025-01-16 14:42:07.970 <ZWEAGW1:https-jsse-nio-0.0.0.0-40010-exec-5:16842795> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.s.s.w.s.u.m.OrServerWebExchangeMatcher)) Trying to match using PathMatcherServerWebExchangeMatcher{pattern='/gateway/services/**', method=null}
2025-01-16 14:42:07.971 <ZWEAGW1:https-jsse-nio-0.0.0.0-40010-exec-5:16842795> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.s.s.w.s.u.m.PathPatternParserServerWebExchangeMatcher)) Request 'DELETE /gateway/api/v1/auth/access-token/revoke/tokens/user' doesn't match 'null /gateway/services/**'
2025-01-16 14:42:07.971 <ZWEAGW1:https-jsse-nio-0.0.0.0-40010-exec-5:16842795> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.s.s.w.s.u.m.OrServerWebExchangeMatcher)) Trying to match using PathMatcherServerWebExchangeMatcher{pattern='/gateway/api/v1/services', method=null}
2025-01-16 14:42:07.971 <ZWEAGW1:https-jsse-nio-0.0.0.0-40010-exec-5:16842795> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.s.s.w.s.u.m.PathPatternParserServerWebExchangeMatcher)) Request 'DELETE /gateway/api/v1/auth/access-token/revoke/tokens/user' doesn't match 'null /gateway/api/v1/services'
2025-01-16 14:42:07.971 <ZWEAGW1:https-jsse-nio-0.0.0.0-40010-exec-5:16842795> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.s.s.w.s.u.m.OrServerWebExchangeMatcher)) Trying to match using PathMatcherServerWebExchangeMatcher{pattern='/gateway/api/v1/services/**', method=null}
2025-01-16 14:42:07.971 <ZWEAGW1:https-jsse-nio-0.0.0.0-40010-exec-5:16842795> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.s.s.w.s.u.m.PathPatternParserServerWebExchangeMatcher)) Request 'DELETE /gateway/api/v1/auth/access-token/revoke/tokens/user' doesn't match 'null /gateway/api/v1/services/**'
2025-01-16 14:42:07.971 <ZWEAGW1:https-jsse-nio-0.0.0.0-40010-exec-5:16842795> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.s.s.w.s.u.m.OrServerWebExchangeMatcher)) Trying to match using PathMatcherServerWebExchangeMatcher{pattern='/gateway/conformance/**', method=null}
2025-01-16 14:42:07.971 <ZWEAGW1:https-jsse-nio-0.0.0.0-40010-exec-5:16842795> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.s.s.w.s.u.m.PathPatternParserServerWebExchangeMatcher)) Request 'DELETE /gateway/api/v1/auth/access-token/revoke/tokens/user' doesn't match 'null /gateway/conformance/**'
2025-01-16 14:42:07.971 <ZWEAGW1:https-jsse-nio-0.0.0.0-40010-exec-5:16842795> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.s.s.w.s.u.m.OrServerWebExchangeMatcher)) Trying to match using PathMatcherServerWebExchangeMatcher{pattern='/gateway/api/v1/conformance/**', method=null}
2025-01-16 14:42:07.971 <ZWEAGW1:https-jsse-nio-0.0.0.0-40010-exec-5:16842795> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.s.s.w.s.u.m.PathPatternParserServerWebExchangeMatcher)) Request 'DELETE /gateway/api/v1/auth/access-token/revoke/tokens/user' doesn't match 'null /gateway/api/v1/conformance/**'
2025-01-16 14:42:07.971 <ZWEAGW1:https-jsse-nio-0.0.0.0-40010-exec-5:16842795> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.s.s.w.s.u.m.OrServerWebExchangeMatcher)) Trying to match using PathMatcherServerWebExchangeMatcher{pattern='/gateway/validate', method=null}
2025-01-16 14:42:07.971 <ZWEAGW1:https-jsse-nio-0.0.0.0-40010-exec-5:16842795> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.s.s.w.s.u.m.PathPatternParserServerWebExchangeMatcher)) Request 'DELETE /gateway/api/v1/auth/access-token/revoke/tokens/user' doesn't match 'null /gateway/validate'
2025-01-16 14:42:07.971 <ZWEAGW1:https-jsse-nio-0.0.0.0-40010-exec-5:16842795> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.s.s.w.s.u.m.OrServerWebExchangeMatcher)) Trying to match using PathMatcherServerWebExchangeMatcher{pattern='/gateway/api/v1/validate', method=null}
2025-01-16 14:42:07.971 <ZWEAGW1:https-jsse-nio-0.0.0.0-40010-exec-5:16842795> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.s.s.w.s.u.m.PathPatternParserServerWebExchangeMatcher)) Request 'DELETE /gateway/api/v1/auth/access-token/revoke/tokens/user' doesn't match 'null /gateway/api/v1/validate'
2025-01-16 14:42:07.971 <ZWEAGW1:https-jsse-nio-0.0.0.0-40010-exec-5:16842795> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.s.s.w.s.u.m.OrServerWebExchangeMatcher)) Trying to match using PathMatcherServerWebExchangeMatcher{pattern='/application/**', method=null}
2025-01-16 14:42:07.971 <ZWEAGW1:https-jsse-nio-0.0.0.0-40010-exec-5:16842795> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.s.s.w.s.u.m.PathPatternParserServerWebExchangeMatcher)) Request 'DELETE /gateway/api/v1/auth/access-token/revoke/tokens/user' doesn't match 'null /application/**'
2025-01-16 14:42:07.971 <ZWEAGW1:https-jsse-nio-0.0.0.0-40010-exec-5:16842795> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.s.s.w.s.u.m.OrServerWebExchangeMatcher)) No matches found
2025-01-16 14:42:07.971 <ZWEAGW1:https-jsse-nio-0.0.0.0-40010-exec-5:16842795> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.z.a.g.x.X509Util$1)) Subject DN is 'CN=user, OU=IT, O=Broadcom Inc, L=Prague, ST=Czechia, C=CZ'
2025-01-16 14:42:07.971 <ZWEAGW1:https-jsse-nio-0.0.0.0-40010-exec-5:16842795> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.z.a.g.x.X509Util$1)) Extracted Principal name is 'user'
2025-01-16 14:42:07.972 <ZWEAGW1:parallel-3:16842795> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.s.s.w.s.u.m.OrServerWebExchangeMatcher)) Trying to match using PathMatcherServerWebExchangeMatcher{pattern='/logout', method=POST}
2025-01-16 14:42:07.972 <ZWEAGW1:parallel-3:16842795> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.s.s.w.s.u.m.PathPatternParserServerWebExchangeMatcher)) Request 'DELETE /gateway/api/v1/auth/access-token/revoke/tokens/user' doesn't match 'POST /logout'
2025-01-16 14:42:07.972 <ZWEAGW1:parallel-3:16842795> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.s.s.w.s.u.m.OrServerWebExchangeMatcher)) No matches found
2025-01-16 14:42:07.972 <ZWEAGW1:parallel-3:16842795> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.s.w.r.f.s.s.RouterFunctionMapping)) [61f5aed9] Mapped to org.zowe.apiml.gateway.config.AuthEndpointConfig$$Lambda$1023/0x00000000e56c7048@e5d7d595
2025-01-16 14:42:07.973 <ZWEAGW1:parallel-3:16842795> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.z.a.g.l.DeterministicLoadBalancer)) No authentication present on request, not filtering the service: zaas
2025-01-16 14:42:07.973 <ZWEAGW1:parallel-3:16842795> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.s.w.r.f.c.ExchangeFunctions)) [8642790a] HTTP DELETE https://mvsde66.lvn.broadcom.net:40018/zaas/api/v1/auth/access-token/revoke/tokens/user
2025-01-16 14:42:07.974 <ZWEAGW1:reactor-http-nio-2:16842795> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((r.n.h.c.HttpClientConnect)) [c04657c6-2, L:/10.175.80.135:13390 - R:mvsde66.lvn.broadcom.net/10.175.80.135:40018] Handler is being applied: {uri=https://mvsde66.lvn.broadcom.net:40018/zaas/api/v1/auth/access-token/revoke/tokens/user, method=DELETE}
2025-01-16 14:42:07.996 <ZWEAGW1:reactor-http-nio-2:16842795> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((r.n.h.c.HttpClientOperations)) [c04657c6-2, L:/10.175.80.135:13390 - R:mvsde66.lvn.broadcom.net/10.175.80.135:40018] Received response (auto-read:false) : RESPONSE(decodeResult: success, version: HTTP/1.1)

<HTTP DUMP>

2025-01-16 14:42:07.996 <ZWEAGW1:reactor-http-nio-2:16842795> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.s.w.r.f.c.ExchangeFunctions)) [8642790a] [c04657c6-2] Response 500 INTERNAL_SERVER_ERROR
2025-01-16 14:42:07.997 <ZWEAGW1:reactor-http-nio-2:16842795> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((r.n.h.c.HttpClientOperations)) [c04657c6-2, L:/10.175.80.135:13390 - R:mvsde66.lvn.broadcom.net/10.175.80.135:40018] Received last HTTP packet

and the ZAAS following logs:

2025-01-16 14:42:07.978 <ZWEAZS1:https-jsse-nio-0.0.0.0-40018-exec-10:33620038> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.s.s.w.FilterChainProxy)) Securing DELETE /zaas/api/v1/auth/access-token/revoke/tokens/user
2025-01-16 14:42:07.979 <ZWEAZS1:https-jsse-nio-0.0.0.0-40018-exec-10:33620038> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.z.a.s.c.v.CertificateValidator)) The whole certificate chain is trusted.
2025-01-16 14:42:07.979 <ZWEAZS1:https-jsse-nio-0.0.0.0-40018-exec-10:33620038> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.z.a.s.c.f.CategorizeCertsFilter)) Found client certificate in header, adding it to the request. Subject DN: CN=user,OU=IT,O=Broadcom Inc,L=Prague,ST=Czechia,C=CZ
2025-01-16 14:42:07.980 <ZWEAZS1:https-jsse-nio-0.0.0.0-40018-exec-10:33620038> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.z.a.s.c.f.CategorizeCertsFilter)) Filtering certificates: client.auth.X509Certificate -> [[

<CERTIFICATE DUMP - cca 150 lines>

2025-01-16 14:42:07.984 <ZWEAZS1:https-jsse-nio-0.0.0.0-40018-exec-10:33620038> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.s.s.w.a.p.x.SubjectDnX509PrincipalExtractor)) Subject DN is 'CN=*.lvn.broadcom.net, O=Broadcom Inc., L=San Jose, ST=California, C=US'
2025-01-16 14:42:07.984 <ZWEAZS1:https-jsse-nio-0.0.0.0-40018-exec-10:33620038> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.s.s.w.a.p.x.SubjectDnX509PrincipalExtractor)) Extracted Principal name is '*.lvn.broadcom.net'
2025-01-16 14:42:07.984 <ZWEAZS1:https-jsse-nio-0.0.0.0-40018-exec-10:33620038> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.s.s.w.a.p.x.X509AuthenticationFilter)) preAuthenticatedPrincipal = *.lvn.broadcom.net, trying to authenticate
2025-01-16 14:42:07.986 <ZWEAZS1:https-jsse-nio-0.0.0.0-40018-exec-10:33620038> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.s.s.w.a.p.x.X509AuthenticationFilter)) X.509 client authentication certificate:[

<CERTIFICATE DUMP - cca 150 lines>

2025-01-16 14:42:07.987 <ZWEAZS1:https-jsse-nio-0.0.0.0-40018-exec-10:33620038> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.s.s.w.a.p.PreAuthenticatedAuthenticationProvider)) PreAuthenticated authentication request: PreAuthenticatedAuthenticationToken [Principal=*.lvn.broadcom.net, Credentials=[PROTECTED], Authenticated=false, Details=WebAuthenticationDetails [RemoteIpAddress=10.175.80.135, SessionId=null], Granted Authorities=[]]
2025-01-16 14:42:07.987 <ZWEAZS1:https-jsse-nio-0.0.0.0-40018-exec-10:33620038> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.s.s.w.a.p.x.X509AuthenticationFilter)) Authentication success: PreAuthenticatedAuthenticationToken [Principal=org.springframework.security.core.userdetails.User [Username=*.lvn.broadcom.net, Password=[PROTECTED], Enabled=true, AccountNonExpired=true, CredentialsNonExpired=true, AccountNonLocked=true, Granted Authorities=[]], Credentials=[PROTECTED], Authenticated=true, Details=WebAuthenticationDetails [RemoteIpAddress=10.175.80.135, SessionId=null], Granted Authorities=[]]
2025-01-16 14:42:07.987 <ZWEAZS1:https-jsse-nio-0.0.0.0-40018-exec-10:33620038> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.z.a.s.c.l.X509AuthenticationFilter)) One or more X509 certificate found in request.
2025-01-16 14:42:07.987 <ZWEAZS1:https-jsse-nio-0.0.0.0-40018-exec-10:33620038> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.z.a.z.s.l.x.X509AuthenticationProvider)) Authenticating X509 Certificate
2025-01-16 14:42:07.987 <ZWEAZS1:https-jsse-nio-0.0.0.0-40018-exec-10:33620038> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.z.a.z.s.l.x.X509AuthenticationProvider)) Getting user id for certificate: [

<CERTIFICATE DUMP - cca 100 lines>

2025-01-16 14:42:07.991 <ZWEAZS1:https-jsse-nio-0.0.0.0-40018-exec-10:33620038> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.z.a.z.s.m.NativeMapper)) CertificateResponse(userId=, rc=-1, errno=164, errno2=318832640)
2025-01-16 14:42:07.991 <ZWEAZS1:https-jsse-nio-0.0.0.0-40018-exec-10:33620038> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.z.a.z.s.l.x.X509AuthenticationProvider)) Mapping user to certificate was not successful.
2025-01-16 14:42:07.991 <ZWEAZS1:https-jsse-nio-0.0.0.0-40018-exec-10:33620038> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.s.s.w.FilterChainProxy)) Secured DELETE /zaas/api/v1/auth/access-token/revoke/tokens/user
2025-01-16 14:42:07.992 <ZWEAZS1:https-jsse-nio-0.0.0.0-40018-exec-10:33620038> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.s.s.a.m.AuthorizationManagerBeforeMethodInterceptor)) Authorizing method invocation ReflectiveMethodInvocation: public org.springframework.http.ResponseEntity org.zowe.apiml.zaas.controllers.AuthController.revokeAccessTokensForUser(org.zowe.apiml.zaas.controllers.AuthController$RulesRequestModel) throws com.fasterxml.jackson.core.JsonProcessingException; target is of class [org.zowe.apiml.zaas.controllers.AuthController]
2025-01-16 14:42:07.992 <ZWEAZS1:https-jsse-nio-0.0.0.0-40018-exec-10:33620038> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.z.a.s.c.a.s.SafResourceAccessSaf)) Evaluating access of user *.lvn.broadcom.net to resource ZOWE in class APIML.SERVICES level READ
2025-01-16 14:42:07.993 <ZWEAZS1:https-jsse-nio-0.0.0.0-40018-exec-10:33620038> �[35mZWESVUSR�[0;39m �[36mERROR�[0;39m ((o.z.a.s.c.a.s.SafResourceAccessSaf)) Platform access control failed: EINVAL JRUserNameLenError The user name length value was incorrect PlatformReturned(success=false, rc=0, errno=121, errno2=154665638, errnoMsg=EDC5121I Invalid argument. (errno2=0x093802A6), stringRet=null, objectRet=null)
2025-01-16 14:42:07.993 <ZWEAZS1:https-jsse-nio-0.0.0.0-40018-exec-10:33620038> �[35mZWESVUSR�[0;39m �[36mDEBUG�[0;39m ((o.z.a.z.z.ZaasExceptionHandler)) Unexpected internal error

<JAVA STACKTRACE - cca 170 lines>

About 30% of log lines are missing in the spool SYSPRINT. Notice that only a few ZAAS log entries are present in the spool file.

Impact:
System operators cannot rely on spool SYSPRINT and have to investigate the log files instead.

How to reproduce:
We run APIML in debug mode. We are unable to provide exact conditions when it happens, it seems to be occurring when log entries are produced at a high rate.

[JoeNemo]

Sounds like APIML has some places it logs to that are not known by the launcher. There is no way to know this and control this universally from the launcher.

[richard-salac]

The APIML logs the same output to stdout for Zowe launcher and own log file. The configuration is here. The problem is that Zowe Launcher does not process everything produced to stdout.

[JoeNemo]

Is there any chance that these lines are going to STDERR? The config looks good, AFAIK.

[JoeNemo]

It is also suspected that the Zowe Launcher does NOT capture STDERR, so this is a reminder to @ifakhrutdinov , @1000TurquoisePogs

[richard-salac]

These logs go to STDOUT. The same messages are sometimes present and sometimes missing.

The truth is the environment is a mini system with limited resources, so in debug the system could be under significant load.

[JoeNemo]

That's interesting, @richard-salac , maybe our method of capturing has edge cases where some lines are lost. But in general pipes should not lose info in the middle a pipe?

[richard-salac]

I would personally consider system pipes safe, I guess it can be something in the post processing. But it is a long shot from my side since I am not familiar with implementation details. We observed this behavior while troubleshooting apiml internal errors, when the application is in debug and stacktraces are printed. In such cases vast amount of messages is logged.