SIP re-invite issue with session timers

22 Jul 2011

      While testing some outbound T.38 fax calls, they were getting quickly
disconnected, and I found that I was running into problems related to
the session timer during the re-invite process.  I was wondering if
anyone else has run into anything similar?  I'm not sure if it's just
T.38 related, or would have occurred on any re-invite scenario.

In the trace below, I think my gateway (Flowroute) reacts a little
strangely since it appears to refuse a session timer that it itself
chose during the initial invite process (instead seeming to want to
flip who handles the refresh), but while odd, that's not necessarily
invalid, is it?  I also noticed that FreeSWITCH promoted the timer to
a requirement during the re-invite.  But the eventual call disconnect
seems due to FreeSWITCH never completing renegotiation - the last
thing it transmits is a 100 response.

Disabling session timers (enable-timer=false) in the profile gets
around the problem, but it seems like keeping the timers, if possible,
is preferable in terms of an additional safety net.

Any thoughts or suggestions would be welcome.  Does this appear
strictly a gateway side issue, or is something also not working
properly on the FreeSWITCH side?

-- David

Note: git-b1d1beb is the same as f1de377 from 7/16 plus one local
      change to mod_conference.  The dialed number has been replaced
      by 11111111111, my public switch address with 111.111.111.111,
      and I've excluded the Proxy-Authorization header throughout.

The initial call setup seems ok:

          - - - - - - - - - - - - - - - - - - - - - - - - -

send 1390 bytes to udp/[216.115.69.144]:5060 at 21:29:19.155730:
   ------------------------------------------------------------------------
   INVITE sip:11111111111@sip.flowroute.com SIP/2.0
   Via: SIP/2.0/UDP 111.111.111.111:5080;rport;branch=z9hG4bKK8mr3pcre4a2j
   Max-Forwards: 70
   From: "" <sip:XXXX@sip.flowroute.com;transport=udp>;tag=KcKN11gj6arQS
   To: <sip:11111111111@sip.flowroute.com>
   Call-ID: 7fe743c9-2f4c-122f-9790-f23c91931894
   CSeq: 15349016 INVITE
   Contact: <sip:gw+flowroute@111.111.111.111:5080;transport=udp;gw=flowroute>
   Expires: 600
   User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-b1d1beb 2011-07-18 23-08-16 -0400
   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY
   Supported: timer, precondition, path, replaces
   Allow-Events: talk, hold, refer
   Content-Type: application/sdp
   Content-Disposition: session
   Content-Length: 213
   X-FS-Support: update_display
   Remote-Party-ID: <sip:0000000000@sip.flowroute.com>;party=calling;screen=yes;privacy=off

   v=0
   o=FreeSWITCH 1311342219 1311342220 IN IP4 111.111.111.111
   s=FreeSWITCH
   c=IN IP4 111.111.111.111
   t=0 0
   m=audio 27940 RTP/AVP 9 0 8 3 101 13
   a=rtpmap:101 telephone-event/8000
   a=fmtp:101 0-16
   a=ptime:20
   ------------------------------------------------------------------------
recv 305 bytes from udp/[216.115.69.144]:5060 at 21:29:19.194573:
   ------------------------------------------------------------------------
   SIP/2.0 100 Trying
   Via: SIP/2.0/UDP 111.111.111.111:5080;rport=5080;branch=z9hG4bKK8mr3pcre4a2j
   From: "" <sip:XXXX@sip.flowroute.com;transport=udp>;tag=KcKN11gj6arQS
   To: <sip:11111111111@sip.flowroute.com>
   Call-ID: 7fe743c9-2f4c-122f-9790-f23c91931894
   CSeq: 15349016 INVITE
   Content-Length: 0

   ------------------------------------------------------------------------
