Re: [SR-Users] evapi tcp parsing??

22 Sep 2015

Hi,
Took time to get back with the test results as I was trying to analyze too
much myself before getting back on the list. Also I was stuck with weird
error of module version mismatch, but I figured and solved that issue.
So I do see the logs "frame size mismatch" when I miss the events. Since
the logs are too huge, I am sending it in pastebin. Here it is:
http://pastebin.com/MzTpYsrk

In Kamailio Logs, I see:
DEBUG: evapi [evapi_dispatch.c:361]: evapi_recv_client(): frame size
mismatch the ending char
(h):[{"event":"REGISTER","tindex":"12603","tlabel":"626010915
","PhoneNumber":"42000","D146:"event":"REGISTER","tindex":"3639","tlabel":"
1889788252","P] (146)

Whereas the messages in ngrep looks good where the messages are split in
two TCP packets. The first packet ends at D and the second packet is the
proper continuation which send the rest. But it feels Kamailio skipped the
beginning of the message and started parsing at colon again and it thinks
the netstring started with D146 which is incorrect. Hence, it never emitted
any event for the messages in the first chunk.

Hoping this to be helpful !! Thanks.

- Jayesh

On Mon, Sep 21, 2015 at 4:37 PM Daniel-Constantin Mierla &lt;miconda(a)gmail.com&gt;
wrote:

...
  Hello,

 I pushed another commit to add more debug messages to see if the event
 route is supposed to be executed or not. Can you run the tests again and
 give again the log messages for missing event route executions?

 Cheers,
 Daniel

 On 21/09/15 09:04, Jayesh Nambiar wrote:

 Hi Daniel,
 I have captured debug messages after testing with your latest commit on
 master. Once again, here's what I'm doing exactly for my test:
 1) Use SIPp to send OPTIONS towards Kamailio.
 2) On getting options send event as follows:

