[SR-Users] evapi tcp parsing??
Daniel-Constantin Mierla
miconda at gmail.com
Tue Sep 22 13:33:38 CEST 2015
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 <mailto: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 <http://s.int>});
>> $var(t_label) = $(var(tlabel){s.int <http://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
>> <mailto: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
>> <mailto: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
>> <mailto:23021-12910 at 198.24.63.39>"},] (151)
>> NOTICE: evapi [evapi_dispatch.c:290]: evapi_recv_client(): {0}
>> [198.24.63.45:48881 <http://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
>> <mailto: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
>> <mailto: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
>> <mailto: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
>> <mailto:27182-12910 at 198.24.63.39>"},] (152)
>> NOTICE: evapi [evapi_dispatch.c:290]: evapi_recv_client(): {0}
>> [198.24.63.45:48881 <http://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
>> <mailto: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
>> <mailto: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
>> <mailto: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
>> <mailto:49957-13056 at 198.24.63.39>"},] (152)
>> NOTICE: evapi [evapi_dispatch.c:290]: evapi_recv_client(): {0}
>> [198.24.63.45:48881 <http://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
>> <mailto: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 <mailto: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"
>> <mailto: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 <http://1.2.3.4:48873> -> 5.6.7.8:3927
>>> <http://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
>>> <mailto: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
>>> <mailto: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
>>> <mailto:21222-3848 at 5.6.7.8>"},145:{"event":"REGISTER","tindex":"46605","tlabel":"112015324","PhoneNumber":"20710","DeviceId"
>>>
>>>
>>>
>>>
>>>
>>> T 1.2.3.4:48873 <http://1.2.3.4:48873> -> 5.6.7.8:3927
>>> <http://5.6.7.8:3927> [AP]
>>> :"abcd1234abcd1234","CallId":"21224-3848 at 5.6.7.8
>>> <mailto: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 <http://1.2.3.4:48873> -> 5.6.7.8:3927
>>> <http://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
>>> <mailto: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
>>> <mailto: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
>>> <http://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
>>> <mailto: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
>>> <mailto: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 <mailto: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 <mailto: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
>>>>> <mailto: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
>>>>> <mailto: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 list
>>>>>> sr-users at lists.sip-router.org
>>>>>> <mailto:sr-users at lists.sip-router.org>
>>>>>> http://lists.sip-router.org/cgi-bin/mailman/listinfo/sr-users
>>>>>
>>>>> --
>>>>> Daniel-Constantin Mierla
>>>>> http://twitter.com/#!/miconda
>>>>> <http://twitter.com/#%21/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
>>>>> <mailto:sr-users at lists.sip-router.org>
>>>>> http://lists.sip-router.org/cgi-bin/mailman/listinfo/sr-users
>>>>>
>>>>>
>>>>>
>>>>
>>>> --
>>>> Daniel-Constantin Mierla
>>>> http://twitter.com/#!/miconda
>>>> <http://twitter.com/#%21/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 Mierla
>>> http://twitter.com/#!/miconda
>>> <http://twitter.com/#%21/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 Mierla
>> http://twitter.com/#!/miconda <http://twitter.com/#%21/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 Mierla
> http://twitter.com/#!/miconda <http://twitter.com/#%21/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 Mierla
http://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/31a5b561/attachment.html>
More information about the sr-users
mailing list