Also forgot to mention, this starts happening at around 1200cps. And using SIPp I accelerate from 500cps to 1200cps very quick. So it might be related to concurrency is what I'm assuming. Thanks.
- Jayesh On Tue, Sep 22, 2015 at 12:40 PM Jayesh Nambiar <jayesh1...@gmail.com> wrote: > Hi, > Took time to get back with the test results as I was trying to analyze too > much myself before getting back on the list. Also I was stuck with weird > error of module version mismatch, but I figured and solved that issue. > So I do see the logs "frame size mismatch" when I miss the events. Since > the logs are too huge, I am sending it in pastebin. Here it is: > http://pastebin.com/MzTpYsrk > > In Kamailio Logs, I see: > DEBUG: evapi [evapi_dispatch.c:361]: evapi_recv_client(): frame size > mismatch the ending char > (h):[{"event":"REGISTER","tindex":"12603","tlabel":"626010915 > ","PhoneNumber":"42000","D146:"event":"REGISTER","tindex":"3639","tlabel":" > 1889788252","P] (146) > > Whereas the messages in ngrep looks good where the messages are split in > two TCP packets. The first packet ends at D and the second packet is the > proper continuation which send the rest. But it feels Kamailio skipped the > beginning of the message and started parsing at colon again and it thinks > the netstring started with D146 which is incorrect. Hence, it never emitted > any event for the messages in the first chunk. > > Hoping this to be helpful !! Thanks. > > - Jayesh > > > On Mon, Sep 21, 2015 at 4:37 PM Daniel-Constantin Mierla < > mico...@gmail.com> wrote: > >> Hello, >> >> I pushed another commit to add more debug messages to see if the event >> route is supposed to be executed or not. Can you run the tests again and >> give again the log messages for missing event route executions? >> >> Cheers, >> Daniel >> >> >> On 21/09/15 09:04, Jayesh Nambiar wrote: >> >> 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>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>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>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>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>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>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>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>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>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>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>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>49957-13056@198.24.63.39"},] (152) (0) >> >> Thanks, >> >> - Jayesh >> On Sat, Sep 19, 2015 at 3:55 AM Daniel-Constantin Mierla < >> mico...@gmail.com> wrote: >> >>> 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>"21225-3848@5.6.7.8" <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: >>> >>> T 1.2.3.4:48873 -> 5.6.7.8:3927 [AP] >>> >>> 146:{"event":"REGISTER","tindex":"16916","tlabel":"1753048277","PhoneNumber":"20708","DeviceId":"abcd1234abcd1234","CallId":" >>> <21220-3848@5.6.7.8>21220-3848@5.6.7.8 >>> "},144:{"event":"REGISTER","tindex":"7954","tlabel":"254315075","PhoneNumber":"20709","DeviceId":"abcd1234abcd1234","CallId":" >>> <21223-3848@5.6.7.8>21223-3848@5.6.7.8 >>> "},145:{"event":"REGISTER","tindex":"64529","tlabel":"599481568","PhoneNumber":"20709","DeviceId":"abcd1234abcd1234","CallId":" >>> <21222-3848@5.6.7.8>21222-3848@5.6.7.8"},145:{"event":"REGISTER","tindex":"46605","tlabel":"112015324","PhoneNumber":"20710","DeviceId" >>> >>> >>> >>> >>> T 1.2.3.4:48873 -> 5.6.7.8:3927 [AP] >>> :"abcd1234abcd1234","CallId":" <21224-3848@5.6.7.8>21224-3848@5.6.7.8 >>> "}, >>> >>> *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.* >>> >>> 1.2.3.4:48873 -> 5.6.7.8:3927 [AP] >>> >>> 145:{"event":"REGISTER","tindex":"55567","tlabel":"627458699","PhoneNumber":"20711","DeviceId":"abcd1234abcd1234","CallId":" >>> <21225-3848@5.6.7.8>21225-3848@5.6.7.8 >>> "},143:{"event":"REGISTER","tindex":"28682","tlabel":"9676691","PhoneNumber":"20712","DeviceId":"abcd1234abcd1234","CallId":" >>> <21226-3848@5.6.7.8>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>21225-3848@5.6.7.8 >>> "},143:{"event":"REGISTER","tindex":"28682","tlabel":"9676691","PhoneNumber":"20712","DeviceId":"abcd1234abcd1234","CallId":" >>> <21226-3848@5.6.7.8>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 >>> >>> >>> >>> On Fri, Sep 18, 2015 at 2:55 PM, Jayesh Nambiar < <jayesh1...@gmail.com> >>> jayesh1...@gmail.com> wrote: >>> >>>> Will have this tested by tomorrow and will get back to you. Thanks. >>>> >>>> - Jayesh >>>> >>>> On Fri, Sep 18, 2015 at 1:41 PM, Daniel-Constantin Mierla < >>>> <mico...@gmail.com>mico...@gmail.com> wrote: >>>> >>>>> Hello, >>>>> >>>>> I just pushed a patch to master branch that should cope with partial >>>>> data received on tcp connection. No time to test at all, therefore any >>>>> feedback will be appreciated. >>>>> >>>>> Cheers, >>>>> Daniel >>>>> >>>>> >>>>> On 15/09/15 14:52, Daniel-Constantin Mierla wrote: >>>>> >>>>> Hello, >>>>> >>>>> I will look if there are options in libev to buffer data or try to >>>>> implement a buffering mechanism locally for such cases. >>>>> >>>>> Cheers, >>>>> Daniel >>>>> >>>>> On 14/09/15 23:00, Jayesh Nambiar wrote: >>>>> >>>>> Hello Daniel, >>>>> After further testing with evapi module, I figured that when >>>>> Netstrings are used, an event route is invoked individually for each >>>>> message even if if multiple netstring messages are received in a single >>>>> TCP >>>>> packet. But this doesn't work effectively when a single proper message is >>>>> split-up in two packets. For Example, if a message arrives as: >>>>> 12:Hello World!, 12:Hello World!, 12:Hello World! in a single packet, >>>>> kamailio properly invokes the event route "evapi:message-received" thrice >>>>> for every individual proper netstring message. >>>>> But if the first packet contains: >>>>> 12:Hello World!, 12:Hello >>>>> And Second Packet contains: >>>>> World!, 12:Hello World! >>>>> the event route is invoked only once !! >>>>> >>>>> The above pattern is very much possible while sending and receiving >>>>> packets over TCP Socket. Our tests for receiving an approximately 150 byte >>>>> message over evapi socket at the rate of roughly 1000cps causes a lot of >>>>> real events to be missed because of the above problem. You can never be >>>>> sure when TCP will split messages in different chunks. >>>>> This definitely looks like a bug which makes it not very reliable at >>>>> large scale deployments. Would really appreciate your inputs on this. >>>>> Thanks; >>>>> >>>>> - Jayesh >>>>> >>>>> >>>>> >>>>> On Thu, Sep 10, 2015 at 4:01 PM, Jayesh Nambiar < >>>>> <jayesh1...@gmail.com>jayesh1...@gmail.com> wrote: >>>>> >>>>>> Hi Daniel, >>>>>> Thanks for the quick response. So if I do not use Netstrings, does >>>>>> Kamailio allow me to create a custom logic in the script. For eg. if I >>>>>> decide to use newline as a delimiter, can I keep buffering the message >>>>>> until I encounter the delimiter from the event route and then execute >>>>>> whatever I have to within the script?? >>>>>> >>>>>> Thanks, >>>>>> >>>>>> - Jayesh >>>>>> >>>>>> On Thu, Sep 10, 2015 at 1:29 PM, Daniel-Constantin Mierla < >>>>>> <mico...@gmail.com>mico...@gmail.com> wrote: >>>>>> >>>>>>> Hello, >>>>>>> >>>>>>> tcb is stream protocol and several messages can be queued on the >>>>>>> pipe at the same time. That is the reason for netstring format, to be >>>>>>> able >>>>>>> to easily detect the boundaries of each message. If netstring format is >>>>>>> enabled and kamailio receives several messages at once, it splits them >>>>>>> and >>>>>>> for each is executing the event route. >>>>>>> >>>>>>> If netstring format is not used, the kamailio is executing the event >>>>>>> route with the entire content that was read at once from the tcp >>>>>>> connection. >>>>>>> >>>>>>> Cheers, >>>>>>> Daniel >>>>>>> >>>>>>> >>>>>>> On 09/09/15 22:01, Jayesh Nambiar wrote: >>>>>>> >>>>>>> Hello, >>>>>>> I'm exploring the evapi module for my kamailio to interface with an >>>>>>> external node.js app for third party stuff like AAA, billing engine >>>>>>> tasks, >>>>>>> notifications and so on. I followed and took some ideas from the rtjson >>>>>>> and >>>>>>> evapi tutorial found here( >>>>>>> <http://kb.asipto.com/kamailio:k43-async-sip-routing-nodejs> >>>>>>> http://kb.asipto.com/kamailio:k43-async-sip-routing-nodejs) to >>>>>>> build the node.js app consuming events. >>>>>>> When I stress tested the scenario using SIPp and tried sending a lot >>>>>>> of events at 300-350cps from Kamailio, I noticed that at times the >>>>>>> client >>>>>>> is receiving 2-3 events in a single message together although I do >>>>>>> event_sync_relay once per SIP message received and have netstrings >>>>>>> enabled. >>>>>>> I believe this is a typical behavior of TCP and needs to be handled by >>>>>>> the >>>>>>> client using some kind of Netstring handler. Please correct me if I'm >>>>>>> wrong. >>>>>>> And hence I'd like to know what particularly needs to be taken care >>>>>>> of while writing a client that is listening for events on raw tcp socket >>>>>>> and how does kamailio handle this situation while receiving messages >>>>>>> over >>>>>>> TCP socket?? Does kamailio recognize the end of netstring properly on >>>>>>> evapi:message-received and give exactly one message to take care of on >>>>>>> every "message-received" event or should that be handled in the script >>>>>>> somewhere !! >>>>>>> I also referred cgrates client over evapi example which is written >>>>>>> in GO, but I couldnt find them handling TCP streams clearly either. >>>>>>> I'd really appreciate some expert suggestion here to make an >>>>>>> informed decision on using the evapi module for a large scale solution. >>>>>>> >>>>>>> Thanks, >>>>>>> >>>>>>> - Jayesh >>>>>>> >>>>>>> >>>>>>> >>>>>>> >>>>>>> _______________________________________________ >>>>>>> SIP Express Router (SER) and Kamailio (OpenSER) - sr-users mailing >>>>>>> listsr-us...@lists.sip-router.orghttp://lists.sip-router.org/cgi-bin/mailman/listinfo/sr-users >>>>>>> >>>>>>> >>>>>>> -- >>>>>>> Daniel-Constantin Mierlahttp://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 >>>>>>> >>>>>>> >>>>>>> _______________________________________________ >>>>>>> SIP Express Router (SER) and Kamailio (OpenSER) - sr-users mailing >>>>>>> list >>>>>>> <sr-users@lists.sip-router.org>sr-users@lists.sip-router.org >>>>>>> <http://lists.sip-router.org/cgi-bin/mailman/listinfo/sr-users> >>>>>>> http://lists.sip-router.org/cgi-bin/mailman/listinfo/sr-users >>>>>>> >>>>>>> >>>>>> >>>>> >>>>> -- >>>>> Daniel-Constantin Mierlahttp://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 >>>>> >>>>> >>>>> -- >>>>> Daniel-Constantin Mierlahttp://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 >>>>> >>>>> >>>> >>> >>> -- >>> Daniel-Constantin Mierlahttp://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 >>> >>> >> -- >> Daniel-Constantin Mierlahttp://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 >> >>
_______________________________________________ SIP Express Router (SER) and Kamailio (OpenSER) - sr-users mailing list sr-users@lists.sip-router.org http://lists.sip-router.org/cgi-bin/mailman/listinfo/sr-users
