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:
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(a)gmail.com <mailto:miconda@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@198.24.63.39
<mailto: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
<mailto: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
<mailto:23021-12910@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@198.24.63.39
<mailto: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
<mailto: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
<mailto: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
<mailto:27182-12910@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@198.24.63.39
<mailto: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
<mailto: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
<mailto: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
<mailto:49957-13056@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@198.24.63.39
<mailto: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
<mailto:miconda@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@5.6.7.8"
<mailto:21225-3848@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@5.6.7.8
<mailto:21220-3848@5.6.7.8>"},144:{"event":"REGISTER","tindex":"7954","tlabel":"254315075","PhoneNumber":"20709","DeviceId":"abcd1234abcd1234","CallId":"21223-3848@5.6.7.8
<mailto:21223-3848@5.6.7.8>"},145:{"event":"REGISTER","tindex":"64529","tlabel":"599481568","PhoneNumber":"20709","DeviceId":"abcd1234abcd1234","CallId":"21222-3848@5.6.7.8
<mailto:21222-3848@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@5.6.7.8
<mailto: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 <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@5.6.7.8
<mailto:21225-3848@5.6.7.8>"},143:{"event":"REGISTER","tindex":"28682","tlabel":"9676691","PhoneNumber":"20712","DeviceId":"abcd1234abcd1234","CallId":"21226-3848@5.6.7.8
<mailto: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
<http://1.2.3.4:48873>] - received
[145:{"event":"REGISTER","tindex":"55567","tlabel":"627458699","PhoneNumber":"20711","DeviceId":"abcd1234abcd1234","CallId":"21225-3848@5.6.7.8
<mailto:21225-3848@5.6.7.8>"},143:{"event":"REGISTER","tindex":"28682","tlabel":"9676691","PhoneNumber":"20712","DeviceId":"abcd1234abcd1234","CallId":"21226-3848@5.6.7.8
<mailto: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
<jayesh1017(a)gmail.com
<mailto:jayesh1017@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(a)gmail.com
<mailto: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(a)gmail.com
>> <mailto: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(a)gmail.com
>> <mailto: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)
>>> 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(a)lists.sip-router.org
<mailto:sr-users@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(a)lists.sip-router.org
>> <mailto:sr-users@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