recv 687 bytes from udp/[216.115.69.144]:5060 at 21:29:19.839258:
   ------------------------------------------------------------------------
   SIP/2.0 180 Ringing
   From: "" <sip:XXXX@sip.flowroute.com;transport=udp>;tag=KcKN11gj6arQS
   To: <sip:11111111111@sip.flowroute.com>;tag=SDvtmh399-gK0a9c4821
   Via: SIP/2.0/UDP 111.111.111.111:5080;rport=5080;branch=z9hG4bKK8mr3pcre4a2j
   Call-ID: 7fe743c9-2f4c-122f-9790-f23c91931894
   CSeq: 15349016 INVITE
   Record-Route: <sip:216.115.69.133;lr>
   Record-Route: <sip:216.115.69.144;lr>
   Contact: <sip:+11111111111@67.16.125.60:5060;transport=udp>
   Content-Length: 184
   Content-Type: application/sdp

   v=0
   o=- 3829 19246 IN IP4 67.16.125.60
   s=-
   c=IN IP4 67.16.125.60
   t=0 0
   m=audio 50330 RTP/AVP 0 101
   a=rtpmap:101 telephone-event/8000
   a=fmtp:101 0-15
   a=ptime:20
   a=maxptime:20
   ------------------------------------------------------------------------
recv 850 bytes from udp/[216.115.69.144]:5060 at 21:29:21.587130:
   ------------------------------------------------------------------------
   SIP/2.0 200 OK
   From: "" <sip:XXXX@sip.flowroute.com;transport=udp>;tag=KcKN11gj6arQS
   To: <sip:11111111111@sip.flowroute.com>;tag=SDvtmh399-gK0a9c4821
   Via: SIP/2.0/UDP 111.111.111.111:5080;rport=5080;branch=z9hG4bKK8mr3pcre4a2j
   Call-ID: 7fe743c9-2f4c-122f-9790-f23c91931894
   CSeq: 15349016 INVITE
   Record-Route: <sip:216.115.69.133;lr>
   Record-Route: <sip:216.115.69.144;lr>
   Accept: application/sdp, application/isup, application/dtmf, application/dtmf-relay,  multipart/mixed
   Contact: <sip:+11111111111@67.16.125.60:5060;transport=udp>
   Supported: timer,replaces
   Session-Expires: 10800;refresher=uas
   Content-Length: 184
   Content-Type: application/sdp

   v=0
   o=- 3829 19246 IN IP4 67.16.125.60
   s=-
   c=IN IP4 67.16.125.60
   t=0 0
   m=audio 50330 RTP/AVP 0 101
   a=rtpmap:101 telephone-event/8000
   a=fmtp:101 0-15
   a=ptime:20
   a=maxptime:20
   ------------------------------------------------------------------------
send 826 bytes to udp/[216.115.69.144]:5060 at 21:29:21.587678:
   ------------------------------------------------------------------------
   ACK sip:+11111111111@67.16.125.60:5060;transport=udp SIP/2.0
   Via: SIP/2.0/UDP 111.111.111.111:5080;rport;branch=z9hG4bKmHeH5HXUBD1me
   Route: <sip:216.115.69.144;lr>
   Route: <sip:216.115.69.133;lr>
   Max-Forwards: 70
   From: "" <sip:XXXX@sip.flowroute.com;transport=udp>;tag=KcKN11gj6arQS
   To: <sip:11111111111@sip.flowroute.com>;tag=SDvtmh399-gK0a9c4821
   Call-ID: 7fe743c9-2f4c-122f-9790-f23c91931894
   CSeq: 15349016 ACK
   Contact: <sip:gw+flowroute@111.111.111.111:5080;transport=udp;gw=flowroute>
   Content-Length: 0

   ------------------------------------------------------------------------

          - - - - - - - - - - - - - - - - - - - - - - - - -

The gateway appears to have specified a uas-refreshed session timer in
its 200 message.  Below, the re-invite happens for T.38.  Here I noticed
the new Require: timer option (with the session-expires from before),
which is rejected, then oddly the gateway re-invites but apparently
with a uac-refreshed timer.  FreeSWITCH then sends a 100, and nothing else.

          - - - - - - - - - - - - - - - - - - - - - - - - -

