camel-users mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Bjørn Ellingsen <bjorn.elling...@baymarkets.com>
Subject Re: Lost messages when streaming with Jetty
Date Tue, 14 Jun 2016 13:38:53 GMT
Hi, enabling MDC to tie output together, I can see some discrepancies 
between the OK and the NOT-OK cases (these are probably present when 
turning on trace logging as well, but are harder to catch due to the 
vast amount of log statements):

OK scenario:

2016-06-14 15:27:01.029 [INFO] [CamelStreamConverterTest] [ID-bel-45088-1465910818280-0-4530]:
[ID-bel-45088-1465910818280-0-4530] Before Bean[tmp.CamelStreamConverterTest$Foo@239a307b]
with body org.apache.camel.converter.stream.InputStreamCache@6211d210
2016-06-14 15:27:01.029 [DEBUG] [MethodInfo] [ID-bel-45088-1465910818280-0-4530]: Setting
bean invocation result on the IN message: OK
2016-06-14 15:27:01.029 [INFO] [CamelStreamConverterTest] [ID-bel-45088-1465910818280-0-4530]:
[ID-bel-45088-1465910818280-0-4530] After Bean[tmp.CamelStreamConverterTest$Foo@239a307b]
with body OK

NOT-OK scenario:

2016-06-14 15:27:01.033 [INFO] [CamelStreamConverterTest] [ID-bel-45088-1465910818280-0-4542]:
[ID-bel-45088-1465910818280-0-4542] Before Bean[tmp.CamelStreamConverterTest$Foo@239a307b]
with body org.apache.camel.converter.stream.InputStreamCache@6002fb72
2016-06-14 15:27:01.033 [INFO] [CamelStreamConverterTest] [ID-bel-45088-1465910818280-0-4542]:
[ID-bel-45088-1465910818280-0-4542] After Bean[tmp.CamelStreamConverterTest$Foo@239a307b]
with body org.apache.camel.converter.stream.InputStreamCache@6002fb72

The main difference being absence of the MethodInfo log statement, and 
that body in the after log is "OK" - which is the text returned from the 
bean - for the first case, while still a InputStreamCache in the latter 
case (because the exchange failed).

Regards,
Bjørn E.

On 14. juni 2016 14:35, souciance wrote:

