[OpenSIPS-Devel] Can't get 2.3 running with voiptests properly

Maxim Sobolev sobomax at sippysoft.com
Thu Jul 27 15:59:50 EDT 2017 

Bogdan, I've re-enabled that test and re-run with more debug output
enabled. Here is the problematic run:

Jul 27 19:20:16 [21451] OpenSIPS received a request INVITE from 127.0.0.1
Jul 27 19:20:16 [21451] OpenSIPS received a request INVITE from 127.0.0.1
Jul 27 19:20:16 [21452] OpenSIPS received a request INVITE from
0:0:0:0:0:0:0:1
Jul 27 19:20:16 [21452] OpenSIPS received a request INVITE from
0:0:0:0:0:0:0:1
Jul 27 19:20:16 [21452] OpenSIPS received a request INVITE from
0:0:0:0:0:0:0:1
Jul 27 19:20:16 [21451] OpenSIPS received a request INVITE from 127.0.0.1
Jul 27 19:20:16 [21452] OpenSIPS received a request INVITE from
0:0:0:0:0:0:0:1
Jul 27 19:20:16 [21451] OpenSIPS received a request INVITE from 127.0.0.1
Jul 27 19:20:16 [21451] OpenSIPS received a request INVITE from 127.0.0.1
Jul 27 19:20:16 [21451] OpenSIPS received a request INVITE from 127.0.0.1
Jul 27 19:20:16 [21451] OpenSIPS received a request INVITE from 127.0.0.1
Jul 27 19:20:16 [21451] OpenSIPS received a request INVITE from 127.0.0.1
Jul 27 19:20:16 [21452] OpenSIPS received a request INVITE from
0:0:0:0:0:0:0:1
Jul 27 19:20:16 [21452] OpenSIPS received a request INVITE from
0:0:0:0:0:0:0:1
Jul 27 19:20:16 [21451] OpenSIPS received a reply 100/INVITE from 127.0.0.1
Jul 27 19:20:16 [21451] OpenSIPS received a request INVITE from 127.0.0.1
Jul 27 19:20:16 [21451] OpenSIPS received a request INVITE from 127.0.0.1
Jul 27 19:20:16 [21452] OpenSIPS received a request INVITE from
0:0:0:0:0:0:0:1
Jul 27 19:20:16 [21451] OpenSIPS received a request INVITE from 127.0.0.1
Jul 27 19:20:16 [21452] OpenSIPS received a request INVITE from
0:0:0:0:0:0:0:1
Jul 27 19:20:16 [21452] OpenSIPS received a request INVITE from
0:0:0:0:0:0:0:1
Jul 27 19:20:16 [21451] OpenSIPS received a request INVITE from 127.0.0.1
Jul 27 19:20:16 [21451] OpenSIPS received a request INVITE from 127.0.0.1
Jul 27 19:20:16 [21452] OpenSIPS received a reply 100/INVITE from
0:0:0:0:0:0:0:1
Jul 27 19:20:16 [21451] OpenSIPS received a reply 100/INVITE from 127.0.0.1
Jul 27 19:20:16 [21452] OpenSIPS received a reply 100/INVITE from
0:0:0:0:0:0:0:1
Jul 27 19:20:16 [21452] OpenSIPS received a reply 100/INVITE from
0:0:0:0:0:0:0:1
Jul 27 19:20:16 [21451] OpenSIPS received a reply 100/INVITE from 127.0.0.1
Jul 27 19:20:16 [21452] OpenSIPS received a request INVITE from
0:0:0:0:0:0:0:1
Jul 27 19:20:16 [21452] OpenSIPS received a request INVITE from
0:0:0:0:0:0:0:1
Jul 27 19:20:16 [21451] OpenSIPS received a request INVITE from 127.0.0.1
Jul 27 19:20:16 [21452] OpenSIPS received a request INVITE from
0:0:0:0:0:0:0:1
Jul 27 19:20:17 [21451] OpenSIPS received a request INVITE from 127.0.0.1
Jul 27 19:20:17 [21451] OpenSIPS received a reply 100/INVITE from 127.0.0.1
Jul 27 19:20:17 [21452] OpenSIPS received a request INVITE from
0:0:0:0:0:0:0:1
Jul 27 19:20:17 [21451] OpenSIPS received a reply 100/INVITE from 127.0.0.1
Jul 27 19:20:17 [21451] OpenSIPS received a reply 100/INVITE from 127.0.0.1
Jul 27 19:20:17 [21451] OpenSIPS received a reply 100/INVITE from 127.0.0.1
Jul 27 19:20:17 [21451] OpenSIPS received a reply 100/INVITE from 127.0.0.1
Jul 27 19:20:17 [21451] OpenSIPS received a reply 100/INVITE from 127.0.0.1
Jul 27 19:20:17 [21451] OpenSIPS received a reply 100/INVITE from 127.0.0.1
Jul 27 19:20:17 [21451] OpenSIPS received a reply 100/INVITE from 127.0.0.1
Jul 27 19:20:17 [21451] OpenSIPS received a request CANCEL from 127.0.0.1
Jul 27 19:20:17 [21452] OpenSIPS received a reply 100/INVITE from
0:0:0:0:0:0:0:1
Jul 27 19:20:17 [21452] OpenSIPS received a request INVITE from
0:0:0:0:0:0:0:1
Jul 27 19:20:17 [21452] OpenSIPS received a request INVITE from
0:0:0:0:0:0:0:1
Jul 27 19:20:17 [21452] OpenSIPS received a reply 100/INVITE from
0:0:0:0:0:0:0:1
Jul 27 19:20:17 [21452] OpenSIPS received a reply 100/INVITE from
0:0:0:0:0:0:0:1
Jul 27 19:20:17 [21452] OpenSIPS received a reply 100/INVITE from
0:0:0:0:0:0:0:1
Jul 27 19:20:17 [21452] OpenSIPS received a request CANCEL from
0:0:0:0:0:0:0:1
Jul 27 19:20:20 [21450] WARNING:core:utimer_ticker: utimer task <tm-utimer>
already scheduled for 5690 ms (now 5700 ms), it may overlap..