send 1638 bytes to udp/[216.115.69.144]:5060 at 21:29:22.108341:
   ------------------------------------------------------------------------
   INVITE sip:+11111111111@67.16.125.60:5060;transport=udp SIP/2.0
   Via: SIP/2.0/UDP 111.111.111.111:5080;rport;branch=z9hG4bKNt796ceZ8NQ7S
   Route: <sip:216.115.69.144;lr>
   Route: <sip:216.115.69.133;lr>
   Max-Forwards: 70
   From: "" <sip:XXXX@sip.flowroute.com;transport=udp>;tag=KcKN11gj6arQS
   To: <sip:11111111111@sip.flowroute.com>;tag=SDvtmh399-gK0a9c4821
   Call-ID: 7fe743c9-2f4c-122f-9790-f23c91931894
   CSeq: 15349017 INVITE
   Contact: <sip:gw+flowroute@111.111.111.111:5080;transport=udp;gw=flowroute>
   User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-b1d1beb 2011-07-18 23-08-16 -0400
   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY
   Require: timer
   Supported: timer, precondition, path, replaces
   Session-Expires: 10800;refresher=uas
   Min-SE: 120
   Content-Type: application/sdp
   Content-Disposition: session
   Content-Length: 322
   X-FS-Support: update_display
   Remote-Party-ID: <sip:0000000000@sip.flowroute.com>;party=calling;screen=yes;privacy=off

   v=0
   o=FreeSWITCH 1311342219 1311342221 IN IP4 111.111.111.111
   s=FreeSWITCH
   c=IN IP4 111.111.111.111
   t=0 0
   m=image 27940 udptl t38
   a=T38FaxVersion:0
   a=T38MaxBitRate:14400
   a=T38FaxFillBitRemoval
   a=T38FaxRateManagement:transferredTCF
   a=T38FaxMaxBuffer:2000
   a=T38FaxMaxDatagram:400
   a=T38FaxUdpEC:t38UDPRedundancy
   ------------------------------------------------------------------------
recv 330 bytes from udp/[216.115.69.144]:5060 at 21:29:22.147343:
   ------------------------------------------------------------------------
   SIP/2.0 100 Trying
   Via: SIP/2.0/UDP 111.111.111.111:5080;rport=5080;branch=z9hG4bKNt796ceZ8NQ7S
   From: "" <sip:XXXX@sip.flowroute.com;transport=udp>;tag=KcKN11gj6arQS
   To: <sip:11111111111@sip.flowroute.com>;tag=SDvtmh399-gK0a9c4821
   Call-ID: 7fe743c9-2f4c-122f-9790-f23c91931894
   CSeq: 15349017 INVITE
   Content-Length: 0

   ------------------------------------------------------------------------
recv 338 bytes from udp/[216.115.69.144]:5060 at 21:29:22.170802:
   ------------------------------------------------------------------------
   SIP/2.0 420 Bad Extension
   From: "" <sip:XXXX@sip.flowroute.com;transport=udp>;tag=KcKN11gj6arQS
   To: <sip:11111111111@sip.flowroute.com>;tag=SDvtmh399-gK0a9c4821
   Via: SIP/2.0/UDP 111.111.111.111:5080;rport=5080;branch=z9hG4bKNt796ceZ8NQ7S
   Call-ID: 7fe743c9-2f4c-122f-9790-f23c91931894
   CSeq: 15349017 INVITE
   Unsupported: timer

   ------------------------------------------------------------------------
send 446 bytes to udp/[216.115.69.144]:5060 at 21:29:22.171034:
   ------------------------------------------------------------------------
   ACK sip:+11111111111@67.16.125.60:5060;transport=udp SIP/2.0
   Via: SIP/2.0/UDP 111.111.111.111:5080;rport;branch=z9hG4bKNt796ceZ8NQ7S
   Route: <sip:216.115.69.144;lr>
   Route: <sip:216.115.69.133;lr>
   Max-Forwards: 70
   From: "" <sip:XXXX@sip.flowroute.com;transport=udp>;tag=KcKN11gj6arQS
   To: <sip:11111111111@sip.flowroute.com>;tag=SDvtmh399-gK0a9c4821
   Call-ID: 7fe743c9-2f4c-122f-9790-f23c91931894
   CSeq: 15349017 ACK
   Content-Length: 0

   ------------------------------------------------------------------------
