[SR-Users] evapi tcp parsing??
Jayesh Nambiar
jayesh1017 at gmail.com
Mon Sep 21 09:04:42 CEST 2015
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>},
>
> 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>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>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>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>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>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>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>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>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>
>>> 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>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>
>>>>> 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>sr-users at 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
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.sip-router.org/pipermail/sr-users/attachments/20150921/9987740b/attachment.html>
More information about the sr-users
mailing list