Can't get 2.3 running with voiptests properly

classic Classic list List threaded Threaded
13 messages Options
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Can't get 2.3 running with voiptests properly

Maxim Sobolev
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.


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


_______________________________________________
Devel mailing list
[hidden email]
http://lists.opensips.org/cgi-bin/mailman/listinfo/devel
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: Can't get 2.3 running with voiptests properly

Bogdan-Andrei Iancu-2
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.


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



_______________________________________________
Devel mailing list
[hidden email]
http://lists.opensips.org/cgi-bin/mailman/listinfo/devel
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: Can't get 2.3 running with voiptests properly

Maxim Sobolev
In reply to this post by Maxim Sobolev
Just a little big of more debug, the message processing on Alice side stops after this exchange:

00:00:03.839/GLOBAL/alice_ua: RECEIVED message from 127.0.0.1:5060:
SIP/2.0 100 Giving a try
v: SIP/2.0/UDP 127.0.0.1:5061;received=127.0.0.1;branch=z9hG4bKfa99d5e33e5a65ffd3d6dff13e002248;rport=5061
f: "Alice Smith" <[hidden email]>;tag=46ab5763086d0d7b59a49297c8088e99
t: <[hidden email]>
i: [hidden email]
CSeq: 200 INVITE
Server: OpenSIPS (2.3.1 (x86_64/linux))
Content-Length: 0

00:00:04.312/GLOBAL/alice_ua: SENDING message to [::1]:5060:
CANCEL sip:bob_early_cancel@[::1]:5060 SIP/2.0
Via: SIP/2.0/UDP [::1]:5061;rport;branch=z9hG4bK2ec62cc49f6f02cf2cbc93ec19e89ff5
Max-Forwards: 70
From: "Alice Smith" <sip:alice_early_cancel_ipv6@[::1]>;tag=0eade29cb9f0b1a2aad797f2f052b9fc
To: <sip:bob_early_cancel@[::1]>
Call-ID: [hidden email]
CSeq: 200 CANCEL
User-Agent: Sippy
Content-Length: 0
Then it pretty much stays mute for 30 seconds ignoring anything from Alice until we get this:
00:00:34.185/GLOBAL/alice_ua: RECEIVED message from 127.0.0.1:5060:
SIP/2.0 408 Request Timeout
Via: SIP/2.0/UDP 127.0.0.1:5061;received=127.0.0.1;branch=z9hG4bK559f343d8acaf4f0255ffa7487b3d36e;rport=5061
From: "Alice Smith" <[hidden email]>;tag=95f73c1ed722dbe6bf619dbd68147be5
To: <[hidden email]>;tag=155c340f586c28d0300cf5a6ccf90d99-24f1
Call-ID: [hidden email]
CSeq: 200 INVITE
Server: OpenSIPS (2.3.1 (x86_64/linux))
Content-Length: 0
Now, looking at the bob side re-transmission of INVITEs continues during the interval (looks like 100 Trying is being ignored).
Working hypothesis that I have is that this might be somehow related to the early CANCEL transaction, I see some pattern of OpenSIPS going mute after receiving that. Any thoughts? I might take that early cancel test out and see if it helps.

On Thu, Jul 27, 2017 at 9:46 AM, Maxim Sobolev <[hidden email]> 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.


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
Tel (Toll-Free): +1-855-747-7779
Fax: +1-866-857-6942
Web: http://www.sippysoft.com
MSN: [hidden email]
Skype: SippySoft

_______________________________________________
Devel mailing list
[hidden email]
http://lists.opensips.org/cgi-bin/mailman/listinfo/devel
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: Can't get 2.3 running with voiptests properly

Maxim Sobolev
In reply to this post by Bogdan-Andrei Iancu-2
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 <[hidden email]> 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.


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
Tel (Toll-Free): +1-855-747-7779
Fax: +1-866-857-6942
Web: http://www.sippysoft.com
MSN: [hidden email]
Skype: SippySoft

_______________________________________________
Devel mailing list
[hidden email]
http://lists.opensips.org/cgi-bin/mailman/listinfo/devel
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: Can't get 2.3 running with voiptests properly

