Opensips tm fails to cancel fr_timer if "100 Trying" is received too soon

[MayamaTakeshi]

I was testing upgrading my OS from CentOS 5.3 to CentOS 6.4. After that, the same opensips.cfg (that uses SIP UDP only) started to fail to cancel the fr_timer when "100 Trying" is received.
The scenario is:
uac --> INVITE --> opensips --> INVITE --> FreeSWITCH
where opensips and FreeSWITCH reside on the same CentOS 6.4 machine.
FS just replies with "100 Trying" and sleep. Then after fr_timer passes, opensips terminates the call with "408 Request Timeout", but it shoudn't.
I know "100 Trying" was processed by opensips because it doesn't retransmit the INVITE to FS.

It seems to me that in CentOS 6.4, the OS handles the packets to opensips more quickly than with CentOS 5.3 and opensips is not ready to handle it.

To confirm this, I added a small delay in the packets doing this:
tc qdisc add dev lo root netem delay 1ms
and after that, opensips correctly canceled the fr_timer after reception of "100 Trying".

I have originally found this issue on branch 1.6, but I tested the latest revision of all branches 1.7, 1.8, 1.9 up to head and all of them shows this issue.
The one that I used for the investigation is this:

svn info

Path: .
URL: http://svn.code.sf.net/p/opensips/svn/trunk
Repository Root: http://svn.code.sf.net/p/opensips/svn
Repository UUID: 689a6050-402a-0410-94f2-e92a70836424
Revision: 10114
Node Kind: directory
Schedule: normal
Last Changed Author: opensipsrelease
Last Changed Rev: 10112
Last Changed Date: 2013-07-12 01:40:29 +0900 (Fri, 12 Jul 2013)

Regards,
Takeshi

[MayamaTakeshi]

I realized svn mirror is not in sync with git repo.

So i checked out latest git commit:

git log |head

commit 707e9ed
Author: Bogdan-Andrei Iancu bogdan@opensips.org
Date: Tue Jul 30 21:37:47 2013 +0300

- support for SCA Broadsoft based on dialog module

Trying again with the above shows the problem persists.

[MayamaTakeshi]

I think I understand what is happening.
It seems processing of the transaction for the initial INVITE (let's call it "process1") has not completed when the "100 Trying" reply comes in and is processed by opensips "process2". This is surprising as i would not expect the INVITE to be relayed before all transaction setup is done.
But this seems to be the case, and process2 messes with the timers (retrans and fr) before process1 is able to set them.

Here are for comparison the logs for Failed and OK cases (I have collected only the logs for processing of INVITE and "100 Trying"):

Failed:
http://pastebin.com/13Z8Va1i

OK:
http://pastebin.com/j2t0AaAx

[MayamaTakeshi]

I located the problem at tm:t_forward_nonack: the INVITE is relayed, and after that, the retrans and fr timers are started. But there is a chance (and this happens all the time if we relay to a fast SIP app running on the same server) that the "100 Trying" is received between these two instants and this messes with the uac processing.
So i changed the code to call start_retr before calling SEND_BUFFER and reset the timers in case of failure. This worked in my tests.

[MayamaTakeshi]

Hello Bogdan,
I understood your explanation about the flaw in the patch. Thanks.

Checking FreeSWITCH, I realized it actually increases its process priority so that it gets more time slices than opensips causing it to respond too soon when they run on the same machine (I tested with a plain ad-hoc sofia SIP app and i don't get the problem with it). So maybe this should not be categorized as a bug as FS is not being fair with the other processes and so it should be solved by properly adjusting process priority in the particular server where opensips and FS live together.

[dsandras]

I experience the same problem. It seems that in some cases the 100 Trying is received so fast that the fr_timer is not reset and is still triggered.

[bogdan-iancu]

The proper fix is available on GIT - please update and test to see if (1) there are no side effects and (2) it fixes the problem.

Thanks,
Bogdan

[MayamaTakeshi]

Bogdan, I tested with latest head and latest 1.9:
there are no side effects and problem is fixed in both.
Thanks a lot.

[bogdan-iancu]

Perfect, thanks for tests, closing the report.