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