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