Jimmy Praet created CAMEL-14653:
-----------------------------------
Summary: MDC is not passed from "XNIO-1 task" thread to
"default-workqueue" thread
Key: CAMEL-14653
URL: https://issues.apache.org/jira/browse/CAMEL-14653
Project: Camel
Issue Type: Bug
Components: came-core
Affects Versions: 3.0.1
Reporter: Jimmy Praet
Attachments: camel-mdc-trace.txt
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}{Content-Type: text/xml;
charset=UTF-8}\{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}{Date: Wed, 04 Mar 2020 10:20:50 GMT}\{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*
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