Bogdan-Andrei Iancu-2
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 <[hidden email]> 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.


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
Tel (Toll-Free): +1-855-747-7779
Fax: +1-866-857-6942
Web: http://www.sippysoft.com
MSN: [hidden email]
Skype: SippySoft


_______________________________________________
Devel mailing list
[hidden email]
http://lists.opensips.org/cgi-bin/mailman/listinfo/devel
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: Can't get 2.3 running with voiptests properly

Maxim Sobolev
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:

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:

00:00:02.433/GLOBAL/alice_ua: SENDING message to 127.0.0.1:5060:

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:

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 <[hidden email]> 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 <[hidden email]> 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.


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): <a href="tel:(778)%20783-0474" value="+17787830474" target="_blank">+1-778-783-0474
Tel (Toll-Free): <a href="tel:(855)%20747-7779" value="+18557477779" target="_blank">+1-855-747-7779
Fax: <a href="tel:(866)%20857-6942" value="+18668576942" target="_blank">+1-866-857-6942
Web: http://www.sippysoft.com
MSN: [hidden email]
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: [hidden email]
Skype: SippySoft

_______________________________________________
Devel mailing list
[hidden email]
http://lists.opensips.org/cgi-bin/mailman/listinfo/devel
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: Can't get 2.3 running with voiptests properly

Maxim Sobolev
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. 



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 <[hidden email]> 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:

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:

00:00:02.433/GLOBAL/alice_ua: SENDING message to 127.0.0.1:5060:

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:

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 <[hidden email]> 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 <[hidden email]> 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.


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): <a href="tel:(778)%20783-0474" value="+17787830474" target="_blank">+1-778-783-0474
Tel (Toll-Free): <a href="tel:(855)%20747-7779" value="+18557477779" target="_blank">+1-855-747-7779
Fax: <a href="tel:(866)%20857-6942" value="+18668576942" target="_blank">+1-866-857-6942
Web: http://www.sippysoft.com
MSN: [hidden email]
Skype: SippySoft




--
Maksym Sobolyev
Sippy Software, Inc.
Internet Telephony (VoIP) Experts
Tel (Canada): <a href="tel:(778)%20783-0474" value="+17787830474" target="_blank">+1-778-783-0474
Tel (Toll-Free): <a href="tel:(855)%20747-7779" value="+18557477779" target="_blank">+1-855-747-7779
Fax: <a href="tel:(866)%20857-6942" value="+18668576942" target="_blank">+1-866-857-6942
Web: http://www.sippysoft.com
MSN: [hidden email]
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: [hidden email]
Skype: SippySoft

_______________________________________________
Devel mailing list
[hidden email]
http://lists.opensips.org/cgi-bin/mailman/listinfo/devel
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: Can't get 2.3 running with voiptests properly

Maxim Sobolev
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 <[hidden email]> 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. 



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 <[hidden email]> 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:

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:

00:00:02.433/GLOBAL/alice_ua: SENDING message to 127.0.0.1:5060:

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:

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 <[hidden email]> 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 <[hidden email]> 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.


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): <a href="tel:(778)%20783-0474" value="+17787830474" target="_blank">+1-778-783-0474
Tel (Toll-Free): <a href="tel:(855)%20747-7779" value="+18557477779" target="_blank">+1-855-747-7779
Fax: <a href="tel:(866)%20857-6942" value="+18668576942" target="_blank">+1-866-857-6942
Web: http://www.sippysoft.com
MSN: [hidden email]
Skype: SippySoft




--
Maksym Sobolyev
Sippy Software, Inc.
Internet Telephony (VoIP) Experts
Tel (Canada): <a href="tel:(778)%20783-0474" value="+17787830474" target="_blank">+1-778-783-0474
Tel (Toll-Free): <a href="tel:(855)%20747-7779" value="+18557477779" target="_blank">+1-855-747-7779
Fax: <a href="tel:(866)%20857-6942" value="+18668576942" target="_blank">+1-866-857-6942
Web: http://www.sippysoft.com
MSN: [hidden email]
Skype: SippySoft



