[SR-Users] evapi tcp parsing??
Jayesh Nambiar
jayesh1017 at gmail.com
Tue Sep 29 14:15:15 CEST 2015
Hi Daniel,
Taking a second look at the NGREP Trace I think I can see what is going
wrong. The message in the third packet was discarded by Evapi module. If
you look at the first two packets carefully, the first packet ends at Dev
and the second packet is the continuation of first packet which starts with
"iceId". The first two packets are processed perfectly fine.
Now the third packet is a new message, but Kamailio is trying to continue
the third packet again with the first packet. So even when the third packet
starts with '146:' Kamailio considers it to be starting with 'Dev146'. This
causes the evapi to discard this message since it does not remain a valid
netstring then. Here the three packets that I'm talking about:
T 198.24.63.45:48905 -> 198.24.63.39:3927 [A]
146:{"event":"REGISTER","tindex":"43213","tlabel":"220429340","PhoneNumber":"11151","DeviceId":"abcd1234abcd1234","CallId":"10932-15480 at 198.24.63.39"},146:{"event":"REGISTER","tindex":"52174","tlabel":"708781916","PhoneNumber":"11150","DeviceId":"abcd1234abcd1234","CallId":"10933-15480 at 198.24.63.39"},147:{"event":"REGISTER","tindex":"34251","tlabel":"1354642017","PhoneNumber":"11153","DeviceId":"abcd1234abcd1234","CallId":"10935-15480 at 198.24.63.39"},146:{"event":"REGISTER","tindex":"7366","tlabel":"1368396808","PhoneNumber":"11154","DeviceId":"abcd1234abcd1234","CallId":"10936-15480 at 198.24.63.39"},146:{"event":"REGISTER","tindex":"25289","tlabel":"119788881","PhoneNumber":"11152","DeviceId":"abcd1234abcd1234","CallId":"10934-15480 at 198.24.63.39"},146:{"event":"REGISTER","tindex":"16327","tlabel":"971937029","PhoneNumber":"11155","DeviceId":"abcd1234abcd1234","CallId":"10937-15480 at 198.24.63.39"},146:{"event":"REGISTER","tindex":"22242","tlabel":"609737074","PhoneNumber":"11156","DeviceId":"abcd1234abcd1234","CallId":"10938-15480 at 198.24.63.39"},146:{"event":"REGISTER","tindex":"10720","tlabel":"930036340","PhoneNumber":"11157","DeviceId":"abcd1234abcd1234","CallId":"10939-15480 at 198.24.63.39"},146:{"event":"REGISTER","tindex":"61133","tlabel":"450961398","PhoneNumber":"11158","DeviceId":"abcd1234abcd1234","CallId":"10940-15480 at 198.24.63.39"},146:{"event":"REGISTER","tindex":"43210","tlabel":"639090568","PhoneNumber":"11160","Dev
T 198.24.63.45:48905 -> 198.24.63.39:3927 [AP]
iceId":"abcd1234abcd1234","CallId":"10942-15480 at 198.24.63.39"},146:{"event":"REGISTER","tindex":"4559","tlabel":"1701553747","PhoneNumber":"11159","DeviceId":"abcd1234abcd1234","CallId":"10941-15480 at 198.24.63.39"},
T 198.24.63.45:48905 -> 198.24.63.39:3927 [AP]
146:{"event":"REGISTER","tindex":"52171","tlabel":"748030241","PhoneNumber":"11161","DeviceId":"abcd1234abcd1234","CallId":"10943-15480 at 198.24.63.39"},
On Tue, Sep 29, 2015 at 4:43 PM Jayesh Nambiar <jayesh1017 at gmail.com> wrote:
> Hi Daniel:
> I did a new test where I stopped as soon as I saw one message that got
> discarded. Basically the following message got discarded:
>
> {"event":"REGISTER","tindex":"52171","tlabel":"748030241","PhoneNumber":"11161","DeviceId":"abcd1234abcd1234","CallId":"
> 10943-15480 at 198.24.63.39"}
> The CallId parameter in the above json is auto incremented, so I tried
> gathering logs for messages with following CallIds:
> "CallId":"10940-15480 at 198.24.63.39"
> "CallId":"10941-15480 at 198.24.63.39"
> "CallId":"10942-15480 at 198.24.63.39"
> "CallId":"10943-15480 at 198.24.63.39"
> "CallId":"10944-15480 at 198.24.63.39"
> "CallId":"10945-15480 at 198.24.63.39"
>
> And the message with CallID "CallId":"10943-15480 at 198.24.63.39" got
> discarded.
>
> Here's the bunch of kamailio logs printed by the evapi module:
> *Logs for processed messages just before the discarded message:*
> DEBUG: evapi [evapi_dispatch.c:492]: evapi_recv_notify(): received
> [0x7f43da494ad0]
> [146:{"event":"REGISTER","tindex":"61133","tlabel":"450961398","PhoneNumber":"11158","DeviceId":"abcd1234abcd1234","CallId":"
> 10940-15480 at 198.24.63.39"},] (151)
>
> NOTICE: evapi_recv_client(): {0} [198.24.63.45:48905] - received
> [147:{"event":"REGISTER","tindex":"25291","tlabel":"2047024302","PhoneNumber":"11132","DeviceId":"abcd1234abcd1234","CallId":"
> 10914-15480 at 198.24.63.39
> "},146:{"event":"REGISTER","tindex":"61136","tlabel":"839735223","PhoneNumber":"11148","DeviceId":"abcd1234abcd1234","CallId":"
> 10930-15480 at 198.24.63.39
> "},143:{"event":"REGISTER","tindex":"4562","tlabel":"6586867","PhoneNumber":"11149","DeviceId":"abcd1234abcd1234","CallId":"
> 10931-15480 at 198.24.63.39
> "},146:{"event":"REGISTER","tindex":"43213","tlabel":"220429340","PhoneNumber":"11151","DeviceId":"abcd1234abcd1234","CallId":"
> 10932-15480 at 198.24.63.39
> "},146:{"event":"REGISTER","tindex":"52174","tlabel":"708781916","PhoneNumber":"11150","DeviceId":"abcd1234abcd1234","CallId":"
> 10933-15480 at 198.24.63.39
> "},147:{"event":"REGISTER","tindex":"34251","tlabel":"1354642017","PhoneNumber":"11153","DeviceId":"abcd1234abcd1234","CallId":"
> 10935-15480 at 198.24.63.39
> "},146:{"event":"REGISTER","tindex":"7366","tlabel":"1368396808","PhoneNumber":"11154","DeviceId":"abcd1234abcd1234","CallId":"
> 10936-15480 at 198.24.63.39
> "},146:{"event":"REGISTER","tindex":"25289","tlabel":"119788881","PhoneNumber":"11152","DeviceId":"abcd1234abcd1234","CallId":"
> 10934-15480 at 198.24.63.39
> "},146:{"event":"REGISTER","tindex":"16327","tlabel":"971937029","PhoneNumber":"11155","DeviceId":"abcd1234abcd1234","CallId":"
> 10937-15480 at 198.24.63.39
> "},146:{"event":"REGISTER","tindex":"22242","tlabel":"609737074","PhoneNumber":"11156","DeviceId":"abcd1234abcd1234","CallId":"
> 10938-15480 at 198.24.63.39
> "},146:{"event":"REGISTER","tindex":"10720","tlabel":"930036340","PhoneNumber":"11157","DeviceId":"abcd1234abcd1234","CallId":"
> 10939-15480 at 198.24.63.39
> "},146:{"event":"REGISTER","tindex":"61133","tlabel":"450961398","PhoneNumber":"11158","DeviceId":"abcd1234abcd1234","CallId":"
> 10940-15480 at 198.24.63.39"},146:{"event":"REGISTER","tindex":"43210","tlabel":"639090568","PhoneNumber":"11160","Dev]
> (1899) (0)
>
>
> evapi_recv_client(): executing event route for frame:
> [{"event":"REGISTER","tindex":"61133","tlabel":"450961398","PhoneNumber":"11158","DeviceId":"abcd1234abcd1234","CallId":"
> 10940-15480 at 198.24.63.39"}] (146)
>
> Sep 29 05:35:14 v39 /usr/local/kamailio-dev/sbin/kamailio[15387]: DEBUG:
> evapi [evapi_dispatch.c:492]: evapi_recv_notify(): received
> [0x7f43da4b67e0]
> [146:{"event":"REGISTER","tindex":"4559","tlabel":"1701553747","PhoneNumber":"11159","DeviceId":"abcd1234abcd1234","CallId":"
> 10941-15480 at 198.24.63.39"},] (151)
>
> NOTICE: evapi [evapi_dispatch.c:290]: evapi_recv_client(): {0} [
> 198.24.63.45:48905] - received [iceId":"abcd1234abcd1234","CallId":"
> 10942-15480 at 198.24.63.39
> "},146:{"event":"REGISTER","tindex":"4559","tlabel":"1701553747","PhoneNumber":"11159","DeviceId":"abcd1234abcd1234","CallId":"
> 10941-15480 at 198.24.63.39"},] (214) (88)
>
> DEBUG: evapi [evapi_dispatch.c:370]: evapi_recv_client(): executing event
> route for frame:
> [{"event":"REGISTER","tindex":"4559","tlabel":"1701553747","PhoneNumber":"11159","DeviceId":"abcd1234abcd1234","CallId":"
> 10941-15480 at 198.24.63.39"}] (146)
>
> DEBUG: evapi [evapi_dispatch.c:492]: evapi_recv_notify(): received
> [0x7f43d93c2a70]
> [146:{"event":"REGISTER","tindex":"43210","tlabel":"639090568","PhoneNumber":"11160","DeviceId":"abcd1234abcd1234","CallId":"
> 10942-15480 at 198.24.63.39"},] (151)
>
> DEBUG: evapi [evapi_dispatch.c:370]: evapi_recv_client(): executing event
> route for frame:
> [{"event":"REGISTER","tindex":"43210","tlabel":"639090568","PhoneNumber":"11160","DeviceId":"abcd1234abcd1234","CallId":"
> 10942-15480 at 198.24.63.39"}] (146)
>
> DEBUG: evapi [evapi_dispatch.c:353]: evapi_recv_client(): residual data
> [146:{"event":"REGISTER","tindex":"43210","tlabel":"639090568","PhoneNumber":"11160","Dev]
> (88)
>
> DEBUG: evapi [evapi_dispatch.c:361]: evapi_recv_client(): frame size
> mismatch the ending char ("):
> [{"event":"REGISTER","tindex":"43210","tlabel":"639090568","PhoneNumber":"11160","Dev146:{"event":"REGISTER","tindex":"52171","tlabel":"748030241",]
> (146)
>
> *Logs for discarded message:*
> DEBUG: evapi [evapi_dispatch.c:492]: evapi_recv_notify(): received
> [0x7f43da3e69a0]
> [146:{"event":"REGISTER","tindex":"52171","tlabel":"748030241","PhoneNumber":"11161","DeviceId":"abcd1234abcd1234","CallId":"
> 10943-15480 at 198.24.63.39"},] (151)
>
> NOTICE: evapi [evapi_dispatch.c:290]: evapi_recv_client(): {0} [
> 198.24.63.45:48905] - received
> [146:{"event":"REGISTER","tindex":"52171","tlabel":"748030241","PhoneNumber":"11161","DeviceId":"abcd1234abcd1234","CallId":"
> 10943-15480 at 198.24.63.39"},] (151) (88)
>
> *Logs for messages after the discarded message:*
> DEBUG: evapi [evapi_dispatch.c:492]: evapi_recv_notify(): received
> [0x7f43da3e6aa0]
> [146:{"event":"REGISTER","tindex":"25286","tlabel":"809034258","PhoneNumber":"11163","DeviceId":"abcd1234abcd1234","CallId":"
> 10944-15480 at 198.24.63.39"},] (151)
>
> NOTICE: evapi [evapi_dispatch.c:290]: evapi_recv_client(): {0} [
> 198.24.63.45:48905] - received
> [146:{"event":"REGISTER","tindex":"25286","tlabel":"809034258","PhoneNumber":"11163","DeviceId":"abcd1234abcd1234","CallId":"
> 10944-15480 at 198.24.63.39"},] (151) (0)
>
> DEBUG: evapi [evapi_dispatch.c:370]: evapi_recv_client(): executing event
> route for frame:
> [{"event":"REGISTER","tindex":"25286","tlabel":"809034258","PhoneNumber":"11163","DeviceId":"abcd1234abcd1234","CallId":"
> 10944-15480 at 198.24.63.39"}] (146)
>
> DEBUG: evapi [evapi_dispatch.c:492]: evapi_recv_notify(): received
> [0x7f43d9598778]
> [146:{"event":"REGISTER","tindex":"34248","tlabel":"187029249","PhoneNumber":"11162","DeviceId":"abcd1234abcd1234","CallId":"
> 10945-15480 at 198.24.63.39"},] (151)
>
> NOTICE: evapi [evapi_dispatch.c:290]: evapi_recv_client(): {0} [
> 198.24.63.45:48905] - received
> [146:{"event":"REGISTER","tindex":"34248","tlabel":"187029249","PhoneNumber":"11162","DeviceId":"abcd1234abcd1234","CallId":"
> 10945-15480 at 198.24.63.39"},] (151) (0)
>
> DEBUG: evapi [evapi_dispatch.c:370]: evapi_recv_client(): executing event
> route for frame:
> [{"event":"REGISTER","tindex":"34248","tlabel":"187029249","PhoneNumber":"11162","DeviceId":"abcd1234abcd1234","CallId":"
> 10945-15480 at 198.24.63.39"}] (146)
>
> DEBUG: evapi [evapi_dispatch.c:492]: evapi_recv_notify(): received
> [0x7f43d9598878]
> [145:{"event":"REGISTER","tindex":"7363","tlabel":"949153805","PhoneNumber":"11164","DeviceId":"abcd1234abcd1234","CallId":"
> 10946-15480 at 198.24.63.39"},] (150)
>
> NOTICE: evapi [evapi_dispatch.c:290]: evapi_recv_client(): {0} [
> 198.24.63.45:48905] - received
> [145:{"event":"REGISTER","tindex":"7363","tlabel":"949153805","PhoneNumber":"11164","DeviceId":"abcd1234abcd1234","CallId":"
> 10946-15480 at 198.24.63.39"},] (150) (0)
>
> DEBUG: evapi [evapi_dispatch.c:370]: evapi_recv_client(): executing event
> route for frame:
> [{"event":"REGISTER","tindex":"7363","tlabel":"949153805","PhoneNumber":"11164","DeviceId":"abcd1234abcd1234","CallId":"
> 10946-15480 at 198.24.63.39"}] (145)
>
> Just in case if you need to see the NGREP trace for the above messages, it
> is here:
> http://pastebin.com/4zTKmBJX
>
> Thanks,
>
> - Jayesh
>
>
> On Tue, Sep 29, 2015 at 12:16 PM Daniel-Constantin Mierla <
> miconda at gmail.com> wrote:
>
>> Hello,
>>
>> can you send here the log messages printed by evapi that contain "] -
>> received [" which have:
>>
>> - the previous bunch of json documents that were processed ok (just
>> before the one that was discarded)
>> - the bunch of json documents that were discarded
>> - the next bunch of json documents that were processed ok
>>
>> The logs were sent on could of emails and pastebin, so it is hard to
>> track them -- if you have the logs, just locate the log messages with the
>> discarded json and send it here along with the previous and next logs.
>>
>> Cheers,
>> Daniel
>>
>>
>> On 28/09/15 17:04, Jayesh Nambiar wrote:
>>
>> Thank you daniel.
>> Yes, they all get printed by the evapi module even when they get
>> discarded. If you once again check the paste-bin, the logs pasted as
>> Kamailio Logs are all discarded packets but show up as received by evapi
>> module.
>> I believe they got discarded because a packet that came before them was
>> partial and evapi discarded the remaining part of the message in the new
>> packet and encountered error.
>> - Jayesh
>>
>> On Mon, Sep 28, 2015 at 11:13 AM Daniel-Constantin Mierla <
>> miconda at gmail.com> wrote:
>>
>>> Hello,
>>>
>>> I will look over it during next days.
>>>
>>> One more thing, are the packages sent by you printed by evapi module,
>>> even not they are not processed (but discarded)?
>>>
>>> Cheers,
>>> Daniel
>>>
>>>
>> --
>> Daniel-Constantin Mierlahttp://twitter.com/#!/miconda - http://www.linkedin.com/in/miconda
>> Book: SIP Routing With Kamailio - http://www.asipto.com
>>
>>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.sip-router.org/pipermail/sr-users/attachments/20150929/b203316f/attachment.html>
More information about the sr-users
mailing list