[SR-Users] evapi tcp parsing??
Jayesh Nambiar
jayesh1017 at gmail.com
Tue Sep 22 16:53:45 CEST 2015
Hi,
Here's the NGREP trace where
{"event":"REGISTER","tindex":"3639","tlabel":"1889788252"
... is present on the first line itself.
198.24.63.45:48886 -> 198.24.63.39:3927 [AP]
146:{"event":"REGISTER","tindex":"3639","tlabel":"1889788252","PhoneNumber":"42008","DeviceId":"abcd1234abcd1234","CallId":"
11542-19872 at 198.24.63.39
"},147:{"event":"REGISTER","tindex":"12600","tlabel":"1916422130","PhoneNumber":"42009","DeviceId":"abcd1234abcd1234","CallId":"
11543-19872 at 198.24.63.39
"},147:{"event":"REGISTER","tindex":"51251","tlabel":"1549871937","PhoneNumber":"42010","DeviceId":"abcd1234abcd
1234","CallId":"11544-19872 at 198.24.63.39
"},147:{"event":"REGISTER","tindex":"60213","tlabel":"2100336684","PhoneNumber":"42011","DeviceId":"abcd1234abcd1234","CallId":"
11545-19872 at 198.24.63.39"},146:{"event
":"REGISTER","tindex":"33328","tlabel":"622251552","PhoneNumber":"42012","DeviceId":"abcd1234abcd1234","CallId":"
11546-19872 at 198.24.63.39
"},147:{"event":"REGISTER","tindex":"42289","tlabel":"1360864805","PhoneNumber":"42013","DeviceId":"abcd1234abcd1234","CallId":"
11547-19872 at 198.24.63.39
"},146:{"event":"REGISTER","tindex":"48204","tlabel":"315887672","PhoneNumber":"42014","DeviceId":"abcd1234abcd1234","CallId":"
11548-19872 at 198.24.63.39
"},145:{"event":"REGISTER","tindex":"36682","tlabel":"18660440","PhoneNumber":"42015","DeviceId":"abcd1234abcd1234","CallId":"
11549-19872 at 198.24.63.39"},
And yes, this packet is right after the second packet in the pastebin trace.
Thanks,
- Jayesh
On Tue, Sep 22, 2015 at 5:03 PM Daniel-Constantin Mierla <miconda at gmail.com>
wrote:
> Hello,
>
> I haven't seen in the ngrep when the data containing next line is received:
>
> {"event":"REGISTER","tindex":"3639","tlabel":"1889788252" ...
>
> Do you still have it? Is it after:
>
> {"event":"REGISTER","tindex":"12603","tlabel":"626010915", ...
>
> Cheers,
> Daniel
>
>
> On 22/09/15 09:09, Jayesh Nambiar wrote:
>
> 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 <
> miconda at gmail.com> 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 198.24.63.39"},] (152) (0)
>>
>> Thanks,
>>
>> - Jayesh
>> On Sat, Sep 19, 2015 at 3:55 AM Daniel-Constantin Mierla <
>> miconda at gmail.com> 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 at 5.6.7.8" <21225-3848 at 5.6.7.8> <21225-3848 at 5.6.7.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 at 5.6.7.8
>>> "},144:{"event":"REGISTER","tindex":"7954","tlabel":"254315075","PhoneNumber":"20709","DeviceId":"abcd1234abcd1234","CallId":"
>>> 21223-3848 at 5.6.7.8
>>> "},145:{"event":"REGISTER","tindex":"64529","tlabel":"599481568","PhoneNumber":"20709","DeviceId":"abcd1234abcd1234","CallId":"
>>> 21222-3848 at 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 at 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 at 5.6.7.8
>>> "},143:{"event":"REGISTER","tindex":"28682","tlabel":"9676691","PhoneNumber":"20712","DeviceId":"abcd1234abcd1234","CallId":"
>>> 21226-3848 at 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 at 5.6.7.8
>>> "},143:{"event":"REGISTER","tindex":"28682","tlabel":"9676691","PhoneNumber":"20712","DeviceId":"abcd1234abcd1234","CallId":"
>>> 21226-3848 at 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 <jayesh1017 at gmail.com>
>>> 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 at 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 at 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 at 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) 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 at 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 at lists.sip-router.org
>>>>>>> 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
>>
>>
> --
> 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
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.sip-router.org/pipermail/sr-users/attachments/20150922/e3d8678b/attachment.html>
More information about the sr-users
mailing list