[FS-6688] Notify message record-route tag Created: 24/Jul/14  Updated: 14/Nov/18  Resolved: 09/Apr/15

Status: Closed
Project: FreeSWITCH
Component/s: mod_sofia
Affects Version/s: 1.4.6
Fix Version/s: 1.4.18

Type: Bug Priority: Minor
Reporter: Ira Tessler Assignee: Mike Jerris
Resolution: Fixed Votes: 1
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment: Debian 7

Attachments: File bad blf no route tag     Text File bad request no route tag capture.txt     File blf.pcap     Text File freeswitch.log     Text File freeswitch.log     Text File output.txt     Text File trace.txt     Text File trace_from_fs.txt     File trace_from_phone.pcap    
Issue Links:
Related
is related to FS-6998 No fs_path stored for in-dialog SUBSC... Closed
CPU Architecture:
x86-64
Kernel:
Linux
uname: Linux fssbctest1 3.2.0-4-amd64 #1 SMP Debian 3.2.60-1+deb7u1 x86_64 GNU/Linux
Userland:
GNU/Linux
Distribution:
Debian
Distribution Version:
Debian 7 wheezy
Compiler:
gcc
FreeSWITCH GIT Revision: 1.4.6
GIT Master Revision hash:: 1.4.6
Target Version:

 Description   
I am filing this issue as per William King. FS Notify messages are missing record-route tags after the second Subscribe message and also sometimes when sending a <state>early</state>. Attached are two traces. One from the Freeswitch side one from the phone side. Freeswitch is beside a Sansay SBC which is generating the error message:

U 2014/07/24 15:13:31.876092 10.10.10.103:5060 -> 10.10.100.3:5060
SIP/2.0 481 bad request, no route tag.
Via: SIP/2.0/UDP 10.10.100.3;rport=5060;branch=z9hG4bK8Kar4je8c9mrQ.
To: "706" <sip:706@22555.udp.ha1.testsbcdax.com:5060>;tag=a69a7a1c41.
From: <sip:702@22555.udp.ha1.testsbcdax.com:5060>;tag=5g9PGFFyMzcq.
Call-ID: 3aa39717d11098f2.
CSeq: 1768041002 NOTIFY.
Content-Length: 0.


 Comments   
Comment by Ira Tessler [ 15/Aug/14 ]
Updated packet capture requested by William King
Comment by Mike Jerris [ 04/Dec/14 ]
this fix breaks issue originally fixed in 4129adc9ac94003d5c24cfedb993c5831a9ec9a7 to handle when remote contact actually changes, a totally valid case. we need to handle this differently. We need to be able to update the contact, but not the route.
Comment by Ira Tessler [ 06/Jan/15 ]
This issue is broken again in 1.4.15. Attached are traces from the initial subscribe to the re-subscribe.
Comment by Ira Tessler [ 06/Jan/15 ]
Same trace just one in text format the other in pcap format. Look at the last packet which is an error, no route tag.
Comment by Mike Jerris [ 06/Jan/15 ]
can you point to where in this trace things actually go wrong?
Comment by Mike Jerris [ 06/Jan/15 ]
what i see from the trace at line 1675, we continue to send the NOTIFY to the location in the original RecordRoute as we are supposed to, but after the resubscribe, the other end stops replying to our NOTIFY. This is for dialog with Call-ID: f3b6f64e878b1e97

What am I missing here?
Comment by Ira Tessler [ 06/Jan/15 ]
Yes. Look at the very last packet. It says error "bad request, no route tag" from my SBC. Once this happens, BLF stops working totally until I reboot all my phones.

recv 317 bytes from udp/[10.10.10.103]:5060 at 09:37:44.206453:
   ------------------------------------------------------------------------
   SIP/2.0 481 bad request, no route tag
   Via: SIP/2.0/UDP 10.10.100.3;rport=5060;branch=z9hG4bKUQr1j83BgHKtS
   To: "705" <sip:705@22555.udp.ha1.testsbcdax.com:5060>;tag=08dd3db11a
   From: <sip:702@22555.udp.ha1.testsbcdax.com:5060>;tag=6XYKO96u2KNV
   Call-ID: bee4780816d66973
   CSeq: 23333201 NOTIFY
   Content-Length: 0
