21 Sep
2015
21 Sep
'15
2:07 p.m.
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:
--
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
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:
--
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
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:
--
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
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