recv 1160 bytes from udp/[216.115.69.144]:5060 at 21:29:26.533911:
   ------------------------------------------------------------------------
   INVITE sip:gw+flowroute@111.111.111.111:5080;transport=udp;gw=flowroute SIP/2.0
   Record-Route: <sip:216.115.69.144;lr>
   Record-Route: <sip:216.115.69.133;lr>
   From: <sip:11111111111@sip.flowroute.com>;tag=SDvtmh399-gK0a9c4821;tag=SDvtmh399-gK0a9c4821
   To: "" <sip:XXXX@sip.flowroute.com;transport=udp>;tag=KcKN11gj6arQS
   Via: SIP/2.0/UDP 216.115.69.144;branch=z9hG4bK1dbe.2add7494aaa097ffa4b75892aba82f61.0
   Via: SIP/2.0/UDP 216.115.69.133;branch=z9hG4bK1dbe.bbcd1cf6f99ecd7a297b5dc33dd676dd.0
   Via: SIP/2.0/UDP 67.16.125.60:5060;branch=z9hG4bKmthalp308g505g83r340sb0000hc3.1
   Call-ID: 7fe743c9-2f4c-122f-9790-f23c91931894
   CSeq: 4313 INVITE
   Max-Forwards: 67
   Accept: application/sdp, application/isup, application/dtmf, application/dtmf-relay,  multipart/mixed
   Contact: <sip:+11111111111@67.16.125.60:5060;transport=udp>
   Supported: timer,replaces
   Session-Expires: 10800;refresher=uac
   Min-SE: 90
   Content-Length: 172
   Content-Type: application/sdp

   v=0
   o=- 3829 19247 IN IP4 67.16.125.60
   s=-
   c=IN IP4 67.16.125.60
   t=0 0
   m=image 50330 udptl t38
   a=T38FaxRateManagement:transferredTCF
   a=T38FaxUdpEC:t38UDPRedundancy
   ------------------------------------------------------------------------
send 688 bytes to udp/[216.115.69.144]:5060 at 21:29:26.534587:
   ------------------------------------------------------------------------
   SIP/2.0 100 Trying
   Via: SIP/2.0/UDP 216.115.69.144;branch=z9hG4bK1dbe.2add7494aaa097ffa4b75892aba82f61.0
   Via: SIP/2.0/UDP 216.115.69.133;branch=z9hG4bK1dbe.bbcd1cf6f99ecd7a297b5dc33dd676dd.0
   Via: SIP/2.0/UDP 67.16.125.60:5060;branch=z9hG4bKmthalp308g505g83r340sb0000hc3.1
   Record-Route: <sip:216.115.69.144;lr>
   Record-Route: <sip:216.115.69.133;lr>
   From: <sip:11111111111@sip.flowroute.com>;tag=SDvtmh399-gK0a9c4821;tag=SDvtmh399-gK0a9c4821
   To: "" <sip:XXXX@sip.flowroute.com;transport=udp>;tag=KcKN11gj6arQS
   Call-ID: 7fe743c9-2f4c-122f-9790-f23c91931894
   CSeq: 4313 INVITE
   User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-b1d1beb 2011-07-18 23-08-16 -0400
   Content-Length: 0

   ------------------------------------------------------------------------

             - - - - - - - - - - - - - - - - - - - - - - - - -

At this point the fax actually proceeds for a few seconds, but I get a BYE
after about 10 seconds:

             - - - - - - - - - - - - - - - - - - - - - - - - -

recv 708 bytes from udp/[216.115.69.144]:5060 at 21:29:36.285179:
   ------------------------------------------------------------------------
   BYE sip:gw+flowroute@111.111.111.111:5080;transport=udp;gw=flowroute SIP/2.0
   Record-Route: <sip:216.115.69.144;lr>
   Record-Route: <sip:216.115.69.133;lr>
   From: <sip:11111111111@sip.flowroute.com>;tag=SDvtmh399-gK0a9c4821;tag=SDvtmh399-gK0a9c4821
   To: "" <sip:XXXX@sip.flowroute.com;transport=udp>;tag=KcKN11gj6arQS
   Via: SIP/2.0/UDP 216.115.69.144;branch=z9hG4bKecbe.d96adce16997b042396d38106987a638.0
   Via: SIP/2.0/UDP 216.115.69.133;branch=z9hG4bKecbe.75fcc1a3bc1f3a68e4c0241e8b6b0298.0
   Via: SIP/2.0/UDP 67.16.125.60:5060;branch=z9hG4bKmthalp308g505g83r340sd00001d3.1
   Call-ID: 7fe743c9-2f4c-122f-9790-f23c91931894
   CSeq: 4314 BYE
   Max-Forwards: 67
   Content-Length: 0

   ------------------------------------------------------------------------
             - - - - - - - - - - - - - - - - - - - - - - - - -

David Bolen

tags

participants (1)