evapi_async_relay("{\"event\":\"REGISTER\",\"tindex\":\"$T(id_index)\",\"tlabel\":\"$T(id_label)\",\"PhoneNumber\":\"$avp(phone_number)\",\"DeviceId\":\"$avp(device_id)\",\"CallId\":\"$ci\"}");
 3) There's a client connected which listens for messages on this socket,
 parses the netstring, and sends same data back as netstring to Kamailio.
 4) On the event_route[evapi:message-received, I do the following:
 xlog("L_INFO", "GOT [$evapi(msg)] from
$evapi(srcaddr):$evapi(srcport)\n");
     if($evapi(msg)=~"REGISTER" && $evapi(msg)=~"tindex") {
       jansson_get_field("$evapi(msg)", "tlabel",
"$var(tlabel)");
     jansson_get_field("$evapi(msg)", "tindex",
"$var(tindex)");
        $var(t_index) = $(var(tindex){s.int});
     $var(t_label) = $(var(tlabel){s.int});
        t_continue('$var(t_index)', '$var(t_label)',
'REGISTER_RESPONSE');
     exit;
     }
 5) On route[REGISTER_RESPONSE], I send 200 OK to SIPp

 Now here are detailed logs for which neither SIPp didnt get a response nor
 the GOT [$evapi(msg)] from $evapi(srcaddr):$evapi(srcport)\n"); got logged
 in the syslog:

 First Event:
 DEBUG: evapi [evapi_dispatch.c:598]: evapi_relay(): relaying event data

[{"event":"REGISTER","tindex":"26266","tlabel":"587925078","PhoneNumber":"21956","DeviceId":"abcd1234abcd1234","CallId":"
 <23021-12910@198.24.63.39>23021-12910@198.24.63.39"}] (146)
 DEBUG: evapi [evapi_dispatch.c:623]: evapi_relay(): sending
 [0x7f132588de68]

[146:{"event":"REGISTER","tindex":"26266","tlabel":"587925078","PhoneNumber":"21956","DeviceId":"abcd1234abcd1234","CallId":"
 <23021-12910@198.24.63.39>23021-12910@198.24.63.39"},] (151)

 DEBUG: evapi [evapi_dispatch.c:488]: evapi_recv_notify(): received
 [0x7f132588de68]

[146:{"event":"REGISTER","tindex":"26266","tlabel":"587925078","PhoneNumber":"21956","DeviceId":"abcd1234abcd1234","CallId":"
 <23021-12910@198.24.63.39>23021-12910@198.24.63.39"},] (151)
 NOTICE: evapi [evapi_dispatch.c:290]: evapi_recv_client(): {0} [
 198.24.63.45:48881] - received

[146:{"event":"REGISTER","tindex":"26266","tlabel":"587925078","PhoneNumber":"21956","DeviceId":"abcd1234abcd1234","CallId":"
 <23021-12910@198.24.63.39>23021-12910@198.24.63.39"},] (151) (18)

 Second Event:
 DEBUG: evapi [evapi_dispatch.c:598]: evapi_relay(): relaying event data

[{"event":"REGISTER","tindex":"32244","tlabel":"1637923412","PhoneNumber":"25597","DeviceId":"abcd1234abcd1234","CallId":"
 <27182-12910@198.24.63.39>27182-12910@198.24.63.39"}] (147)
   DEBUG: evapi [evapi_dispatch.c:623]: evapi_relay(): sending
 [0x7f1325884410]

[147:{"event":"REGISTER","tindex":"32244","tlabel":"1637923412","PhoneNumber":"25597","DeviceId":"abcd1234abcd1234","CallId":"
 <27182-12910@198.24.63.39>27182-12910@198.24.63.39"},] (152)

   DEBUG: evapi [evapi_dispatch.c:488]: evapi_recv_notify(): received
 [0x7f1325884410]

[147:{"event":"REGISTER","tindex":"32244","tlabel":"1637923412","PhoneNumber":"25597","DeviceId":"abcd1234abcd1234","CallId":"
 <27182-12910@198.24.63.39>27182-12910@198.24.63.39"},] (152)
   NOTICE: evapi [evapi_dispatch.c:290]: evapi_recv_client(): {0} [
 198.24.63.45:48881] - received

[147:{"event":"REGISTER","tindex":"32244","tlabel":"1637923412","PhoneNumber":"25597","DeviceId":"abcd1234abcd1234","CallId":"
 <27182-12910@198.24.63.39>27182-12910@198.24.63.39"},] (152) (85)

 I had three such events which got missed out of some 25000 odd messages
 sent from SIPp. Other major difference that I see in the debug logs for
 problematic events are that there is a positive number in the second
 parentheses of evapi_recv_client() function. For the events that were
 invoked successfully the value of second parentheses is 0 for
 evapi_recv_client() function. Hope the debugging helps.

 Debug log for a successful event:
 DEBUG: evapi [evapi_dispatch.c:598]: evapi_relay(): relaying event data

[{"event":"REGISTER","tindex":"22127","tlabel":"1896682192","PhoneNumber":"73168","DeviceId":"abcd1234abcd1234","CallId":"
 <49957-13056@198.24.63.39>49957-13056@198.24.63.39"}] (147)
   DEBUG: evapi [evapi_dispatch.c:623]: evapi_relay(): sending
 [0x7f132568e850]

[147:{"event":"REGISTER","tindex":"22127","tlabel":"1896682192","PhoneNumber":"73168","DeviceId":"abcd1234abcd1234","CallId":"
 <49957-13056@198.24.63.39>49957-13056@198.24.63.39"},] (152)

   DEBUG: evapi [evapi_dispatch.c:488]: evapi_recv_notify(): received
 [0x7f132568e850]

[147:{"event":"REGISTER","tindex":"22127","tlabel":"1896682192","PhoneNumber":"73168","DeviceId":"abcd1234abcd1234","CallId":"
 <49957-13056@198.24.63.39>49957-13056@198.24.63.39"},] (152)
   NOTICE: evapi [evapi_dispatch.c:290]: evapi_recv_client(): {0} [
 198.24.63.45:48881] - received

[147:{"event":"REGISTER","tindex":"22127","tlabel":"1896682192","PhoneNumber":"73168","DeviceId":"abcd1234abcd1234","CallId":"
 <49957-13056@198.24.63.39>49957-13056@198.24.63.39"},] (152) (0)

 Thanks,

 - Jayesh
 On Sat, Sep 19, 2015 at 3:55 AM Daniel-Constantin Mierla <
 miconda(a)gmail.com&gt; wrote:

  I pushed a commit to add more debug message while
processing received
 data. You can use debugger module to set a higher debug level for evapi
 module in order to see what happens.

 I checked the netstring packet size and it is invalid (unless email
 stripped some white chars there) -- for example in:

145:{"event":"REGISTER","tindex":"55567","tlabel":"627458699","PhoneNumber":"20711","DeviceId":"abcd1234abcd1234","CallId":
 <21225-3848@5.6.7.8>"21225-3848@5.6.7.8" &lt;21225-3848(a)5.6.7.8&gt;}8>},

 the size is 141, not 145 -- it looks like the size includes the size
 itself plus the delimiters ':,'. The size is only the effective data, see:

 https://en.wikipedia.org/wiki/Netstring

 If evapi gets a packet with an invalid size, then it discards the buffer
 content.

 See if the app on the other side of evapi connection builds netstrings
 with wrong size.

 Cheers,
 Daniel

 On 18/09/15 23:19, Jayesh Nambiar wrote:

 Here are the tests that I did:

 With the patch applied, I see that Kamailio is invoking event
 individually for each netstring even when they come in different chunks.
 But I did see instances where when there were complete netstrings in a
 single chunk; kamailio did not raise an event for them. Here's the
 illustration:

 T 1.2.3.4:48873 -> 5.6.7.8:3927 [AP]

146:{"event":"REGISTER","tindex":"16916","tlabel":"1753048277","PhoneNumber":"20708","DeviceId":"abcd1234abcd1234","CallId":"
 <21220-3848@5.6.7.8>21220-3848@5.6.7.8

"},144:{"event":"REGISTER","tindex":"7954","tlabel":"254315075","PhoneNumber":"20709","DeviceId":"abcd1234abcd1234","CallId":"
 <21223-3848@5.6.7.8>21223-3848@5.6.7.8

"},145:{"event":"REGISTER","tindex":"64529","tlabel":"599481568","PhoneNumber":"20709","DeviceId":"abcd1234abcd1234","CallId":"

<21222-3848@5.6.7.8>21222-3848@5.6.7.8"},145:{"event":"REGISTER","tindex":"46605","tlabel":"112015324","PhoneNumber":"20710","DeviceId"

 T 1.2.3.4:48873 -> 5.6.7.8:3927 [AP]
   :"abcd1234abcd1234","CallId":"
<21224-3848@5.6.7.8>21224-3848@5.6.7.8
 "},

 *The above two chunks contain 4 proper netstrings where the second chunk
 contains part of the 4th netstring. In this case Evapi properly raised 4
 individual events.*

 1.2.3.4:48873 -> 5.6.7.8:3927 [AP]

145:{"event":"REGISTER","tindex":"55567","tlabel":"627458699","PhoneNumber":"20711","DeviceId":"abcd1234abcd1234","CallId":"
 <21225-3848@5.6.7.8>21225-3848@5.6.7.8

"},143:{"event":"REGISTER","tindex":"28682","tlabel":"9676691","PhoneNumber":"20712","DeviceId":"abcd1234abcd1234","CallId":"
 <21226-3848@5.6.7.8>21226-3848@5.6.7.8"},

 *This above chunk contains two complete netstrings but Kamailio never
 raised events for these two netstrings.*

 For the events that were not raised I see proper Kamailio Logs which is:
 evapi_recv_client(): {0} [1.2.3.4:48873] - received

[145:{"event":"REGISTER","tindex":"55567","tlabel":"627458699","PhoneNumber":"20711","DeviceId":"abcd1234abcd1234","CallId":"
 <21225-3848@5.6.7.8>21225-3848@5.6.7.8

"},143:{"event":"REGISTER","tindex":"28682","tlabel":"9676691","PhoneNumber":"20712","DeviceId":"abcd1234abcd1234","CallId":"
 <21226-3848@5.6.7.8>21226-3848@5.6.7.8"},]

 But I don't see the logs that I've written in the script after the event
 was raised, which means Kamailio did not invoke events for these two
 netstrings.

 So in my tests, out of 27232 messages sent, there were approximately 27
 messages for which the events were not raised by Evapi. The rate of
 messages started at 500cps and I stopped after I saw missed events at
 around 1200cps.

 Thanks, and do let me know for any further tests or information required
 about the same.

 - Jayesh

 On Fri, Sep 18, 2015 at 2:55 PM, Jayesh Nambiar < &lt;jayesh1017(a)gmail.com&gt;
 jayesh1017(a)gmail.com&gt; wrote:

  Will have this tested by tomorrow and will get
back to you. Thanks.

 - Jayesh

 On Fri, Sep 18, 2015 at 1:41 PM, Daniel-Constantin Mierla <
 <miconda@gmail.com>miconda@gmail.com> wrote:

  Hello,

 I just pushed a patch to master branch that should cope with partial
 data received on tcp connection. No time to test at all, therefore any
 feedback will be appreciated.

 Cheers,
 Daniel

 On 15/09/15 14:52, Daniel-Constantin Mierla wrote:

 Hello,

 I will look if there are options in libev to buffer data or try to
 implement a buffering mechanism locally for such cases.

 Cheers,
 Daniel

 On 14/09/15 23:00, Jayesh Nambiar wrote:

 Hello Daniel,
 After further testing with evapi module, I figured that when Netstrings
 are used, an event route is invoked individually for each message even if
 if multiple netstring messages are received in a single TCP packet. But
 this doesn't work effectively when a single proper message is split-up in
 two packets. For Example, if a message arrives as:
 12:Hello World!, 12:Hello World!, 12:Hello World! in a single packet,
 kamailio properly invokes the event route "evapi:message-received" thrice
 for every individual proper netstring message.
 But if the first packet contains:
 12:Hello World!, 12:Hello
 And Second Packet contains:
  World!, 12:Hello World!
 the event route is invoked only once !!

 The above pattern is very much possible while sending and receiving
 packets over TCP Socket. Our tests for receiving an approximately 150 byte
 message over evapi socket at the rate of roughly 1000cps causes a lot of
 real events to be missed because of the above problem. You can never be
 sure when TCP will split messages in different chunks.
 This definitely looks like a bug which makes it not very reliable at
 large scale deployments. Would really appreciate your inputs on this.
 Thanks;

 - Jayesh

 On Thu, Sep 10, 2015 at 4:01 PM, Jayesh Nambiar <
 <jayesh1017@gmail.com>jayesh1017@gmail.com> wrote:

> Hi Daniel,
> Thanks for the quick response. So if I do not use Netstrings, does
> Kamailio allow me to create a custom logic in the script. For eg. if I
> decide to use newline as a delimiter, can I keep buffering the message
> until I encounter the delimiter from the event route and then execute
> whatever I have to within the script??
>
> Thanks,
>
> - Jayesh
>
> On Thu, Sep 10, 2015 at 1:29 PM, Daniel-Constantin Mierla <
> <miconda@gmail.com>miconda@gmail.com> wrote:
>
>> Hello,
>>
>> tcb is stream protocol and several messages can be queued on the pipe
>> at the same time. That is the reason for netstring format, to be able to
>> easily detect the boundaries of each message. If netstring format is
>> enabled and kamailio receives several messages at once, it splits them and
>> for each is executing the event route.
>>
>> If netstring format is not used, the kamailio is executing the event
>> route with the entire content that was read at once from the tcp connection.
>>
>> Cheers,
>> Daniel
>>
>>
>> On 09/09/15 22:01, Jayesh Nambiar wrote:
>>
>> Hello,
>> I'm exploring the evapi module for my kamailio to interface with an
>> external node.js app for third party stuff like AAA, billing engine tasks,
>> notifications and so on. I followed and took some ideas from the rtjson and
>> evapi tutorial found here(
>> <http://kb.asipto.com/kamailio:k43-async-sip-routing-nodejs>
>> http://kb.asipto.com/kamailio:k43-async-sip-routing-nodejs) to build
>> the node.js app consuming events.
>> When I stress tested the scenario using SIPp and tried sending a lot
>> of events at 300-350cps from Kamailio, I noticed that at times the client
>> is receiving 2-3 events in a single message together although I do
>> event_sync_relay once per SIP message received and have netstrings enabled.
>> I believe this is a typical behavior of TCP and needs to be handled by the
>> client using some kind of Netstring handler. Please correct me if I'm wrong.
>> And hence I'd like to know what particularly needs to be taken care
>> of while writing a client that is listening for events on raw tcp socket
>> and how does kamailio handle this situation while receiving messages over
>> TCP socket?? Does kamailio recognize the end of netstring properly on
>> evapi:message-received and give exactly one message to take care of on
>> every "message-received" event or should that be handled in the script
>> somewhere !!
>> I also referred cgrates client over evapi example which is written in
>> GO, but I couldnt find them handling TCP streams clearly either.
>> I'd really appreciate some expert suggestion here to make an informed
>> decision on using the evapi module for a large scale solution.
>>
>> Thanks,
>>
>> - Jayesh
>>
>>
>>
>>
>> _______________________________________________
>> SIP Express Router (SER) and Kamailio (OpenSER) - sr-users mailing
listsr-users@lists.sip-router.orghttp://lists.sip-router.org/cgi-bin/mailman/listinfo/sr-users
>>
>>
>> --
>> Daniel-Constantin Mierlahttp://twitter.com/#!/miconda -
http://www.linkedin.com/in/miconda
>> Book: SIP Routing With Kamailio - http://www.asipto.com
>> Kamailio Advanced Training, Sep 28-30, 2015, in Berlin - http://asipto.com/u/kat
>>
>>
>> _______________________________________________
>> SIP Express Router (SER) and Kamailio (OpenSER) - sr-users mailing
>> list
>> <sr-users@lists.sip-router.org>sr-users@lists.sip-router.org
>> <http://lists.sip-router.org/cgi-bin/mailman/listinfo/sr-users>
>> http://lists.sip-router.org/cgi-bin/mailman/listinfo/sr-users
>>
>>
>

 --
 Daniel-Constantin Mierlahttp://twitter.com/#!/miconda -
http://www.linkedin.com/in/miconda
 Book: SIP Routing With Kamailio - http://www.asipto.com
 Kamailio Advanced Training, Sep 28-30, 2015, in Berlin - http://asipto.com/u/kat

 --
 Daniel-Constantin Mierlahttp://twitter.com/#!/miconda -
http://www.linkedin.com/in/miconda
 Book: SIP Routing With Kamailio - http://www.asipto.com
 Kamailio Advanced Training, Sep 28-30, 2015, in Berlin - http://asipto.com/u/kat

 --
 Daniel-Constantin Mierlahttp://twitter.com/#!/miconda -
http://www.linkedin.com/in/miconda
 Book: SIP Routing With Kamailio - http://www.asipto.com
 Kamailio Advanced Training, Sep 28-30, 2015, in Berlin - http://asipto.com/u/kat

  --
 Daniel-Constantin Mierlahttp://twitter.com/#!/miconda -
http://www.linkedin.com/in/miconda
 Book: SIP Routing With Kamailio - http://www.asipto.com
 Kamailio Advanced Training, Sep 28-30, 2015, in Berlin - http://asipto.com/u/kat

2024

2023

2022

2021

2020

2019

2018

2017

2016

2015

2014

2013

2012

2011

2010

2009

2008

2007

2006

2005

2004

2003

2002

Re: [SR-Users] evapi tcp parsing??