> Hi,
>
> Yeah probably something between the VM endpoint and the bean caused this.
>
> I extend CamelBlueprintTestSupport but works for normal CamelTestSupport as
> well. Hopefully the debug log will reveal what could be going wrong in
> between. See below for adding the debug methods:
>
> public class yourtestclass extends CamelBlueprintTestSpport {
>
> private boolean debugBeforeMethodCalled:
> private boolean debugAfterMethodCalled:
>
> public void test() throws Exception {}
>
> @Override
> protected void debugBefore(Exchange exchange,
> org.apache.camel.Processor processor, ProcessorDefinition<?>
> definition, String id, String label) {
>    log.info("Before " + definition + " with body " + exchange.getIn().getBody());
>    debugBeforeMethodCalled = true;
> }
>
> @Override
> protected void debugAfter(Exchange exchange,
> org.apache.camel.Processor processor, ProcessorDefinition<?>
> definition, String id, String label, long timeTaken) {
>    log.info("After " + definition + " with body " + exchange.getIn().getBody());
>    debugAfterMethodCalled = true;
> }
>
> }
>
> On Tue, Jun 14, 2016 at 2:28 PM, Bjørn Ellingsen-2 [via Camel] <
> ml-node+s465427n5784027h0@n5.nabble.com> wrote:
>
>> Thanks for the quick reply, adding a log step to the route right after
>> message is received by the jetty component confirms that all exchanges
>> have a complete body at that point. I suspect the issue is related to
>> the transition from delivery to vm:test and consumption by the bean from
>> the same endpoint.
>>
>> As to the debug logging methods: what API do these methods override?
>>
>> Regards,
>> Bjørn E.
>>
>> On 14. juni 2016 14:03, souciance wrote:
>>
>>> Hello,
>>>
>>> I am not able to test this at the moment but what happens if you change
>> the
>>> first "from" to from("jetty:" + URI).log("${body} and ${headers}".to("")
>>>
>>> In the case of the empty messages, does the log statement also show that
>>> the body being empty?
>>>
>>> You can also include debug level logs in your test to further break
>> things
>>> down to see if there is something obvious going on. To do that include
>> the
>>> variables:
>>> private boolean debugBeforeMethodCalled:
>>> private boolean debugAfterMethodCalled:
>>>
>>> Include the methods:
>>>
>>> @Override
>>> protected void debugBefore(Exchange exchange,
>>> org.apache.camel.Processor processor, ProcessorDefinition<?>
>>> definition, String id, String label) {
>>>     log.info("Before " + definition + " with body " +
>> exchange.getIn().getBody());
>>>     debugBeforeMethodCalled = true;
>>> }
>>>
>>> @Override
>>> protected void debugAfter(Exchange exchange,
>>> org.apache.camel.Processor processor, ProcessorDefinition<?>
>>> definition, String id, String label, long timeTaken) {
>>>     log.info("After " + definition + " with body " +
>> exchange.getIn().getBody());
>>>     debugAfterMethodCalled = true;
>>> }
>>>
>>>
>>>
>>> Best
>>> Souciance
>>>
>>> On Tue, Jun 14, 2016 at 1:44 PM, Bjørn Ellingsen-2 [via Camel] <
>>> [hidden email] <http:///user/SendEmail.jtp?type=node&node=5784027&i=0>>
>> wrote:
>>>> Hi, I get sporadic cases of no body when having a client sending small
>>>> JSON messages over http, and a jetty endpoint receiving them, and a
>>>> short route with a vm endpoint and a bean. Stream-caching is enabled.
>>>> The issue only appears when MEP is InOnly. A simple test case to
>>>> reproduce the issue is attached, you might have to adjust (increase)
>> the
>>>> message count if test executes without failure.
>>>>
>>>> Enabling trace logging on org.apache.camel, there is only one log
>>>> statement I noticed to differ when message came through vs. was lost:
>>>>
>>>> 2016-06-14 12:50:49.441 [TRACE] [MethodInfo] []: Parameter #0 evaluated
>>>> as:
>>>>
>> {"key1":"value1","key2":"value2","key3":"value3","key4":"value4","key5":"value5"}
>>
>>>> type:
>>>>
>>>> vs.:
>>>>
>>>> 2016-06-14 12:50:49.547 [TRACE] [MethodInfo] []: Parameter #0 evaluated
>>>> as:  type:
>>>>
>>>> The number of lost messages - or empty bodied messages - when running
>>>> this test case is in the range 5-50 (out of 800). I have avoided the
>>>> issue for now by converting the body from stream to string, but I would
>>>> really like to know if I'm using the API wrong or if there is a bug
>>>> hidden somewhere. Any help appreciated.
>>>>
>>>> Versions etc:
>>>> Camel: 2.17.1
>>>> JDK: 1.8.0_77
>>>> Jetty: 9.2.15 (also tried 9.1.6)
>>>> OS: Fedora + RHEL
>>>> Same result if using other client than camel-http
>>>>
>>>> Regards,
>>>> Bjørn E.
>>>>
>>>> *CamelStreamConverterTest.java* (1K) Download Attachment
>>>> <
>> http://camel.465427.n5.nabble.com/attachment/5784020/0/CamelStreamConverterTest.java>
>>
>>>> *log4j2-test.xml* (476 bytes) Download Attachment
>>>> <http://camel.465427.n5.nabble.com/attachment/5784020/1/log4j2-test.xml>
>>>> *pom.xml* (1K) Download Attachment
>>>> <http://camel.465427.n5.nabble.com/attachment/5784020/2/pom.xml>
>>>>
>>>>
>>>> ------------------------------
>>>> If you reply to this email, your message will be added to the
>> discussion
>>>> below:
>>>>
>>>>
>> http://camel.465427.n5.nabble.com/Lost-messages-when-streaming-with-Jetty-tp5784020.html
>>>> To start a new topic under Camel - Users, email
>>>> [hidden email] <http:///user/SendEmail.jtp?type=node&node=5784027&i=1>
>>>> To unsubscribe from Camel - Users, click here
>>>> <
>>>> .
>>>> NAML
>>>> <
>> http://camel.465427.n5.nabble.com/template/NamlServlet.jtp?macro=macro_viewer&id=instant_html%21nabble%3Aemail.naml&base=nabble.naml.namespaces.BasicNamespace-nabble.view.web.template.NabbleNamespace-nabble.view.web.template.NodeNamespace&breadcrumbs=notify_subscribers%21nabble%3Aemail.naml-instant_emails%21nabble%3Aemail.naml-send_instant_email%21nabble%3Aemail.naml>
>>
>>>
>>>
>>> --
>>> View this message in context:
>> http://camel.465427.n5.nabble.com/Lost-messages-when-streaming-with-Jetty-tp5784020p5784023.html
>>> Sent from the Camel - Users mailing list archive at Nabble.com.
>>
>>
>> ------------------------------
>> If you reply to this email, your message will be added to the discussion
>> below:
>>
>> http://camel.465427.n5.nabble.com/Lost-messages-when-streaming-with-Jetty-tp5784020p5784027.html
>> To start a new topic under Camel - Users, email
>> ml-node+s465427n465428h31@n5.nabble.com
>> To unsubscribe from Camel - Users, click here
>> <http://camel.465427.n5.nabble.com/template/NamlServlet.jtp?macro=unsubscribe_by_code&node=465428&code=c291Y2lhbmNlLmVxZGFtLnJhc2h0aUBnbWFpbC5jb218NDY1NDI4fDE1MzI5MTE2NTY=>
>> .
>> NAML
>> <http://camel.465427.n5.nabble.com/template/NamlServlet.jtp?macro=macro_viewer&id=instant_html%21nabble%3Aemail.naml&base=nabble.naml.namespaces.BasicNamespace-nabble.view.web.template.NabbleNamespace-nabble.view.web.template.NodeNamespace&breadcrumbs=notify_subscribers%21nabble%3Aemail.naml-instant_emails%21nabble%3Aemail.naml-send_instant_email%21nabble%3Aemail.naml>
>>
>
>
>
> --
> View this message in context: http://camel.465427.n5.nabble.com/Lost-messages-when-streaming-with-Jetty-tp5784020p5784029.html
> Sent from the Camel - Users mailing list archive at Nabble.com.


Mime
  • Unnamed multipart/alternative (inline, None, 0 bytes)
View raw message