[jira] [Commented] (CAMEL-14653) MDC is not passed from "XNIO-1 task" thread to "default-workqueue" thread
[
https://issues.apache.org/jira/browse/CAMEL-14653?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17052102#comment-17052102
]
Jimmy Praet commented on CAMEL-14653:
-
The problem only occurs when "synchronous=false" (which is the default) on the
CXF endpoint. It works fine if I configure "synchronous=true", which I'll do
for now as a workaround.
> 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-cxf
>Affects Versions: 3.0.1
>Reporter: Jimmy Praet
>Priority: Minor
> 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}
> 20
[jira] [Created] (CAMEL-14653) MDC is not passed from "XNIO-1 task" thread to "default-workqueue" thread
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 reasonCod
[jira] [Updated] (CAMEL-13958) XPathBuilder threadSafe mode should also be enabled when the NodeList contains only 1 item
[
https://issues.apache.org/jira/browse/CAMEL-13958?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Jimmy Praet updated CAMEL-13958:
Description:
In CAMEL-10225 the "threadSafety" property was added. But looking at the code,
it is only enabled when the NodeList contains 2 or more items:
XPathBuilder:
[https://github.com/apache/camel/blob/master/components/camel-xpath/src/main/java/org/apache/camel/language/xpath/XPathBuilder.java#L1064]
{code:java}
if (threadSafety && answer != null && answer instanceof NodeList) {
try {
NodeList list = (NodeList)answer;// when the
result is NodeList and it has 2+ elements then its
// not thread-safe to use concurrently
// and we need to clone each node and build a thread-safe list
// to be used instead
boolean threadSafetyNeeded = list.getLength() >= 2;
if (threadSafetyNeeded) {
answer = new ThreadSafeNodeList(list);
if (LOG.isDebugEnabled()) {
LOG.debug("Created thread-safe result from: {} as: {}",
list.getClass().getName(), answer.getClass().getName());
}
}
} catch (Exception e) {
throw ObjectHelper.wrapRuntimeCamelException(e);
}
}
{code}
But I get the same type of error as mentioned in CAMEL-10225 when my NodeList
only contains 1 item:
{code:java}
org.apache.camel.TypeConversionException: Error during type conversion from
type: java.lang.String to the required type: java.io.InputStream with value
84073120992 due java.lang.NullPointerException
at
org.apache.camel.impl.converter.BaseTypeConverterRegistry.createTypeConversionException(BaseTypeConverterRegistry.java:666)
at
org.apache.camel.impl.converter.BaseTypeConverterRegistry.convertTo(BaseTypeConverterRegistry.java:157)
at org.apache.camel.impl.MessageSupport.getBody(MessageSupport.java:87)
at org.apache.camel.impl.MessageSupport.getBody(MessageSupport.java:61)
at org.apache.camel.builder.xml.XsltBuilder.process(XsltBuilder.java:124)
at
org.apache.camel.impl.ProcessorEndpoint.onExchange(ProcessorEndpoint.java:103)
at
org.apache.camel.component.xslt.XsltEndpoint.onExchange(XsltEndpoint.java:139)
at
org.apache.camel.impl.ProcessorEndpoint$1.process(ProcessorEndpoint.java:71)
at
org.apache.camel.util.AsyncProcessorConverterHelper$ProcessorToAsyncProcessorBridge.process(AsyncProcessorConverterHelper.java:61)
at org.apache.camel.processor.SendProcessor.process(SendProcessor.java:148)
at
org.apache.camel.processor.RedeliveryErrorHandler.process(RedeliveryErrorHandler.java:548)
at
org.apache.camel.processor.CamelInternalProcessor.process(CamelInternalProcessor.java:201)
at org.apache.camel.processor.Pipeline.process(Pipeline.java:138)
at org.apache.camel.processor.Pipeline.process(Pipeline.java:101)
at
org.apache.camel.processor.CamelInternalProcessor.process(CamelInternalProcessor.java:201)
at
org.apache.camel.component.direct.DirectProducer.process(DirectProducer.java:76)
at org.apache.camel.processor.SendProcessor.process(SendProcessor.java:148)
at
org.apache.camel.processor.RedeliveryErrorHandler.process(RedeliveryErrorHandler.java:548)
at
org.apache.camel.processor.CamelInternalProcessor.process(CamelInternalProcessor.java:201)
at org.apache.camel.processor.Pipeline.process(Pipeline.java:138)
at org.apache.camel.processor.Pipeline.process(Pipeline.java:101)
at
org.apache.camel.processor.CamelInternalProcessor.process(CamelInternalProcessor.java:201)
at
org.apache.camel.component.direct.DirectProducer.process(DirectProducer.java:76)
at
org.apache.camel.processor.RedeliveryErrorHandler.process(RedeliveryErrorHandler.java:548)
at
org.apache.camel.processor.CamelInternalProcessor.process(CamelInternalProcessor.java:201)
at
org.apache.camel.util.AsyncProcessorHelper.process(AsyncProcessorHelper.java:109)
at
org.apache.camel.processor.MulticastProcessor.doProcessParallel(MulticastProcessor.java:859)
at
org.apache.camel.processor.MulticastProcessor.access$200(MulticastProcessor.java:86)
at
org.apache.camel.processor.MulticastProcessor$1.call(MulticastProcessor.java:330)
at
org.apache.camel.processor.MulticastProcessor$1.call(MulticastProcessor.java:316)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at
be.fgov.kszbcss.tracer.concurrent.TracerRunnable.run(TracerRunnable.java:27)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
Caused by: org.apache.camel.RuntimeCamelException:
java.lang.NullPointerException
at
org.apache.camel.util.ObjectHelp
[jira] [Created] (CAMEL-13958) XPathBuilder threadSafe mode should also be enabled when the NodeList contains only 1 item
Jimmy Praet created CAMEL-13958:
---
Summary: XPathBuilder threadSafe mode should also be enabled when
the NodeList contains only 1 item
Key: CAMEL-13958
URL: https://issues.apache.org/jira/browse/CAMEL-13958
Project: Camel
Issue Type: Bug
Components: camel-saxon
Affects Versions: 2.24.1
Reporter: Jimmy Praet
In CAMEL-10225 a the threadSafe property was added, but looking at the code, it
is only enabled when the NodeList contains 2 or more items:
XPathBuilder:
[https://github.com/apache/camel/blob/master/components/camel-xpath/src/main/java/org/apache/camel/language/xpath/XPathBuilder.java#L1064]
{code:java}
if (threadSafety && answer != null && answer instanceof NodeList) {
try {
NodeList list = (NodeList)answer;// when the
result is NodeList and it has 2+ elements then its
// not thread-safe to use concurrently
// and we need to clone each node and build a thread-safe list
// to be used instead
boolean threadSafetyNeeded = list.getLength() >= 2;
if (threadSafetyNeeded) {
answer = new ThreadSafeNodeList(list);
if (LOG.isDebugEnabled()) {
LOG.debug("Created thread-safe result from: {} as: {}",
list.getClass().getName(), answer.getClass().getName());
}
}
} catch (Exception e) {
throw ObjectHelper.wrapRuntimeCamelException(e);
}
}
{code}
But I get the same type of error as mentioned in CAMEL-10225 when my NodeList
only contains 1 item:
{code:java}
org.apache.camel.TypeConversionException: Error during type conversion from
type: java.lang.String to the required type: java.io.InputStream with value
84073120992 due java.lang.NullPointerException
at
org.apache.camel.impl.converter.BaseTypeConverterRegistry.createTypeConversionException(BaseTypeConverterRegistry.java:666)
at
org.apache.camel.impl.converter.BaseTypeConverterRegistry.convertTo(BaseTypeConverterRegistry.java:157)
at org.apache.camel.impl.MessageSupport.getBody(MessageSupport.java:87)
at org.apache.camel.impl.MessageSupport.getBody(MessageSupport.java:61)
at org.apache.camel.builder.xml.XsltBuilder.process(XsltBuilder.java:124)
at
org.apache.camel.impl.ProcessorEndpoint.onExchange(ProcessorEndpoint.java:103)
at
org.apache.camel.component.xslt.XsltEndpoint.onExchange(XsltEndpoint.java:139)
at
org.apache.camel.impl.ProcessorEndpoint$1.process(ProcessorEndpoint.java:71)
at
org.apache.camel.util.AsyncProcessorConverterHelper$ProcessorToAsyncProcessorBridge.process(AsyncProcessorConverterHelper.java:61)
at org.apache.camel.processor.SendProcessor.process(SendProcessor.java:148)
at
org.apache.camel.processor.RedeliveryErrorHandler.process(RedeliveryErrorHandler.java:548)
at
org.apache.camel.processor.CamelInternalProcessor.process(CamelInternalProcessor.java:201)
at org.apache.camel.processor.Pipeline.process(Pipeline.java:138)
at org.apache.camel.processor.Pipeline.process(Pipeline.java:101)
at
org.apache.camel.processor.CamelInternalProcessor.process(CamelInternalProcessor.java:201)
at
org.apache.camel.component.direct.DirectProducer.process(DirectProducer.java:76)
at org.apache.camel.processor.SendProcessor.process(SendProcessor.java:148)
at
org.apache.camel.processor.RedeliveryErrorHandler.process(RedeliveryErrorHandler.java:548)
at
org.apache.camel.processor.CamelInternalProcessor.process(CamelInternalProcessor.java:201)
at org.apache.camel.processor.Pipeline.process(Pipeline.java:138)
at org.apache.camel.processor.Pipeline.process(Pipeline.java:101)
at
org.apache.camel.processor.CamelInternalProcessor.process(CamelInternalProcessor.java:201)
at
org.apache.camel.component.direct.DirectProducer.process(DirectProducer.java:76)
at
org.apache.camel.processor.RedeliveryErrorHandler.process(RedeliveryErrorHandler.java:548)
at
org.apache.camel.processor.CamelInternalProcessor.process(CamelInternalProcessor.java:201)
at
org.apache.camel.util.AsyncProcessorHelper.process(AsyncProcessorHelper.java:109)
at
org.apache.camel.processor.MulticastProcessor.doProcessParallel(MulticastProcessor.java:859)
at
org.apache.camel.processor.MulticastProcessor.access$200(MulticastProcessor.java:86)
at
org.apache.camel.processor.MulticastProcessor$1.call(MulticastProcessor.java:330)
at
org.apache.camel.processor.MulticastProcessor$1.call(MulticastProcessor.java:316)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at
be.fgov.kszbcss.tracer.concurrent.TracerRunnable.run(TracerRunnable.java:27)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at
java.util.concurrent.
[jira] [Commented] (CAMEL-7444) Camel MDC - Should propagate all keys
[ https://issues.apache.org/jira/browse/CAMEL-7444?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16634073#comment-16634073 ] Jimmy Praet commented on CAMEL-7444: +1, I also ran into this issue. > Camel MDC - Should propagate all keys > - > > Key: CAMEL-7444 > URL: https://issues.apache.org/jira/browse/CAMEL-7444 > Project: Camel > Issue Type: Improvement > Components: camel-core >Reporter: Claus Ibsen >Priority: Minor > Fix For: Future > > > When using MDC in Camel, then we only propagate a fixed known number of keys > that are Camel specific. > We should open this so we propagate any custom mdc keys too. > See > http://camel.465427.n5.nabble.com/Camel-MDC-Logging-td5751180.html -- This message was sent by Atlassian JIRA (v7.6.3#76005)
