[SR-Users] evapi tcp parsing??

Daniel-Constantin Mierla miconda at gmail.com
Tue Oct 13 14:09:39 CEST 2015


Thanks for testing and feedback -- good to know it was fixed, not to
keep it open in my side anymore.
 
Cheers,
Daniel

On 13/10/15 12:37, Jayesh Nambiar wrote:
> Yes that problem is definitely solved. Sorry to not post the response.
> I'm having some other issues in scaling and still trying to figure
> where the problem must be, but I can scale upto 2000 cps easily now.
>
> Thanks for the efforts and the credits :)
>
> - Jayesh
>
> On Sun, Oct 11, 2015 at 10:59 PM Daniel-Constantin Mierla
> <miconda at gmail.com <mailto:miconda at gmail.com>> wrote:
>
>     Hello,
>
>     wondering if you had the time to test and see if the issue has
>     been fixed...
>
>     Cheers,
>     Daniel
>
>
>     On 30/09/15 08:31, Daniel-Constantin Mierla wrote:
>>     Hello,
>>
>>     thanks for troubleshooting further and pointing to the issue. I
>>     pushed a patch last night, hopefully fixes it. Try with latest
>>     master branch and let me know the results.
>>
>>     Cheers,
>>     Daniel
>>
>>     On 29/09/15 14:15, Jayesh Nambiar wrote:
>>>     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 <http://198.24.63.45:48905> -> 198.24.63.39:3927 <http://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 <mailto: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 <mailto: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 <mailto: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 <mailto:10936-15480 at 198.24.63.39>"},146:{"event":"REGISTER","tindex":"25289","tlabel":"119788881","PhoneNumber":"11152","DeviceId":"abcd1234abcd1234","C
>>>
>>>     allId":"10934-15480 at 198.24.63.39 <mailto: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 <mailto: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 <mailto: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 <mailto: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 <mailto:10940-15480 at 198.24.63.39>"},146:{"event":"R
>>>
>>>     EGISTER","tindex":"43210","tlabel":"639090568","PhoneNumber":"11160","Dev                                                                                                         
>>>
>>>     T 198.24.63.45:48905 <http://198.24.63.45:48905> -> 198.24.63.39:3927 <http://198.24.63.39:3927> [AP]
>>>       iceId":"abcd1234abcd1234","CallId":"10942-15480 at 198.24.63.39 <mailto: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 <mailto:10941-15480 at 198.24.63.39>"},
>>>                                                                                                                                                                                                    
>>>     T 198.24.63.45:48905 <http://198.24.63.45:48905> -> 198.24.63.39:3927 <http://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 <mailto:10943-15480 at 198.24.63.39>"},
>>>
>>>     On Tue, Sep 29, 2015 at 4:43 PM Jayesh Nambiar
>>>     <jayesh1017 at gmail.com <mailto: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
>>>         <mailto: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
>>>         <mailto:10940-15480 at 198.24.63.39>"
>>>         "CallId":"10941-15480 at 198.24.63.39
>>>         <mailto:10941-15480 at 198.24.63.39>"
>>>         "CallId":"10942-15480 at 198.24.63.39
>>>         <mailto:10942-15480 at 198.24.63.39>"
>>>         "CallId":"10943-15480 at 198.24.63.39
>>>         <mailto:10943-15480 at 198.24.63.39>"
>>>         "CallId":"10944-15480 at 198.24.63.39
>>>         <mailto:10944-15480 at 198.24.63.39>"
>>>         "CallId":"10945-15480 at 198.24.63.39
>>>         <mailto:10945-15480 at 198.24.63.39>"
>>>
>>>         And the message with
>>>         CallID "CallId":"10943-15480 at 198.24.63.39
>>>         <http://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
>>>         <mailto:10940-15480 at 198.24.63.39>"},] (151)
>>>
>>>         NOTICE: evapi_recv_client(): {0} [198.24.63.45:48905
>>>         <http://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
>>>         <mailto: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
>>>         <mailto: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
>>>         <mailto: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
>>>         <mailto: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
>>>         <mailto: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
>>>         <mailto: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
>>>         <mailto: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
>>>         <mailto: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
>>>         <mailto: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
>>>         <mailto: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
>>>         <mailto: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
>>>         <mailto: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
>>>         <mailto: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
>>>         <mailto:10941-15480 at 198.24.63.39>"},] (151)
>>>
>>>         NOTICE: evapi [evapi_dispatch.c:290]: evapi_recv_client():
>>>         {0} [198.24.63.45:48905 <http://198.24.63.45:48905>] -
>>>         received
>>>         [iceId":"abcd1234abcd1234","CallId":"10942-15480 at 198.24.63.39 <mailto: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
>>>         <mailto: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
>>>         <mailto: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
>>>         <mailto: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
>>>         <mailto: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
>>>         <mailto:10943-15480 at 198.24.63.39>"},] (151)
>>>
>>>         NOTICE: evapi [evapi_dispatch.c:290]: evapi_recv_client():
>>>         {0} [198.24.63.45:48905 <http://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
>>>         <mailto: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
>>>         <mailto:10944-15480 at 198.24.63.39>"},] (151)
>>>
>>>         NOTICE: evapi [evapi_dispatch.c:290]: evapi_recv_client():
>>>         {0} [198.24.63.45:48905 <http://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
>>>         <mailto: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
>>>         <mailto: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
>>>         <mailto:10945-15480 at 198.24.63.39>"},] (151)
>>>
>>>         NOTICE: evapi [evapi_dispatch.c:290]: evapi_recv_client():
>>>         {0} [198.24.63.45:48905 <http://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
>>>         <mailto: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
>>>         <mailto: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
>>>         <mailto:10946-15480 at 198.24.63.39>"},] (150)
>>>
>>>         NOTICE: evapi [evapi_dispatch.c:290]: evapi_recv_client():
>>>         {0} [198.24.63.45:48905 <http://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
>>>         <mailto: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
>>>         <mailto: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 <mailto: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 <mailto: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 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
>>>
>>
>>     -- 
>>     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
>
>     -- 
>     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
>

-- 
Daniel-Constantin Mierla
http://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/20151013/c0af1081/attachment.html>


More information about the sr-users mailing list