--
Maksym Sobolyev
Sippy Software, Inc.
Internet Telephony (VoIP) Experts
Tel (Canada): <a href="tel:(778)%20783-0474" value="+17787830474" target="_blank">+1-778-783-0474
Tel (Toll-Free): <a href="tel:(855)%20747-7779" value="+18557477779" target="_blank">+1-855-747-7779
Fax: <a href="tel:(866)%20857-6942" value="+18668576942" target="_blank">+1-866-857-6942
Web: http://www.sippysoft.com
MSN: [hidden email]
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: [hidden email]
Skype: SippySoft

_______________________________________________
Devel mailing list
[hidden email]
http://lists.opensips.org/cgi-bin/mailman/listinfo/devel
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: Can't get 2.3 running with voiptests properly

Bogdan-Andrei Iancu-2
Hi Maxim,,

Is it possible to send me (off list) a pcap (in and out from OpenSIPS)
and the log in log_level 4. I will try to investigate to see what is the
actual problem.

Thanks and 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 10:59 PM, Maxim Sobolev wrote:

> 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
>


_______________________________________________
Devel mailing list
[hidden email]
http://lists.opensips.org/cgi-bin/mailman/listinfo/devel
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: Can't get 2.3 running with voiptests properly

Maxim Sobolev
Bogdan, I've added extra debug, the output around stuckage looks like the below. As for getting PCAP capture that is not easy to arrange as TravisCI does not give us direct access to the network capture. However, bot A and B log whatever is being sent/received, so it should not be that difficult to correlate. You can find the full log here:

http://bit.ly/2vgtcu2

Let me know if it helps to narrow it down or if you need more information. I might try to reproduce it locally here.

-Max