Comment by Ira Tessler [ 06/Jan/15 ]
I think the NOTIFY is missing the record-route tag. Talk to Brian West and/or William King. They have been working with me on this issue for almost a year.
Comment by Mike Jerris [ 06/Jan/15 ]
Yes, I know, I've been the one actually implementing the changes. Can you get me the entry from the sip subscriptions table after the first and second subscribe?
Comment by Ira Tessler [ 06/Jan/15 ]
Sure, no problem. I'll post that data in a little while.
Comment by Ira Tessler [ 06/Jan/15 ]
Attached is the before and after from sip_subscriptions.
Comment by Ira Tessler [ 06/Jan/15 ]
sip_subscriptions subscribe and re-subscribe.
Comment by Anthony Minessale II [ 06/Jan/15 ]
Please confirm you are willing to work on this issue until its resolved.
You opened this bug in August and gave no feedback at all until today.
If you agree to remain responsive we can investigate it for you.
Comment by Ira Tessler [ 06/Jan/15 ]
Sure. We need to get this fixed as soon as we can. This issue was fixed in 1.4.14 and broke again in 1.4.15 which was just release a few weeks ago.

Thanks.
Comment by Mike Jerris [ 06/Jan/15 ]
are you by chance able to git bisect to find the commit that broke this?
Comment by Mike Jerris [ 06/Jan/15 ]
I only see 1 record in sip subscriptions. I need to see the one when its initially working, and the one after it stops working.
Comment by Ira Tessler [ 06/Jan/15 ]
The first one is where is initially worked. After the re-subscribe, FS deletes the row out of sip_subscriptions.
Comment by Ira Tessler [ 06/Jan/15 ]
I can work on the bisect
Comment by Ira Tessler [ 06/Jan/15 ]
Here is the result of the bisect:

<240>:git bisect bad
5376e82669d2f53d8acd06f49a27949bfbb21fcd is the first bad commit
commit 5376e82669d2f53d8acd06f49a27949bfbb21fcd
Author: Michael Jerris <mike@jerris.com>
Date: Thu Dec 4 12:34:05 2014 -0500

    FS-6688: don't update the contact when the original had fs_path, the new one doesnt, and the contact didn't change. This will fix the normal case of record route from a proxy without breaking normal changing of a contact

:040000 040000 6421d2feba00da5b53404da029bc2af79d68ae63 160cd6e27e7256266398303c80f4233dc55277d3 M src

Comment by Ira Tessler [ 07/Jan/15 ]
I did a git pull and tested you change. It still does not work. I am attaching a trace. Look at the end of the file. You will see the same error.

-------------------------------
recv 334 bytes from udp/[10.10.10.103]:5060 at 18:40:24.266689:
   ------------------------------------------------------------------------
   SIP/2.0 481 bad request, no route tag
   Via: SIP/2.0/UDP 10.10.100.3;rport=5060;branch=z9hG4bKQ7QmKDrcH5UUN
   To: "701" <sip:701@22555.udp.ha1.testsbcdax.com:5060>;tag=94a1edecad
   From: <sip:702@22555.udp.ha1.testsbcdax.com:5060>;tag=6XYKO96u2KNV;tag=6XYKO96u2KNV
   Call-ID: dfaea630479840b4
   CSeq: 29281201 NOTIFY
   Content-Length: 0
   
Comment by Mike Jerris [ 08/Jan/15 ]
you tested the branch or master?
Comment by Ira Tessler [ 08/Jan/15 ]
master
Comment by Ira Tessler [ 05/Feb/15 ]
Latest log file from master.
Comment by Ira Tessler [ 06/Feb/15 ]
Updated trace.
Comment by Ira Tessler [ 04/Mar/15 ]
Our architecture is as follows:
A SBC and FS are on the same LAN with no router in between. There is
no NAT between the SBC and FS. The SBC has two LAN cards. One on the
private LAN with FS and one on the public Internet. The SBC handles the
proxying between the Internet and the private LAN.

I commented out the follow line on the sip profile:
<!--<param name="apply-nat-acl" value="nat.auto"/>—>

FS now registers the phones without the fs_path and includes the record-route tag on the resubscribe NOTIFY message.
Comment by Ira Tessler [ 06/Mar/15 ]
After more testing with the apply-nat-acl option commented out, it seems now the FS won't send NOTIFY messages after a RE-SUBSCRIBE. So going back to the original issue, the RECORD-ROUTE tag issue still needs to be corrected.
Comment by Ira Tessler [ 09/Apr/15 ]
Worked correctly now on 1.4.18 with <param name="apply-nat-acl" value="nat.auto"/> removed from the sofia profile.
Generated at Thu Apr 25 02:58:03 CDT 2019 using JIRA 7.3.3#73014-sha1:d5be8da522213be2ca9ad7b043c51da6e4cc9754.