No output is produced by the OpenSIPS after that. Note that timer thing
might be just one time fluke, I don't see it in 2 other runs (we run 3
instances of the same test for each proxy version for the unix, udp and
udp6 rtpp control channel).

-Max

On Thu, Jul 27, 2017 at 11:59 AM, Maxim Sobolev <sobomax at sippysoft.com>
wrote:

> Bogdan, my wild guess about early CANCEL being the culprit turned out to
> be correct. I've disabled that particular test case and now the remaining
> tests actually able to complete (added more debug to see requests as well)!
>
> Please let me know if you have any ideas about what could be wrong with
> the CANCEL processing, if needed I can add/enable some debug code and let
> it run.
>
> https://travis-ci.org/sippy/voiptests/jobs/258254132
>
>
> Jul 27 18:34:54 [21438] OpenSIPS received a request INVITE from 0:0:0:0:0:0:0:1
>
> Jul 27 18:34:54 [21437] OpenSIPS received a request INVITE from 127.0.0.1
>
> Jul 27 18:34:54 [21438] OpenSIPS received a reply 100/INVITE from 0:0:0:0:0:0:0:1
>
> Jul 27 18:34:54 [21438] OpenSIPS received a request INVITE from 0:0:0:0:0:0:0:1
>
> Jul 27 18:34:54 [21438] OpenSIPS received a request INVITE from 0:0:0:0:0:0:0:1
>
> Jul 27 18:34:54 [21437] OpenSIPS received a request INVITE from 127.0.0.1
>
> Jul 27 18:34:54 [21438] OpenSIPS received a reply 100/INVITE from 0:0:0:0:0:0:0:1
>
> Jul 27 18:34:54 [21437] OpenSIPS received a request INVITE from 127.0.0.1
>
> Jul 27 18:34:54 [21438] OpenSIPS received a request INVITE from 0:0:0:0:0:0:0:1
>
> Jul 27 18:34:54 [21437] OpenSIPS received a request INVITE from 127.0.0.1
>
> Jul 27 18:34:54 [21437] OpenSIPS received a request INVITE from 127.0.0.1
>
> Jul 27 18:34:54 [21437] OpenSIPS received a request INVITE from 127.0.0.1
>
> Jul 27 18:34:54 [21438] OpenSIPS received a request INVITE from 0:0:0:0:0:0:0:1
>
> Jul 27 18:34:54 [21438] OpenSIPS received a request INVITE from 0:0:0:0:0:0:0:1
>
> Jul 27 18:34:54 [21438] OpenSIPS received a request INVITE from 0:0:0:0:0:0:0:1
>
> Jul 27 18:34:54 [21437] OpenSIPS received a reply 100/INVITE from 127.0.0.1
>
> Jul 27 18:34:54 [21438] OpenSIPS received a request INVITE from 0:0:0:0:0:0:0:1
>
> Jul 27 18:34:54 [21437] OpenSIPS received a request INVITE from 127.0.0.1
>
> Jul 27 18:34:54 [21438] OpenSIPS received a reply 100/INVITE from 0:0:0:0:0:0:0:1
>
> Jul 27 18:34:54 [21437] OpenSIPS received a request INVITE from 127.0.0.1
>
> Jul 27 18:34:54 [21437] OpenSIPS received a reply 100/INVITE from 127.0.0.1
>
> Jul 27 18:34:54 [21437] OpenSIPS received a request INVITE from 127.0.0.1
>
> Jul 27 18:34:54 [21437] OpenSIPS received a reply 100/INVITE from 127.0.0.1
>
> Jul 27 18:34:54 [21438] OpenSIPS received a reply 100/INVITE from 0:0:0:0:0:0:0:1
>
> Jul 27 18:34:54 [21438] OpenSIPS received a request INVITE from 0:0:0:0:0:0:0:1
>
> Jul 27 18:34:54 [21438] OpenSIPS received a request INVITE from 0:0:0:0:0:0:0:1
>
> Jul 27 18:34:54 [21437] OpenSIPS received a reply 100/INVITE from 127.0.0.1
>
> Jul 27 18:34:54 [21437] OpenSIPS received a request INVITE from 127.0.0.1
>
> Jul 27 18:34:54 [21438] OpenSIPS received a request INVITE from 0:0:0:0:0:0:0:1
>
> Jul 27 18:34:54 [21437] OpenSIPS received a reply 100/INVITE from 127.0.0.1
>
> Jul 27 18:34:54 [21437] OpenSIPS received a request INVITE from 127.0.0.1
>
> Jul 27 18:34:54 [21437] OpenSIPS received a reply 100/INVITE from 127.0.0.1
>
> Jul 27 18:34:54 [21437] OpenSIPS received a request INVITE from 127.0.0.1
>
> Jul 27 18:34:54 [21438] OpenSIPS received a reply 100/INVITE from 0:0:0:0:0:0:0:1
>
> Jul 27 18:34:54 [21438] OpenSIPS received a request INVITE from 0:0:0:0:0:0:0:1
>
> Jul 27 18:34:54 [21438] OpenSIPS received a reply 100/INVITE from 0:0:0:0:0:0:0:1
>
> Jul 27 18:34:54 [21437] OpenSIPS received a request INVITE from 127.0.0.1
>
> Jul 27 18:34:54 [21438] OpenSIPS received a request INVITE from 0:0:0:0:0:0:0:1
>
> Jul 27 18:34:54 [21438] OpenSIPS received a reply 100/INVITE from 0:0:0:0:0:0:0:1
>
> Jul 27 18:34:54 [21437] OpenSIPS received a request INVITE from 127.0.0.1
>
> Jul 27 18:34:54 [21437] OpenSIPS received a reply 100/INVITE from 127.0.0.1
>
> Jul 27 18:34:54 [21438] OpenSIPS received a request INVITE from 0:0:0:0:0:0:0:1
>
> Jul 27 18:34:54 [21437] OpenSIPS received a reply 100/INVITE from 127.0.0.1
>
> Jul 27 18:34:54 [21437] OpenSIPS received a reply 100/INVITE from 127.0.0.1
>
> Jul 27 18:34:54 [21437] OpenSIPS received a reply 100/INVITE from 127.0.0.1
>
> Jul 27 18:34:54 [21437] OpenSIPS received a reply 100/INVITE from 127.0.0.1
>
> Jul 27 18:34:54 [21437] OpenSIPS received a reply 100/INVITE from 127.0.0.1
>
> Jul 27 18:34:54 [21437] OpenSIPS received a reply 100/INVITE from 127.0.0.1
>
> Jul 27 18:34:54 [21437] OpenSIPS received a reply 100/INVITE from 127.0.0.1
>
> Jul 27 18:34:54 [21438] OpenSIPS received a reply 100/INVITE from 0:0:0:0:0:0:0:1
>
> Jul 27 18:34:54 [21438] OpenSIPS received a reply 100/INVITE from 0:0:0:0:0:0:0:1
>
> Jul 27 18:34:54 [21438] OpenSIPS received a reply 100/INVITE from 0:0:0:0:0:0:0:1
>
> Jul 27 18:34:54 [21438] OpenSIPS received a reply 100/INVITE from 0:0:0:0:0:0:0:1
>
> Jul 27 18:34:54 [21438] OpenSIPS received a reply 100/INVITE from 0:0:0:0:0:0:0:1
>
> Jul 27 18:34:54 [21438] OpenSIPS received a reply 100/INVITE from 0:0:0:0:0:0:0:1
>
> Jul 27 18:34:54 [21438] OpenSIPS received a reply 100/INVITE from 0:0:0:0:0:0:0:1
>
> Jul 27 18:34:55 [21437] OpenSIPS received a reply 180/INVITE from 127.0.0.1
>
> Jul 27 18:34:55 [21437] OpenSIPS received a reply 180/INVITE from 127.0.0.1
>
> Jul 27 18:34:55 [21438] OpenSIPS received a reply 180/INVITE from 0:0:0:0:0:0:0:1
>
> Jul 27 18:34:55 [21437] OpenSIPS received a reply 180/INVITE from 127.0.0.1
>
> Jul 27 18:34:55 [21438] OpenSIPS received a reply 180/INVITE from 0:0:0:0:0:0:0:1
>
> Jul 27 18:34:55 [21438] OpenSIPS received a reply 180/INVITE from 0:0:0:0:0:0:0:1
>
> Jul 27 18:34:55 [21438] OpenSIPS received a reply 180/INVITE from 0:0:0:0:0:0:0:1
>
> Jul 27 18:34:55 [21437] OpenSIPS received a reply 180/INVITE from 127.0.0.1
>
> Jul 27 18:34:59 [21438] OpenSIPS received a reply 183/INVITE from 0:0:0:0:0:0:0:1
>
> Jul 27 18:34:59 [21438]   calling search()
>
> Jul 27 18:34:59 [21438]     calling rtpproxy_answer()
>
> Jul 27 18:34:59 [21438] OpenSIPS received a reply 502/INVITE from 0:0:0:0:0:0:0:1
>
> Jul 27 18:34:59 [21438] OpenSIPS received a request ACK from 0:0:0:0:0:0:0:1
>
> Jul 27 18:34:59 [21438] OpenSIPS received a reply 180/INVITE from 0:0:0:0:0:0:0:1
>
> Jul 27 18:34:59 [21437] OpenSIPS received a reply 180/INVITE from 127.0.0.1
>
> Jul 27 18:34:59 [21437] OpenSIPS received a reply 183/INVITE from 127.0.0.1
>
> Jul 27 18:34:59 [21437]   calling search()
>
> Jul 27 18:34:59 [21437]     calling rtpproxy_answer()
>
> Jul 27 18:34:59 [21437] OpenSIPS received a reply 183/INVITE from 127.0.0.1
>
> Jul 27 18:34:59 [21437]   calling search()
>
> Jul 27 18:34:59 [21437]     calling rtpproxy_answer()
>
> Jul 27 18:34:59 [21438] OpenSIPS received a reply 183/INVITE from 0:0:0:0:0:0:0:1
>
> Jul 27 18:34:59 [21438]   calling search()
>
> Jul 27 18:34:59 [21438]     calling rtpproxy_answer()
>
> Jul 27 18:34:59 [21438] OpenSIPS received a reply 183/INVITE from 0:0:0:0:0:0:0:1
>
> Jul 27 18:34:59 [21438]   calling search()
>
> Jul 27 18:34:59 [21438]     calling rtpproxy_answer()
>
> Jul 27 18:34:59 [21437] OpenSIPS received a reply 502/INVITE from 127.0.0.1
>
> Jul 27 18:34:59 [21437] OpenSIPS received a request ACK from 127.0.0.1
>
> Jul 27 18:34:59 [21437] OpenSIPS received a reply 183/INVITE from 127.0.0.1
>
> Jul 27 18:34:59 [21437]   calling search()
>
> Jul 27 18:34:59 [21437]     calling rtpproxy_answer()
>
> Jul 27 18:34:59 [21437] OpenSIPS received a reply 183/INVITE from 127.0.0.1
>
> Jul 27 18:34:59 [21437]   calling search()
>
> Jul 27 18:34:59 [21437]     calling rtpproxy_answer()
>
> Jul 27 18:34:59 [21438] OpenSIPS received a reply 502/INVITE from 0:0:0:0:0:0:0:1
>
> Jul 27 18:34:59 [21438] OpenSIPS received a request ACK from 0:0:0:0:0:0:0:1
>
> Jul 27 18:34:59 [21437] OpenSIPS received a reply 180/INVITE from 127.0.0.1
>
> Jul 27 18:34:59 [21437] OpenSIPS received a reply 180/INVITE from 127.0.0.1
>
> Jul 27 18:34:59 [21438] OpenSIPS received a reply 180/INVITE from 0:0:0:0:0:0:0:1
>
> Jul 27 18:34:59 [21437] OpenSIPS received a reply 180/INVITE from 127.0.0.1
>
> Jul 27 18:34:59 [21438] OpenSIPS received a reply 183/INVITE from 0:0:0:0:0:0:0:1
>
> Jul 27 18:34:59 [21438]   calling search()
>
> Jul 27 18:34:59 [21438]     calling rtpproxy_answer()
>
> Jul 27 18:34:59 [21437] OpenSIPS received a reply 502/INVITE from 127.0.0.1
>
> Jul 27 18:34:59 [21437] OpenSIPS received a request ACK from 127.0.0.1
>
> Jul 27 18:34:59 [21438] OpenSIPS received a reply 180/INVITE from 0:0:0:0:0:0:0:1
>
> Jul 27 18:34:59 [21438] OpenSIPS received a reply 180/INVITE from 0:0:0:0:0:0:0:1
>
> Jul 27 18:35:00 [21437] OpenSIPS received a reply 200/INVITE from 127.0.0.1
>
> Jul 27 18:35:00 [21437]   calling search()
>
> Jul 27 18:35:00 [21437]     calling rtpproxy_answer()
>
> Jul 27 18:35:00 [21437] OpenSIPS received a reply 200/INVITE from 127.0.0.1
>
> Jul 27 18:35:00 [21437]   calling search()
>
> Jul 27 18:35:00 [21437]     calling rtpproxy_answer()
>
> Jul 27 18:35:00 [21437] OpenSIPS received a request ACK from 127.0.0.1
>
> Jul 27 18:35:00 [21437] OpenSIPS received a request ACK from 127.0.0.1
>
> Jul 27 18:35:00 [21438] OpenSIPS received a reply 200/INVITE from 0:0:0:0:0:0:0:1
>
> Jul 27 18:35:00 [21438]   calling search()
>
> Jul 27 18:35:00 [21438]     calling rtpproxy_answer()
>
> Jul 27 18:35:00 [21438] OpenSIPS received a request ACK from 0:0:0:0:0:0:0:1
>
> Jul 27 18:35:00 [21437] OpenSIPS received a reply 200/INVITE from 127.0.0.1
>
> Jul 27 18:35:00 [21437]   calling search()
>
> Jul 27 18:35:00 [21437]     calling rtpproxy_answer()
>
> Jul 27 18:35:00 [21437] OpenSIPS received a request ACK from 127.0.0.1
>
> Jul 27 18:35:00 [21438] OpenSIPS received a reply 200/INVITE from 0:0:0:0:0:0:0:1
>
> Jul 27 18:35:00 [21438]   calling search()
>
> Jul 27 18:35:00 [21438]     calling rtpproxy_answer()
>
> Jul 27 18:35:00 [21438] OpenSIPS received a request ACK from 0:0:0:0:0:0:0:1
>
> Jul 27 18:35:00 [21438] OpenSIPS received a reply 200/INVITE from 0:0:0:0:0:0:0:1
>
> Jul 27 18:35:00 [21438]   calling search()
>
> Jul 27 18:35:00 [21438]     calling rtpproxy_answer()
>
> Jul 27 18:35:00 [21438] OpenSIPS received a request ACK from 0:0:0:0:0:0:0:1
>
> Jul 27 18:35:00 [21438] OpenSIPS received a reply 200/INVITE from 0:0:0:0:0:0:0:1
>
> Jul 27 18:35:00 [21438]   calling search()
>
> Jul 27 18:35:00 [21438]     calling rtpproxy_answer()
>
> Jul 27 18:35:00 [21438] OpenSIPS received a request ACK from 0:0:0:0:0:0:0:1
>
> Jul 27 18:35:00 [21437] OpenSIPS received a reply 200/INVITE from 127.0.0.1
>
> Jul 27 18:35:00 [21437]   calling search()
>
> Jul 27 18:35:00 [21437]     calling rtpproxy_answer()
>
> Jul 27 18:35:00 [21437] OpenSIPS received a request ACK from 127.0.0.1
>
> Jul 27 18:35:02 [21437] OpenSIPS received a request INVITE from 127.0.0.1
>
> Jul 27 18:35:02 [21437] OpenSIPS received a reply 100/INVITE from 127.0.0.1
>
> Jul 27 18:35:02 [21437] OpenSIPS received a reply 200/INVITE from 127.0.0.1
>
> Jul 27 18:35:02 [21437]   calling search()
>
> Jul 27 18:35:02 [21437]     calling rtpproxy_answer()
>
> Jul 27 18:35:02 [21437] OpenSIPS received a request ACK from 127.0.0.1
>
> Jul 27 18:35:02 [21438] OpenSIPS received a request INVITE from 0:0:0:0:0:0:0:1
>
> Jul 27 18:35:02 [21438] OpenSIPS received a reply 100/INVITE from 0:0:0:0:0:0:0:1
>
> Jul 27 18:35:02 [21438] OpenSIPS received a reply 200/INVITE from 0:0:0:0:0:0:0:1
>
> Jul 27 18:35:02 [21438]   calling search()
>
> Jul 27 18:35:02 [21438]     calling rtpproxy_answer()
>
> Jul 27 18:35:02 [21438] OpenSIPS received a request ACK from 0:0:0:0:0:0:0:1
>
> Jul 27 18:35:04 [21437] OpenSIPS received a request INVITE from 127.0.0.1
>
> Jul 27 18:35:04 [21437] OpenSIPS received a reply 100/INVITE from 127.0.0.1
>
> Jul 27 18:35:04 [21437] OpenSIPS received a reply 200/INVITE from 127.0.0.1
>
> Jul 27 18:35:04 [21437]   calling search()
>
> Jul 27 18:35:04 [21437]     calling rtpproxy_answer()
>
> Jul 27 18:35:04 [21438] OpenSIPS received a request INVITE from 0:0:0:0:0:0:0:1
>
> Jul 27 18:35:04 [21438] OpenSIPS received a reply 100/INVITE from 0:0:0:0:0:0:0:1
>
> Jul 27 18:35:04 [21437] OpenSIPS received a request ACK from 127.0.0.1
>
> Jul 27 18:35:04 [21438] OpenSIPS received a reply 200/INVITE from 0:0:0:0:0:0:0:1
>
> Jul 27 18:35:04 [21438]   calling search()
>
> Jul 27 18:35:04 [21438]     calling rtpproxy_answer()
>
> Jul 27 18:35:04 [21438] OpenSIPS received a request ACK from 0:0:0:0:0:0:0:1
>
> Jul 27 18:35:04 [21438] OpenSIPS received a request INVITE from 0:0:0:0:0:0:0:1
>
> Jul 27 18:35:04 [21438] OpenSIPS received a reply 100/INVITE from 0:0:0:0:0:0:0:1
>
> Jul 27 18:35:04 [21438] OpenSIPS received a reply 200/INVITE from 0:0:0:0:0:0:0:1
>
> Jul 27 18:35:04 [21438]   calling search()
>
> Jul 27 18:35:04 [21438]     calling rtpproxy_answer()
>
> Jul 27 18:35:04 [21438] OpenSIPS received a request ACK from 0:0:0:0:0:0:0:1
>
> Jul 27 18:35:05 [21437] OpenSIPS received a request INVITE from 127.0.0.1
>
> Jul 27 18:35:05 [21437] OpenSIPS received a reply 100/INVITE from 127.0.0.1
>
> Jul 27 18:35:05 [21437] OpenSIPS received a reply 200/INVITE from 127.0.0.1
>
> Jul 27 18:35:05 [21437]   calling search()
>
> Jul 27 18:35:05 [21437]     calling rtpproxy_answer()
>
> Jul 27 18:35:05 [21437] OpenSIPS received a request ACK from 127.0.0.1
>
> Jul 27 18:35:05 [21438] OpenSIPS received a request INVITE from 0:0:0:0:0:0:0:1
>
> Jul 27 18:35:05 [21438] OpenSIPS received a reply 100/INVITE from 0:0:0:0:0:0:0:1
>
> Jul 27 18:35:05 [21438] OpenSIPS received a reply 200/INVITE from 0:0:0:0:0:0:0:1
>
> Jul 27 18:35:05 [21438]   calling search()
>
> Jul 27 18:35:05 [21438]     calling rtpproxy_answer()
>
> Jul 27 18:35:05 [21438] OpenSIPS received a request ACK from 0:0:0:0:0:0:0:1
>
> Jul 27 18:35:05 [21437] OpenSIPS received a request INVITE from 127.0.0.1
>
> Jul 27 18:35:05 [21437] OpenSIPS received a reply 100/INVITE from 127.0.0.1
>
> Jul 27 18:35:05 [21437] OpenSIPS received a reply 200/INVITE from 127.0.0.1
>
> Jul 27 18:35:05 [21437]   calling search()
>
> Jul 27 18:35:05 [21437]     calling rtpproxy_answer()
>
> Jul 27 18:35:05 [21437] OpenSIPS received a request ACK from 127.0.0.1
>
> Jul 27 18:35:05 [21437] OpenSIPS received a request INVITE from 127.0.0.1
>
> Jul 27 18:35:05 [21437] OpenSIPS received a reply 100/INVITE from 127.0.0.1
>
> Jul 27 18:35:05 [21437] OpenSIPS received a reply 200/INVITE from 127.0.0.1
>
> Jul 27 18:35:05 [21437]   calling search()
>
> Jul 27 18:35:05 [21437]     calling rtpproxy_answer()
>
> Jul 27 18:35:05 [21437] OpenSIPS received a request ACK from 127.0.0.1
>
> Jul 27 18:35:05 [21438] OpenSIPS received a request INVITE from 0:0:0:0:0:0:0:1
>
> Jul 27 18:35:05 [21438] OpenSIPS received a reply 100/INVITE from 0:0:0:0:0:0:0:1
>
> Jul 27 18:35:05 [21438] OpenSIPS received a reply 200/INVITE from 0:0:0:0:0:0:0:1
>
> Jul 27 18:35:05 [21438]   calling search()
>
> Jul 27 18:35:05 [21438]     calling rtpproxy_answer()
>
> Jul 27 18:35:05 [21438] OpenSIPS received a request ACK from 0:0:0:0:0:0:0:1
>
> Jul 27 18:35:05 [21437] OpenSIPS received a request INVITE from 127.0.0.1
>
> Jul 27 18:35:05 [21437] OpenSIPS received a reply 100/INVITE from 127.0.0.1
>
> Jul 27 18:35:05 [21437] OpenSIPS received a reply 200/INVITE from 127.0.0.1
>
> Jul 27 18:35:05 [21437]   calling search()
>
> Jul 27 18:35:05 [21437]     calling rtpproxy_answer()
>
> Jul 27 18:35:05 [21437] OpenSIPS received a request ACK from 127.0.0.1
>
> Jul 27 18:35:05 [21438] OpenSIPS received a request INVITE from 0:0:0:0:0:0:0:1
>
> Jul 27 18:35:05 [21438] OpenSIPS received a reply 100/INVITE from 0:0:0:0:0:0:0:1
>
> Jul 27 18:35:05 [21438] OpenSIPS received a reply 200/INVITE from 0:0:0:0:0:0:0:1
>
> Jul 27 18:35:05 [21438]   calling search()
>
> Jul 27 18:35:05 [21438]     calling rtpproxy_answer()
>
> Jul 27 18:35:05 [21438] OpenSIPS received a request ACK from 0:0:0:0:0:0:0:1
>
> Jul 27 18:35:08 [21437] OpenSIPS received a request INVITE from 127.0.0.1
>
> Jul 27 18:35:08 [21437] OpenSIPS received a reply 100/INVITE from 127.0.0.1
>
> Bob(bob_reinv_fail): Incoming event: CCEventUpdate, generating failure
>
> Jul 27 18:35:08 [21437] OpenSIPS received a reply 408/INVITE from 127.0.0.1
>
> Jul 27 18:35:08 [21437] OpenSIPS received a request BYE from 127.0.0.1
>
> Alice(alice_reinv_fail_ipv4): Incoming event: CCEventFail, ignoring
>
> Jul 27 18:35:08 [21437] OpenSIPS received a request ACK from 127.0.0.1
>
> Jul 27 18:35:08 [21438] OpenSIPS received a request INVITE from 0:0:0:0:0:0:0:1
>
> Bob(bob_reinv_fail): Incoming event: CCEventUpdate, generating failure
>
> Jul 27 18:35:08 [21438] OpenSIPS received a reply 100/INVITE from 0:0:0:0:0:0:0:1
>
> Jul 27 18:35:08 [21438] OpenSIPS received a reply 408/INVITE from 0:0:0:0:0:0:0:1
>
> Jul 27 18:35:08 [21438] OpenSIPS received a request BYE from 0:0:0:0:0:0:0:1
>
> Alice(alice_reinv_fail_ipv6): Incoming event: CCEventFail, ignoring
>
> Jul 27 18:35:08 [21438] OpenSIPS received a request ACK from 0:0:0:0:0:0:0:1
>
> Jul 27 18:35:08 [21438] OpenSIPS received a request INVITE from 0:0:0:0:0:0:0:1
>
> Jul 27 18:35:08 [21438] OpenSIPS received a reply 100/INVITE from 0:0:0:0:0:0:0:1
>
> Jul 27 18:35:08 [21438] OpenSIPS received a reply 200/INVITE from 0:0:0:0:0:0:0:1
>
> Jul 27 18:35:08 [21438]   calling search()
>
> Jul 27 18:35:08 [21438]     calling rtpproxy_answer()
>
> Jul 27 18:35:08 [21438] OpenSIPS received a request ACK from 0:0:0:0:0:0:0:1
>
> Jul 27 18:35:08 [21437] OpenSIPS received a request INVITE from 127.0.0.1
>
> Jul 27 18:35:08 [21437] OpenSIPS received a reply 100/INVITE from 127.0.0.1
>
> Jul 27 18:35:08 [21437] OpenSIPS received a reply 200/INVITE from 127.0.0.1
>
> Jul 27 18:35:08 [21437]   calling search()
>
> Jul 27 18:35:08 [21437]     calling rtpproxy_answer()
>
> Jul 27 18:35:08 [21437] OpenSIPS received a request ACK from 127.0.0.1
>
> Jul 27 18:35:09 [21437] OpenSIPS received a reply 501/INVITE from 127.0.0.1
>
> Jul 27 18:35:09 [21437] OpenSIPS received a request ACK from 127.0.0.1
>
> Jul 27 18:35:09 [21437] OpenSIPS received a reply 200/INVITE from 127.0.0.1
>
> Jul 27 18:35:09 [21437]   calling search()
>
> Jul 27 18:35:09 [21437]     calling rtpproxy_answer()
>
> Jul 27 18:35:09 [21437] OpenSIPS received a request ACK from 127.0.0.1
>
> Jul 27 18:35:09 [21437] OpenSIPS received a request BYE from 127.0.0.1
>
> Jul 27 18:35:09 [21438] OpenSIPS received a request BYE from 0:0:0:0:0:0:0:1
>
> Jul 27 18:35:09 [21437] OpenSIPS received a request BYE from 127.0.0.1
>
> Jul 27 18:35:09 [21438] OpenSIPS received a request BYE from 0:0:0:0:0:0:0:1
>
> Jul 27 18:35:09 [21438] OpenSIPS received a request BYE from 0:0:0:0:0:0:0:1
>
> Jul 27 18:35:09 [21437] OpenSIPS received a request BYE from 127.0.0.1
>
> Jul 27 18:35:10 [21438] OpenSIPS received a reply 503/INVITE from 0:0:0:0:0:0:0:1
>
> Jul 27 18:35:10 [21438] OpenSIPS received a request ACK from 0:0:0:0:0:0:0:1
>
> Jul 27 18:35:10 [21437] OpenSIPS received a reply 503/INVITE from 127.0.0.1
>
> Jul 27 18:35:10 [21437] OpenSIPS received a request ACK from 127.0.0.1
>
> Jul 27 18:35:10 [21438] OpenSIPS received a reply 200/INVITE from 0:0:0:0:0:0:0:1
>
> Jul 27 18:35:10 [21438]   calling search()
>
> Jul 27 18:35:10 [21438]     calling rtpproxy_answer()
>
> Jul 27 18:35:10 [21438] OpenSIPS received a request ACK from 0:0:0:0:0:0:0:1
>
> Jul 27 18:35:10 [21437] OpenSIPS received a reply 200/INVITE from 127.0.0.1
>
> Jul 27 18:35:10 [21437]   calling search()
>
> Jul 27 18:35:10 [21437]     calling rtpproxy_answer()
>
> Jul 27 18:35:10 [21437] OpenSIPS received a request ACK from 127.0.0.1
>
> Jul 27 18:35:10 [21437] OpenSIPS received a reply 503/INVITE from 127.0.0.1
>
> Jul 27 18:35:10 [21437] OpenSIPS received a request ACK from 127.0.0.1
>
> Jul 27 18:35:10 [21438] OpenSIPS received a reply 200/INVITE from 0:0:0:0:0:0:0:1
>
> Jul 27 18:35:10 [21438]   calling search()
>
> Jul 27 18:35:10 [21438]     calling rtpproxy_answer()
>
> Jul 27 18:35:10 [21438] OpenSIPS received a request ACK from 0:0:0:0:0:0:0:1
>
> Jul 27 18:35:10 [21437] OpenSIPS received a reply 501/INVITE from 127.0.0.1
>
> Jul 27 18:35:10 [21437] OpenSIPS received a request ACK from 127.0.0.1
>
> Jul 27 18:35:10 [21438] OpenSIPS received a reply 200/INVITE from 0:0:0:0:0:0:0:1
>
> Jul 27 18:35:10 [21438]   calling search()
>
> Jul 27 18:35:10 [21438]     calling rtpproxy_answer()
>
> Jul 27 18:35:10 [21438] OpenSIPS received a request ACK from 0:0:0:0:0:0:0:1
>
> Jul 27 18:35:10 [21438] OpenSIPS received a reply 503/INVITE from 0:0:0:0:0:0:0:1
>
> Jul 27 18:35:10 [21438] OpenSIPS received a request ACK from 0:0:0:0:0:0:0:1
>
> Jul 27 18:35:11 [21437] OpenSIPS received a reply 200/INVITE from 127.0.0.1
>
> Jul 27 18:35:11 [21437]   calling search()
>
> Jul 27 18:35:11 [21437]     calling rtpproxy_answer()
>
> Jul 27 18:35:11 [21437] OpenSIPS received a request ACK from 127.0.0.1
>
> Jul 27 18:35:11 [21438] OpenSIPS received a reply 200/INVITE from 0:0:0:0:0:0:0:1
>
> Jul 27 18:35:11 [21438]   calling search()
>
> Jul 27 18:35:11 [21438]     calling rtpproxy_answer()
>
> Jul 27 18:35:11 [21438] OpenSIPS received a request ACK from 0:0:0:0:0:0:0:1
>
> Jul 27 18:35:12 [21437] OpenSIPS received a reply 200/INVITE from 127.0.0.1
>
> Jul 27 18:35:12 [21437]   calling search()
>
> Jul 27 18:35:12 [21437]     calling rtpproxy_answer()
>
> Jul 27 18:35:12 [21437] OpenSIPS received a request ACK from 127.0.0.1
>
> Jul 27 18:35:12 [21438] OpenSIPS received a reply 501/INVITE from 0:0:0:0:0:0:0:1
>
> Jul 27 18:35:12 [21438] OpenSIPS received a request ACK from 0:0:0:0:0:0:0:1
>
> Jul 27 18:35:12 [21438] OpenSIPS received a reply 501/INVITE from 0:0:0:0:0:0:0:1
>
> Jul 27 18:35:12 [21438] OpenSIPS received a request ACK from 0:0:0:0:0:0:0:1
>
> Jul 27 18:35:16 [21438] OpenSIPS received a request BYE from 0:0:0:0:0:0:0:1
>
> Jul 27 18:35:18 [21437] OpenSIPS received a request BYE from 127.0.0.1
>
> Jul 27 18:35:18 [21437] OpenSIPS received a request BYE from 127.0.0.1
>
> Jul 27 18:35:19 [21438] OpenSIPS received a request BYE from 0:0:0:0:0:0:0:1
>
> Jul 27 18:35:19 [21437] OpenSIPS received a request BYE from 127.0.0.1
>
> Jul 27 18:35:19 [21438] OpenSIPS received a request BYE from 0:0:0:0:0:0:0:1
>
> Jul 27 18:35:20 [21437] OpenSIPS received a request BYE from 127.0.0.1
>
> Jul 27 18:35:20 [21438] OpenSIPS received a request BYE from 0:0:0:0:0:0:0:1
>
>
> On Thu, Jul 27, 2017 at 11:13 AM, Maxim Sobolev <sobomax at sippysoft.com>
> wrote:
>
>> Yes, 100 Trying is received from B but A cancels immediately after 100
>> Trying from OpenSIPS, so CANCEL from A comes millisecond earlier than 100
>> Trying from B, whether those are coming in that order  to opensips it's
>> hard to tell. In any case, OpenSIPS continues re-invite re-invite
>> re-transmits to B side like no 100 Trying has been received until
>> eventually it emits 408 Request Timeout to A.
>>
>> 0:00:02.393/GLOBAL/alice_ua: SENDING message to 127.0.0.1:5060:
>> INVITE sip:bob_early_cancel at 127.0.0.1:5060 SIP/2.0
>>
>> 00:00:02.396/GLOBAL/alice_ua: RECEIVED message from 127.0.0.1:5060:
>> SIP/2.0 100 Trying
>>
>> 00:00:02.399/GLOBAL/bob_ua: RECEIVED message from 127.0.0.1:5060:
>> INVITE sip:bob_early_cancel at 127.0.0.1:5062 SIP/2.0
>>
>> 00:00:02.433/GLOBAL/alice_ua: SENDING message to 127.0.0.1:5060:
>> CANCEL sip:bob_early_cancel at 127.0.0.1:5060 SIP/2.0
>>
>> 00:00:02.434/GLOBAL/bob_ua: SENDING message to 127.0.0.1:5060:
>> SIP/2.0 100 Trying
>>
>> 00:00:02.936/GLOBAL/bob_ua: RECEIVED message from 127.0.0.1:5060:
>> INVITE sip:bob_early_cancel at 127.0.0.1:5062 SIP/2.0
>>
>> 00:00:03.941/GLOBAL/bob_ua: SENDING message to 127.0.0.1:5060:
>> SIP/2.0 100 Trying
>>
>> [...INVITE->B B->100 Trying continues...]
>>
>> 00:00:32.661/GLOBAL/alice_ua: RECEIVED message from 127.0.0.1:5060:
>> SIP/2.0 408 Request Timeout
>>
>> On Thu, Jul 27, 2017 at 10:04 AM, Bogdan-Andrei Iancu <
>> bogdan at opensips.org> wrote:
>>
>>> What's the call flow ? I suppose the INVITE gets relayed out, but is
>>> there any reply coming back from the B side ?
>>>
>>> Bogdan-Andrei Iancu
>>>   OpenSIPS Founder and Developer
>>>   http://www.opensips-solutions.com
>>>
>>> OpenSIPS Bootcamp 2017, Houston, US
>>>   http://opensips.org/training/OpenSIPS_Bootcamp_2017.html
>>>
>>> On 07/27/2017 08:02 PM, Maxim Sobolev wrote:
>>>
>>> Thanks, I'll try that. However it's not really "stuck-stuck", see my
>>> e-mail, it does re-transmissions and eventually "unstucks" itself.
>>>
>>> On Thu, Jul 27, 2017 at 9:53 AM, Bogdan-Andrei Iancu <
>>> bogdan at opensips.org> wrote:
>>>
>>>> Hi Maxim,
>>>>
>>>> When you see it stuck, run "opensipsctl trap" to get a dump with the
>>>> backtraces from all processes .....and you can see what that they are
>>>> doing...
>>>>
>>>> Regards,
>>>>
>>>> Bogdan-Andrei Iancu
>>>>   OpenSIPS Founder and Developer
>>>>   http://www.opensips-solutions.com
>>>>
>>>> OpenSIPS Bootcamp 2017, Houston, US
>>>>   http://opensips.org/training/OpenSIPS_Bootcamp_2017.html
>>>>
>>>> On 07/27/2017 07:46 PM, Maxim Sobolev wrote:
>>>>
>>>> Hi folks, we are getting some unexpected trouble with getting 2.3 to
>>>> run properly with voiptests. The issue is that after brief time after
>>>> starting up the proxy stops accepting any new requests/replies. As far as I
>>>> can tell no error output is produced and the opensips eventually exits
>>>> normally. I've added some debug output into the routing script to log
>>>> replies, but I don't see anything logged after 100 Trying.
>>>>
>>>> Full log can be found here, it also dumps effective config.
>>>>
>>>> https://travis-ci.org/sippy/voiptests/jobs/257935671
>>>>
>>>> The only thing I can think of being unusual in our setup is that we are
>>>> running in "foreground" mode, so that we can wait(1) on the pid and
>>>> retrieve status code when it finishes.
>>>>
>>>> Any ideas are greatly appreciated. We can also add more debug if needed.
>>>>
>>>> Jul 26 23:53:38 [21441] OpenSIPS received a reply 100/INVITE from 0:0:0:0:0:0:0:1
>>>>
>>>> Jul 26 23:53:38 [21441] OpenSIPS received a reply 100/INVITE from 0:0:0:0:0:0:0:1
>>>>
>>>> Jul 26 23:53:38 [21441] OpenSIPS received a reply 100/INVITE from 0:0:0:0:0:0:0:1
>>>>
>>>> Jul 26 23:53:38 [21441] OpenSIPS received a reply 100/INVITE from 0:0:0:0:0:0:0:1
>>>>
>>>> Jul 26 23:53:38 [21441] OpenSIPS received a reply 100/INVITE from 0:0:0:0:0:0:0:1
>>>>
>>>> Jul 26 23:53:38 [21440] OpenSIPS received a reply 100/INVITE from 127.0.0.1
>>>>
>>>> Jul 26 23:53:38 [21440] OpenSIPS received a reply 100/INVITE from 127.0.0.1
>>>>
>>>> Jul 26 23:53:38 [21440] OpenSIPS received a reply 100/INVITE from 127.0.0.1
>>>>
>>>> Jul 26 23:53:38 [21441] OpenSIPS received a reply 100/INVITE from 0:0:0:0:0:0:0:1
>>>>
>>>> Jul 26 23:53:38 [21440] OpenSIPS received a reply 100/INVITE from 127.0.0.1
>>>>
>>>> Jul 26 23:53:38 [21441] OpenSIPS received a reply 100/INVITE from 0:0:0:0:0:0:0:1
>>>>
>>>> Jul 26 23:53:38 [21440] OpenSIPS received a reply 100/INVITE from 127.0.0.1
>>>>
>>>> Jul 26 23:53:38 [21440] OpenSIPS received a reply 100/INVITE from 127.0.0.1
>>>>
>>>> Jul 26 23:53:38 [21440] OpenSIPS received a reply 100/INVITE from 127.0.0.1
>>>>
>>>> Jul 26 23:53:38 [21441] OpenSIPS received a reply 100/INVITE from 0:0:0:0:0:0:0:1
>>>>
>>>> Jul 26 23:53:38 [21441] OpenSIPS received a reply 100/INVITE from 0:0:0:0:0:0:0:1
>>>>
>>>> Jul 26 23:53:38 [21441] OpenSIPS received a reply 100/INVITE from 0:0:0:0:0:0:0:1
>>>>
>>>> Jul 26 23:53:38 [21441] OpenSIPS received a reply 100/INVITE from 0:0:0:0:0:0:0:1
>>>>
>>>> Jul 26 23:53:38 [21441] OpenSIPS received a reply 100/INVITE from 0:0:0:0:0:0:0:1
>>>>
>>>> Jul 26 23:53:38 [21441] OpenSIPS received a reply 100/INVITE from 0:0:0:0:0:0:0:1
>>>>
>>>> Jul 26 23:53:38 [21440] OpenSIPS received a reply 100/INVITE from 127.0.0.1
>>>>
>>>> Jul 26 23:53:38 [21440] OpenSIPS received a reply 100/INVITE from 127.0.0.1
>>>>
>>>>
>>>>
>>>> +kill -TERM 21436
>>>>
>>>> +echo MM_PID: 21436
>>>>
>>>> MM_PID: 21436
>>>>
>>>> +wait 21436
>>>>
>>>> Thank you for flying opensips
>>>>
>>>> +MM_RC=0
>>>>
>>>>
>>>>
>>>
>>>
>>> --
>>> Maksym Sobolyev
>>> Sippy Software, Inc.
>>> Internet Telephony (VoIP) Experts
>>> Tel (Canada): +1-778-783-0474 <(778)%20783-0474>
>>> Tel (Toll-Free): +1-855-747-7779 <(855)%20747-7779>
>>> Fax: +1-866-857-6942 <(866)%20857-6942>
>>> Web: http://www.sippysoft.com
>>> MSN: sales at sippysoft.com
>>> Skype: SippySoft
>>>
>>>
>>>
>>
>>
>> --
>> Maksym Sobolyev
>> Sippy Software, Inc.
>> Internet Telephony (VoIP) Experts
>> Tel (Canada): +1-778-783-0474 <(778)%20783-0474>
>> Tel (Toll-Free): +1-855-747-7779 <(855)%20747-7779>
>> Fax: +1-866-857-6942 <(866)%20857-6942>
>> Web: http://www.sippysoft.com
>> MSN: sales at sippysoft.com
>> Skype: SippySoft
>>
>
>
>
> --
> Maksym Sobolyev
> Sippy Software, Inc.
> Internet Telephony (VoIP) Experts
> Tel (Canada): +1-778-783-0474 <(778)%20783-0474>
> Tel (Toll-Free): +1-855-747-7779 <(855)%20747-7779>
> Fax: +1-866-857-6942 <(866)%20857-6942>
> Web: http://www.sippysoft.com
> MSN: sales at sippysoft.com
> Skype: SippySoft
>



-- 
Maksym Sobolyev
Sippy Software, Inc.
Internet Telephony (VoIP) Experts
Tel (Canada): +1-778-783-0474
Tel (Toll-Free): +1-855-747-7779
Fax: +1-866-857-6942
Web: http://www.sippysoft.com
MSN: sales at sippysoft.com
Skype: SippySoft
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.opensips.org/pipermail/devel/attachments/20170727/03ae5763/attachment-0001.html>

More information about the Devel mailing list