Jul 28 22:18:39 [21433] DBG:core:receive_msg: cleaning up
Jul 28 22:18:39 [21433] DBG:core:parse_msg: SIP Request:
Jul 28 22:18:39 [21433] DBG:core:parse_msg:  method:  <CANCEL>
Jul 28 22:18:39 [21433] DBG:core:parse_msg:  uri:     <sip:bob_early_cancel@[::1]:5060>
Jul 28 22:18:39 [21433] DBG:core:parse_msg:  version: <SIP/2.0>
Jul 28 22:18:39 [21433] DBG:core:parse_headers: flags=2
Jul 28 22:18:39 [21433] DBG:core:parse_via_param: found param type 235, <rport> = <n/a>; state=6
Jul 28 22:18:39 [21433] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK5aad8c9774f140be692c3025b6a86417>; state=16
Jul 28 22:18:39 [21433] DBG:core:parse_via: end of header reached, state=5
Jul 28 22:18:39 [21433] DBG:core:parse_headers: via found, flags=2
Jul 28 22:18:39 [21433] DBG:core:parse_headers: this is the first via
Jul 28 22:18:39 [21433] DBG:core:receive_msg: After parse_msg...
Jul 28 22:18:39 [21433] DBG:core:receive_msg: preparing to run routing scripts...
Jul 28 22:18:39 [21433] OpenSIPS received a request CANCEL from 0:0:0:0:0:0:0:1
Jul 28 22:18:39 [21433] DBG:core:parse_headers: flags=100
Jul 28 22:18:39 [21433] DBG:maxfwd:is_maxfwd_present: value = 70 
Jul 28 22:18:39 [21433] DBG:tm:t_newtran: transaction on entrance=0xffffffffffffffff
Jul 28 22:18:39 [21433] DBG:core:parse_headers: flags=ffffffffffffffff
Jul 28 22:18:39 [21433] DBG:core:parse_to: end of header reached, state=10
Jul 28 22:18:39 [21433] DBG:core:parse_to: display={}, ruri={sip:bob_early_cancel@[::1]}
Jul 28 22:18:39 [21433] DBG:core:get_hdr_field: <To> [30]; uri=[sip:bob_early_cancel@[::1]] 
Jul 28 22:18:39 [21433] DBG:core:get_hdr_field: to body [<sip:bob_early_cancel@[::1]>]
Jul 28 22:18:39 [21433] DBG:core:get_hdr_field: cseq <CSeq>: <200> <CANCEL>
Jul 28 22:18:39 [21433] DBG:core:get_hdr_field: content_length=0
Jul 28 22:18:39 [21433] DBG:core:get_hdr_field: found end of header
Jul 28 22:18:39 [21433] DBG:core:parse_headers: flags=78
Jul 28 22:18:39 [21433] DBG:tm:t_lookup_request: start searching: hash=18081, isACK=0
Jul 28 22:18:39 [21433] DBG:tm:matching_3261: RFC3261 transaction matching failed
Jul 28 22:18:39 [21433] DBG:tm:t_lookup_request: no transaction found
Jul 28 22:18:39 [21433] DBG:tm:run_reqin_callbacks: trans=0x7f63d409bc20, callback type 1, id 0 entered
Jul 28 22:18:39 [21433] DBG:core:parse_to_param: tag=211ce361902b0d1ce3ec04a495688cf6
Jul 28 22:18:39 [21433] DBG:core:parse_to: end of header reached, state=29
Jul 28 22:18:39 [21433] DBG:core:parse_to: display={"Alice Smith"}, ruri={sip:alice_early_cancel_ipv6@[::1]}
Jul 28 22:18:39 [21433] DBG:core:parse_headers: flags=200
Jul 28 22:18:39 [21433] DBG:rr:find_first_route: No Route headers found
Jul 28 22:18:39 [21433] DBG:rr:loose_route: There is no Route HF
Jul 28 22:18:39 [21433] DBG:tm:update_cloned_msg_from_msg: new_uri must be copied old=0, new=31
Jul 28 22:18:39 [21433] DBG:tm:t_lookupOriginalT: searching on hash entry 18081
Jul 28 22:18:39 [21433] DBG:tm:matching_3261: RFC3261 transaction matched, tid=5aad8c9774f140be692c3025b6a86417
Jul 28 22:18:39 [21433] DBG:tm:t_lookupOriginalT: canceled transaction found (0x7f63d4022f18)! 
Jul 28 22:18:39 [21433] DBG:tm:t_lookupOriginalT: REF_UNSAFE:[0x7f63d4022f18] after is 1
Jul 28 22:18:39 [21433] DBG:tm:t_lookupOriginalT: t_lookupOriginalT completed
Jul 28 22:18:39 [21433] DBG:core:parse_headers: flags=ffffffffffffffff
Jul 28 22:18:40 [21437] DBG:tm:utimer_routine: timer routine:4,tl=0x7f63d401f050 next=0x7f63d4023138, timeout=1700000
Jul 28 22:18:40 [21437] DBG:tm:utimer_routine: timer routine:4,tl=0x7f63d4023138 next=0x7f63d40272a8, timeout=1700000
Jul 28 22:18:40 [21437] DBG:tm:utimer_routine: timer routine:4,tl=0x7f63d40272a8 next=0x7f63d402e838, timeout=1700000
Jul 28 22:18:40 [21437] DBG:tm:utimer_routine: timer routine:4,tl=0x7f63d402e838 next=0x7f63d402b398, timeout=1700000
Jul 28 22:18:40 [21437] DBG:tm:utimer_routine: timer routine:4,tl=0x7f63d402b398 next=0x7f63d40335e8, timeout=1700000
Jul 28 22:18:40 [21437] DBG:tm:utimer_routine: timer routine:4,tl=0x7f63d40335e8 next=0x7f63d4037690, timeout=1700000
Jul 28 22:18:40 [21437] DBG:tm:utimer_routine: timer routine:4,tl=0x7f63d4037690 next=0x7f63d403b788, timeout=1700000
Jul 28 22:18:40 [21437] DBG:tm:utimer_routine: timer routine:4,tl=0x7f63d403b788 next=0x7f63d403f870, timeout=1700000
Jul 28 22:18:40 [21437] DBG:tm:utimer_routine: timer routine:4,tl=0x7f63d403f870 next=0x7f63d40439d8, timeout=1700000
Jul 28 22:18:40 [21437] DBG:tm:utimer_routine: timer routine:4,tl=0x7f63d40439d8 next=0x7f63d4047b40, timeout=1700000
Jul 28 22:18:40 [21437] DBG:tm:utimer_routine: timer routine:4,tl=0x7f63d4047b40 next=0x7f63d404bca0, timeout=1700000
Jul 28 22:18:40 [21437] DBG:tm:utimer_routine: timer routine:4,tl=0x7f63d404bca0 next=0x7f63d404fe20, timeout=1700000
Jul 28 22:18:40 [21437] DBG:tm:utimer_routine: timer routine:4,tl=0x7f63d404fe20 next=0x7f63d4053f70, timeout=1700000
Jul 28 22:18:40 [21437] DBG:tm:utimer_routine: timer routine:4,tl=0x7f63d4053f70 next=0x7f63d40573c0, timeout=1700000
Jul 28 22:18:40 [21437] DBG:tm:utimer_routine: timer routine:4,tl=0x7f63d40573c0 next=0x7f63d405c180, timeout=1700000
Jul 28 22:18:40 [21437] DBG:tm:utimer_routine: timer routine:4,tl=0x7f63d405c180 next=0x7f63d4060278, timeout=1700000
Jul 28 22:18:40 [21437] DBG:tm:utimer_routine: timer routine:4,tl=0x7f63d4060278 next=0x7f63d4064310, timeout=1700000
Jul 28 22:18:40 [21437] DBG:tm:utimer_routine: timer routine:4,tl=0x7f63d4064310 next=0x7f63d4068408, timeout=1700000
Jul 28 22:18:40 [21437] DBG:tm:utimer_routine: timer routine:4,tl=0x7f63d4068408 next=0x7f63d406c548, timeout=1700000
Jul 28 22:18:40 [21437] DBG:tm:utimer_routine: timer routine:4,tl=0x7f63d406c548 next=0x7f63d40705e0, timeout=1700000
Jul 28 22:18:40 [21437] DBG:tm:utimer_routine: timer routine:4,tl=0x7f63d40705e0 next=0x7f63d40746d0, timeout=1700000
Jul 28 22:18:40 [21437] DBG:tm:utimer_routine: timer routine:4,tl=0x7f63d40746d0 next=0x7f63d4078770, timeout=1700000
Jul 28 22:18:40 [21437] DBG:tm:retransmission_handler: retransmission_handler : request resending (t=0x7f63d40744b0, INVITE si ... )
Jul 28 22:18:40 [21437] DBG:tm:set_timer: relative timeout is 1000000
Jul 28 22:18:40 [21437] DBG:tm:insert_timer_unsafe: [5]: 0x7f63d40746d0 (2700000)
Jul 28 22:18:40 [21437] DBG:tm:retransmission_handler: retransmission_handler : done
Jul 28 22:18:40 [21437] DBG:tm:utimer_routine: timer routine:4,tl=0x7f63d4078770 next=0x7f63d407c818, timeout=1700000
Jul 28 22:18:40 [21437] DBG:tm:retransmission_handler: retransmission_handler : request resending (t=0x7f63d4078550, INVITE si ... )
Jul 28 22:18:40 [21437] DBG:tm:set_timer: relative timeout is 1000000
Jul 28 22:18:40 [21437] DBG:tm:insert_timer_unsafe: [5]: 0x7f63d4078770 (2700000)
Jul 28 22:18:40 [21437] DBG:tm:retransmission_handler: retransmission_handler : done
Jul 28 22:18:40 [21437] DBG:tm:utimer_routine: timer routine:4,tl=0x7f63d407c818 next=0x7f63d4080908, timeout=1700000
Jul 28 22:18:40 [21437] DBG:tm:retransmission_handler: retransmission_handler : request resending (t=0x7f63d407c5f8, INVITE si ... )
Jul 28 22:18:40 [21437] DBG:tm:set_timer: relative timeout is 1000000
Jul 28 22:18:40 [21437] DBG:tm:insert_timer_unsafe: [5]: 0x7f63d407c818 (2700000)
Jul 28 22:18:40 [21437] DBG:tm:retransmission_handler: retransmission_handler : done
Jul 28 22:18:40 [21437] DBG:tm:utimer_routine: timer routine:4,tl=0x7f63d4080908 next=0x7f63d40849b8, timeout=1700000
Jul 28 22:18:40 [21437] DBG:tm:retransmission_handler: retransmission_handler : request resending (t=0x7f63d40806e8, INVITE si ... )
Jul 28 22:18:40 [21437] DBG:tm:set_timer: relative timeout is 1000000
Jul 28 22:18:40 [21437] DBG:tm:insert_timer_unsafe: [5]: 0x7f63d4080908 (2700000)
Jul 28 22:18:40 [21437] DBG:tm:retransmission_handler: retransmission_handler : done
Jul 28 22:18:40 [21437] DBG:tm:utimer_routine: timer routine:4,tl=0x7f63d40849b8 next=0x7f63d4087be8, timeout=1700000
Jul 28 22:18:40 [21437] DBG:tm:retransmission_handler: retransmission_handler : request resending (t=0x7f63d4084798, INVITE si ... )
Jul 28 22:18:40 [21437] DBG:tm:set_timer: relative timeout is 1000000
Jul 28 22:18:40 [21437] DBG:tm:insert_timer_unsafe: [5]: 0x7f63d40849b8 (2700000)
Jul 28 22:18:40 [21437] DBG:tm:retransmission_handler: retransmission_handler : done
Jul 28 22:18:40 [21437] DBG:tm:utimer_routine: timer routine:4,tl=0x7f63d4087be8 next=(nil), timeout=1700000
Jul 28 22:18:40 [21437] DBG:tm:retransmission_handler: retransmission_handler : request resending (t=0x7f63d40879c8, INVITE si ... )
Jul 28 22:18:40 [21437] DBG:tm:set_timer: relative timeout is 1000000
Jul 28 22:18:40 [21437] DBG:tm:insert_timer_unsafe: [5]: 0x7f63d4087be8 (2700000)
Jul 28 22:18:40 [21437] DBG:tm:retransmission_handler: retransmission_handler : done
[...cycles of retransmits..]
Jul 28 22:19:07 [21437] DBG:tm:set_timer: relative timeout is 4000000
Jul 28 22:19:07 [21437] DBG:tm:insert_timer_unsafe: [7]: 0x7f63d4097d58 (32800000)
Jul 28 22:19:07 [21437] DBG:tm:retransmission_handler: retransmission_handler : done
Jul 28 22:19:09 [21442] DBG:tm:timer_routine: timer routine:0,tl=0x7f63d4074700 next=0x7f63d40787a0, timeout=31
Jul 28 22:19:09 [21442] DBG:tm:final_response_handler: Cancel sent out, sending 408 (0x7f63d40744b0)
Jul 28 22:19:09 [21442] DBG:tm:t_should_relay_response: T_code=100, new_code=408
Jul 28 22:19:09 [21442] DBG:tm:t_pick_branch: picked branch 0, code 408 (prio=800)
Jul 28 22:19:09 [21442] DBG:tm:is_3263_failure: dns-failover test: branch=0, last_recv=408, flags=1
Jul 28 22:19:09 [21442] DBG:tm:t_should_relay_response: trying DNS-based failover
Jul 28 22:19:09 [21442] DBG:core:parse_headers: flags=40
Jul 28 22:19:09 [21442] DBG:rtpproxy:unforce_rtpproxy: sent unforce command
Jul 28 22:19:09 [21442] DBG:tm:relay_reply: T_state=4, branch=0, save=0, relay=0, cancel_BM=0
Jul 28 22:19:09 [21442] DBG:core:parse_headers: flags=ffffffffffffffff
Jul 28 22:19:09 [21442] DBG:tm:set_timer: relative timeout is 500000
Jul 28 22:19:09 [21442] DBG:tm:insert_timer_unsafe: [4]: 0x7f63d40745f8 (32200000)
Jul 28 22:19:09 [21442] DBG:tm:insert_timer_unsafe: [0]: 0x7f63d4074628 (61)
Jul 28 22:19:09 [21442] DBG:tm:relay_reply: sent buf=0x7f63d5cfac98: SIP/2.0 4..., shmem=0x7f63d40776e0: SIP/2.0 4
Jul 28 22:19:09 [21442] DBG:tm:final_response_handler: done
Jul 28 22:19:09 [21442] DBG:tm:timer_routine: timer routine:0,tl=0x7f63d40787a0 next=0x7f63d407c848, timeout=31
Jul 28 22:19:09 [21442] DBG:tm:final_response_handler: Cancel sent out, sending 408 (0x7f63d4078550)

