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@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"},] (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"},] (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@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"}] (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"},] (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"},] (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@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"}] (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"},] (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"},] (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@198.24.63.39"},] (152) (0)
Thanks,
- Jayesh
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"},
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:
146:{"event":"REGISTER","tindex":"16916","tlabel":"1753048277","PhoneNumber":"20708","DeviceId":"abcd1234abcd1234","CallId":"
21220-3848@5.6.7.8"},144:{"event":"REGISTER","tindex":"7954","tlabel":"254315075","PhoneNumber":"20709","DeviceId":"abcd1234abcd1234","CallId":"
21223-3848@5.6.7.8"},145:{"event":"REGISTER","tindex":"64529","tlabel":"599481568","PhoneNumber":"20709","DeviceId":"abcd1234abcd1234","CallId":"
21222-3848@5.6.7.8"},145:{"event":"REGISTER","tindex":"46605","tlabel":"112015324","PhoneNumber":"20710","DeviceId"
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.
145:{"event":"REGISTER","tindex":"55567","tlabel":"627458699","PhoneNumber":"20711","DeviceId":"abcd1234abcd1234","CallId":"
21225-3848@5.6.7.8"},143:{"event":"REGISTER","tindex":"28682","tlabel":"9676691","PhoneNumber":"20712","DeviceId":"abcd1234abcd1234","CallId":"
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] - received
[145:{"event":"REGISTER","tindex":"55567","tlabel":"627458699","PhoneNumber":"20711","DeviceId":"abcd1234abcd1234","CallId":"
21225-3848@5.6.7.8"},143:{"event":"REGISTER","tindex":"28682","tlabel":"9676691","PhoneNumber":"20712","DeviceId":"abcd1234abcd1234","CallId":"
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
--
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