Details
-
Bug
-
Status: Resolved
-
Minor
-
Resolution: Won't Fix
-
3.0.1
-
None
-
None
-
Unknown
Description
It seems the MDC is not passed from "XNIO-1 task" thread to "default-workqueue" thread. We use the MDC to associate the request with a unique ticket. When an error occurs processing the request, the error handling is occuring on a different thread. That thread doesn't have the MDC context propagated to it, so the necessary MDC tracing information is not available in the error log.
In fact, the MDC context is propagated later on to the thread, and not cleaned up. This effectively causes the error to be logged with the PREVIOUS request icket handled by that workqueue thread. See attached camel-mdc-trace.txt:
...
2020-03-04 11:20:49,963 TRACE [o.s.b.w.s.f.OrderedRequestContextFilter] (XNIO-1 task-1) {} Bound request context to thread: HttpServletRequestImpl [ POST /DB2PConsultContributionService/consult ]
2020-03-04 11:20:49,965 INFO [be.fgov.kszbcss.tracer.Tracer] (XNIO-1 task-1) {} Loaded tracer binding be.fgov.kszbcss.tracer.spi.Slf4jMdcTracerBinding from ServiceLoader
2020-03-04 11:20:49,968 DEBUG [o.a.c.t.servlet.ServletController] (XNIO-1 task-1) {CBSS-Trace-InboundTicket=06ab8f30-bfae-471b-8901-528d82477613} Service http request on thread: Thread[XNIO-1 task-1,5,main]
=> Here we've added the CBSS-Trace-InboundTicket to the MDC
...
2020-03-04 11:20:50,038 TRACE [o.a.camel.impl.engine.MDCUnitOfWork] (XNIO-1 task-1) {CBSS-Trace-InboundTicket=06ab8f30-bfae-471b-8901-528d82477613} UnitOfWork created for ExchangeId: ID-O14-1583317250038-0-1 with Exchange[ID-O14-1583317250038-0-1]
2020-03-04 11:20:50,039 TRACE [o.a.camel.component.cxf.CxfConsumer] (XNIO-1 task-1) {camel.exchangeId=ID-O14-1583317250038-0-1, CBSS-Trace-InboundTicket=06ab8f30-bfae-471b-8901-528d82477613, camel.contextId=camel-1, camel.messageId=ID-O14-1583317250038-0-2} Suspending continuation of exchangeId: ID-O14-1583317250038-0-1
=> Here, Camel added its own MDC context variables
...
2020-03-04 11:20:50,326 DEBUG [o.a.c.t.servlet.ServletController] (XNIO-1 task-1) {camel.exchangeId=ID-O14-1583317250038-0-1, camel.contextId=camel-1, CBSS-Trace-InboundTicket=06ab8f30-bfae-471b-8901-528d82477613, camel.routeId=call-sskm, camel.messageId=ID-O14-1583317250038-0-2} Finished servicing http request on thread: Thread[XNIO-1 task-1,5,main]
2020-03-04 11:20:50,326 TRACE [o.s.b.w.s.f.OrderedRequestContextFilter] (XNIO-1 task-1) {camel.exchangeId=ID-O14-1583317250038-0-1, camel.contextId=camel-1, camel.routeId=call-sskm, camel.messageId=ID-O14-1583317250038-0-2} Cleared thread-bound request context: HttpServletRequestImpl [ POST /DB2PConsultContributionService/consult ]
2020-03-04 11:20:50,327 TRACE [org.xnio.nio.selector] (XNIO-1 I/O-1) {} Selected on sun.nio.ch.WindowsSelectorImpl@3511c7
2020-03-04 11:20:50,327 TRACE [org.xnio.nio.selector] (XNIO-1 I/O-1) {} Beginning select on sun.nio.ch.WindowsSelectorImpl@3511c7 (with timeout)
2020-03-04 11:20:50,327 DEBUG [s.n.w.p.http.HttpURLConnection] (default-workqueue-1) {} sun.net.www.MessageHeader@5d05f5811 pairs: {POST /sskm/v2/SskmService_oops HTTP/1.1: null}
{Accept: /}
{CBSS-Trace-InboundTicket: 06ab8f30-bfae-471b-8901-528d82477613}{SOAPAction: "http://kszbcss.fgov.be/SskmService/getDataProviders"}
{User-Agent: Apache-CXF/3.3.4}{Cache-Control: no-cache}
{Pragma: no-cache}{Host: dsvc.cbss.inet}
{Connection: keep-alive}{Content-Length: 553}
2020-03-04 11:20:50,333 TRACE [s.n.w.p.http.HttpURLConnection] (default-workqueue-1) {} KeepAlive stream used: http://dsvc.cbss.inet/sskm/v2/SskmService_oops
2020-03-04 11:20:50,335 DEBUG [s.n.w.p.http.HttpURLConnection] (default-workqueue-1) {} sun.net.www.MessageHeader@40d2c1869 pairs: {null: HTTP/1.1 404 Not Found}
{X-Powered-By: Servlet/3.0}{$WSEP: }{Content-Length: 119}
{Keep-Alive: timeout=10, max=100}{Connection: Keep-Alive}
{Content-Type: text/html;charset=UTF-8}{Content-Language: en-US}
2020-03-04 11:20:50,336 DEBUG [o.a.cxf.phase.PhaseInterceptorChain] (default-workqueue-1) {} Invoking handleFault on interceptor org.apache.cxf.interceptor.MessageSenderInterceptor$MessageSenderEndingInterceptor@3c9f67c
=> Here, we see the request being passed off to a "default-workqueue" thread, and the MDC is gone
...
2020-03-04 11:20:50,348 ERROR [b.f.k.camel.support.XslMessageLogger] (default-workqueue-1) {} file:/D:/projects/db2p-consult-contribution/db2p-consult-contribution-camel/target/classes/common-functions/handle-internal-service-fault.xslt#58: Soap Fault without reasonCode MSG00002 received from internal service. Returning MSG00003 SOAP Fault to caller. The original Fault received was: <SOAP-ENV:Fault><faultcode xmlns:SOAP-ENV="http://schemas.xmlsoap.org/soap/envelope/">SOAP-ENV:Server</faultcode><faultstring>org.apache.cxf.transport.http.HTTPException: HTTP response '404: Not Found' when communicating with http://dsvc.cbss.inet/sskm/v2/SskmService_oops</faultstring><faultactor>http://www.ksz-bcss.fgov.be/</faultactor></SOAP-ENV:Fault>
Error at char 1 in xsl:copy-of/@select on line 58 column 30 of handle-internal-service-fault.xslt:
XTMM9000: Processing terminated by xsl:message at line 58 in handle-internal-service-fault.xslt
=> Then, we have 2 ERROR logs with missing MDC context
...
2020-03-04 11:20:50,378 DEBUG [o.a.c.i.e.DefaultReactiveExecutor] (default-workqueue-1) {camel.routeId=call-sskm} Queuing reactive work: Callback[org.apache.camel.processor.CamelInternalProcessor$$Lambda$1182/1240607953@5385b8fa]
2020-03-04 11:20:50,378 TRACE [o.a.c.i.e.DefaultReactiveExecutor] (default-workqueue-1) {camel.routeId=call-sskm} Running: Step[ID-O14-1583317250038-0-1,DefaultErrorHandler[sendTo(soap-call://sskmService)]]
2020-03-04 11:20:50,378 TRACE [o.a.c.m.DefaultInstrumentationProcessor] (default-workqueue-1) {camel.exchangeId=ID-O14-1583317250038-0-1, camel.contextId=camel-1, CBSS-Trace-InboundTicket=06ab8f30-bfae-471b-8901-528d82477613, camel.routeId=call-sskm, camel.messageId=ID-O14-1583317250038-0-2} to: Recording duration: 141 millis for exchange: Exchange[ID-O14-1583317250038-0-1]
2020-03-04 11:20:50,378 TRACE [o.a.c.i.e.DefaultReactiveExecutor] (default-workqueue-1) {camel.exchangeId=ID-O14-1583317250038-0-1, camel.contextId=camel-1, CBSS-Trace-InboundTicket=06ab8f30-bfae-471b-8901-528d82477613, camel.routeId=call-sskm, camel.messageId=ID-O14-1583317250038-0-2} Schedule [first=true, main=false, sync=false]: Callback[org.apache.camel.processor.Pipeline$$Lambda$1185/2003970840@3adacd81]
=> At this point, the MDC context is available again.
...
2020-03-04 11:20:50,379 TRACE [o.a.camel.component.cxf.CxfConsumer] (default-workqueue-1) {camel.exchangeId=ID-O14-1583317250038-0-1, camel.contextId=camel-1, CBSS-Trace-InboundTicket=06ab8f30-bfae-471b-8901-528d82477613, camel.messageId=ID-O14-1583317250038-0-2} Resuming continuation of exchangeId: ID-O14-1583317250038-0-1
2020-03-04 11:20:50,380 TRACE [org.xnio.nio.selector] (XNIO-1 I/O-1) {} Selected on sun.nio.ch.WindowsSelectorImpl@3511c7
2020-03-04 11:20:50,380 TRACE [org.xnio.nio.selector] (XNIO-1 I/O-1) {} Beginning select on sun.nio.ch.WindowsSelectorImpl@3511c7 (with timeout)
2020-03-04 11:20:50,382 DEBUG [o.a.c.c.cxf.CxfClientCallback] (default-workqueue-1) {camel.exchangeId=ID-O14-1583317250038-0-1, camel.contextId=camel-1, CBSS-Trace-InboundTicket=06ab8f30-bfae-471b-8901-528d82477613, camel.messageId=ID-O14-1583317250038-0-2} default-workqueue-1 calling handleException
2020-03-04 11:20:50,383 DEBUG [o.a.c.t.servlet.ServletController] (XNIO-1 task-2) {} Service http request on thread: Thread[XNIO-1 task-2,5,default-workqueue]
=> Then, processing is passed off to yet another thread (for the response processing I presume), which also doesn't have the MDC context