On Fri, Jul 28, 2017 at 2:54 AM, Bogdan-Andrei Iancu <[hidden email]> wrote:
Hi Maxim,,

Is it possible to send me (off list) a pcap (in and out from OpenSIPS) and the log in log_level 4. I will try to investigate to see what is the actual problem.

_______________________________________________
Devel mailing list
[hidden email]
http://lists.opensips.org/cgi-bin/mailman/listinfo/devel
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: Can't get 2.3 running with voiptests properly

Maxim Sobolev
In reply to this post by Maxim Sobolev
Hi Bogdan & Co, I think I've narrowed down failure to a specific revision in the 2.3 branch, see https://travis-ci.org/sippy/voiptests/builds/260009545:

commit 1eb4ec0f78f43f6ff546de49bc72e513876fb86b
Author: Bogdan-Andrei Iancu <[hidden email]>
Date:   Thu Mar 9 15:37:01 2017 +0200

    Added support for dynamic branch manipulation

    New functions were added to allow remote injecting of new branches into an ongoing transaction:
    * t_inject_branches(source, flags) - injects new branches;
    * t_wait_for_new_branches() - instruct transaction to wait more for possible new injections.

Looking at the diff in question, the following piece of code looks suspicious, but it might be something else from that change:

@@ -1244,7 +1301,18 @@ inline static int w_t_relay( struct sip_msg  *p_msg , char *proxy, char *flags)

                update_cloned_msg_from_msg( t->uas.request, p_msg);

-               ret = t_forward_nonack( t, p_msg, p);
+               if (route_type==FAILURE_ROUTE) {
+                       /* If called from failure route we need reset the branch counter to
+                        * ignore the previous set of branches (already terminated) */
+                       ret = t_forward_nonack( t, p_msg, p, 1/*reset*/);
+               } else {
+                       /* if called from request route and the transaction was previously
+                        * created, better lock here to avoid any overlapping with
+                        * branch injection from other processes */
+                       LOCK_REPLIES(t);
+                       ret = t_forward_nonack( t, p_msg, p, 1/*reset*/);
+                       UNLOCK_REPLIES(t);
+               }
                if (ret<=0 ) {
                        LM_ERR("t_forward_nonack failed\n");
                        ret = t_relay_inerr2scripterr();
@@ -1262,7 +1330,8 @@ route_err:

The revisions right before that work, none after does. Hopefully it will give you some clues. Let me know if any other info is needed.

-Max

_______________________________________________
Devel mailing list
[hidden email]
http://lists.opensips.org/cgi-bin/mailman/listinfo/devel
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: Can't get 2.3 running with voiptests properly

Bogdan-Andrei Iancu-2
Thank you Maxim for your troubleshooting.

If you say this code makes a difference in your test, I have the say that the newly added locking may do the "blocking" . To see if this is true, while OpenSIPS is "blocked" could you run several times the "opensipsctl trap" ?

Best 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 08/02/2017 03:59 AM, Maxim Sobolev wrote:
Hi Bogdan & Co, I think I've narrowed down failure to a specific revision in the 2.3 branch, see https://travis-ci.org/sippy/voiptests/builds/260009545:

commit 1eb4ec0f78f43f6ff546de49bc72e513876fb86b
Author: Bogdan-Andrei Iancu <[hidden email]>
Date:   Thu Mar 9 15:37:01 2017 +0200

    Added support for dynamic branch manipulation

    New functions were added to allow remote injecting of new branches into an ongoing transaction:
    * t_inject_branches(source, flags) - injects new branches;
    * t_wait_for_new_branches() - instruct transaction to wait more for possible new injections.

Looking at the diff in question, the following piece of code looks suspicious, but it might be something else from that change:

@@ -1244,7 +1301,18 @@ inline static int w_t_relay( struct sip_msg  *p_msg , char *proxy, char *flags)

                update_cloned_msg_from_msg( t->uas.request, p_msg);

-               ret = t_forward_nonack( t, p_msg, p);
+               if (route_type==FAILURE_ROUTE) {
+                       /* If called from failure route we need reset the branch counter to
+                        * ignore the previous set of branches (already terminated) */
+                       ret = t_forward_nonack( t, p_msg, p, 1/*reset*/);
+               } else {
+                       /* if called from request route and the transaction was previously
+                        * created, better lock here to avoid any overlapping with
+                        * branch injection from other processes */
+                       LOCK_REPLIES(t);
+                       ret = t_forward_nonack( t, p_msg, p, 1/*reset*/);
+                       UNLOCK_REPLIES(t);
+               }
                if (ret<=0 ) {
                        LM_ERR("t_forward_nonack failed\n");
                        ret = t_relay_inerr2scripterr();
@@ -1262,7 +1330,8 @@ route_err:

The revisions right before that work, none after does. Hopefully it will give you some clues. Let me know if any other info is needed.

-Max


_______________________________________________
Devel mailing list
[hidden email]
http://lists.opensips.org/cgi-bin/mailman/listinfo/devel
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: Can't get 2.3 running with voiptests properly

Maxim Sobolev
Bogdan, I've collected some "opensipsctl trap" output here for you, see line 2611 onwards:


This is 10 seconds after starting the test, CANCELs arrive at about 2-3s mark, so it's well into "dead zone". Yet, I see some CANCEL messages in the traces, so it looks like some locking issue indeed.

Please let me know if it helps or if you need any more debug. For the time being, I am successfully running with 2.3 and master by reverting change 1eb4ec0f78f43f6ff546de49bc72e513876fb86b

-Max

On Wed, Aug 2, 2017 at 8:03 AM, Bogdan-Andrei Iancu <[hidden email]> wrote:
Thank you Maxim for your troubleshooting.

If you say this code makes a difference in your test, I have the say that the newly added locking may do the "blocking" . To see if this is true, while OpenSIPS is "blocked" could you run several times the "opensipsctl trap" ?

Best 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 08/02/2017 03:59 AM, Maxim Sobolev wrote:
Hi Bogdan & Co, I think I've narrowed down failure to a specific revision in the 2.3 branch, see https://travis-ci.org/sippy/voiptests/builds/260009545:

commit 1eb4ec0f78f43f6ff546de49bc72e513876fb86b
Author: Bogdan-Andrei Iancu <[hidden email]>
Date:   Thu Mar 9 15:37:01 2017 +0200

    Added support for dynamic branch manipulation

    New functions were added to allow remote injecting of new branches into an ongoing transaction:
    * t_inject_branches(source, flags) - injects new branches;
    * t_wait_for_new_branches() - instruct transaction to wait more for possible new injections.

Looking at the diff in question, the following piece of code looks suspicious, but it might be something else from that change:

@@ -1244,7 +1301,18 @@ inline static int w_t_relay( struct sip_msg  *p_msg , char *proxy, char *flags)

                update_cloned_msg_from_msg( t->uas.request, p_msg);

-               ret = t_forward_nonack( t, p_msg, p);
+               if (route_type==FAILURE_ROUTE) {
+                       /* If called from failure route we need reset the branch counter to
+                        * ignore the previous set of branches (already terminated) */
+                       ret = t_forward_nonack( t, p_msg, p, 1/*reset*/);
+               } else {
+                       /* if called from request route and the transaction was previously
+                        * created, better lock here to avoid any overlapping with
+                        * branch injection from other processes */
+                       LOCK_REPLIES(t);
+                       ret = t_forward_nonack( t, p_msg, p, 1/*reset*/);
+                       UNLOCK_REPLIES(t);
+               }
                if (ret<=0 ) {
                        LM_ERR("t_forward_nonack failed\n");
                        ret = t_relay_inerr2scripterr();
@@ -1262,7 +1330,8 @@ route_err:

The revisions right before that work, none after does. Hopefully it will give you some clues. Let me know if any other info is needed.

-Max




--
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: [hidden email]
Skype: SippySoft

_______________________________________________
Devel mailing list
[hidden email]
http://lists.opensips.org/cgi-bin/mailman/listinfo/devel
Loading...