SIP Call receiving CANCEL with Cause 102 and 408 Request Timeout

I've been working on an issue recently that has caused no small amount of consternation so I thought I would put this down so others could be able to resolve this quickly.  The issue is with a SIP trunk to a SIP carrier.  Most calls are working fine but when they make a call and get ring no answer the call disconnects.  here are the relevant SIP messages.




This is the invite from the phone system to the CUBE.  This isn't a CUCM by the way.
213754499: *Mar 18 19:31:47.704: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Received:
INVITE sip:8019831642@10.9.16.50:5060 SIP/2.0
To: "Unknown" <sip:8019831642@10.9.16.50:5060>
From: "Darth Vader" <sip:3854285044@DEN1507C2IC05.caas.local:5060>;tag=OnkOw6A
Via: SIP/2.0/TCP 192.168.227.169:5060;branch=z9hG4bKwm7hh6EsA4qqU6vErgq5
Call-ID: 623309f7de732cc39529454f83956e5e@192.168.227.169
CSeq: 1 INVITE
Contact: <sip:3854285044@192.168.227.169:5060;transport=tcp>
Max-Forwards: 70
x-inin-crn: 1005061199;loc=Phoenix;ms=VCEINI-SP05
Supported: join, replaces
User-Agent: ININ-TsServer/15.3.14.12
Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, PRACK, REFER, SUBSCRIBE, UPDATE
Accept: application/sdp
Accept-Encoding: identity
Content-Type: application/sdp
Content-Length: 205

v=0
o=ININ 1276544019 1276544020 IN IP4 192.168.227.169
s=Interaction
c=IN IP4 10.9.16.120
t=0 0
m=audio 18300 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15

This is the invite from the CUBE to the carrier
213754500: *Mar 18 19:31:47.716: //4966300/E3D0E4C18BDD/SIP/Msg/ccsipDisplayMsg:
Sent:
INVITE sip:8019831642@66.2.243.158:5060 SIP/2.0
Via: SIP/2.0/UDP 216.30.15.250:5060;branch=z9hG4bK73CADE1AB9
Remote-Party-ID: "Darth Vader" <sip:3854285044@216.30.15.250>;party=calling;screen=no;privacy=off
From: "Darth Vader" <sip:3854285044@216.30.15.250>;tag=D79AC644-9A1
To: <sip:8019831642@66.2.243.158>
Date: Fri, 18 Mar 2016 19:31:47 GMT
Call-ID: E3D21D11-EC7611E5-8BE39BA1-DF32B6B3@216.30.15.250
Supported: timer,resource-priority,replaces,sdp-anat
Min-SE:  1200
Cisco-Guid: 3822118081-3967160805-2346556321-3744642739
User-Agent: Cisco-SIPGateway/IOS-15.4.3.M3
Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY, INFO, REGISTER
CSeq: 101 INVITE
Timestamp: 1458329507
Contact: <sip:3854285044@216.30.15.250:5060>
Expires: 180
Allow-Events: telephone-event
Max-Forwards: 69
Content-Type: application/sdp
Content-Disposition: session;handling=required
Content-Length: 250

v=0
o=CiscoSystemsSIP-GW-UserAgent 4822 8156 IN IP4 216.30.15.250
s=SIP Call
c=IN IP4 216.30.15.250
t=0 0
m=audio 30064 RTP/AVP 0 101
c=IN IP4 216.30.15.250
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20

213754501: *Mar 18 19:31:47.716: //4966299/E3D0E4C18BDD/SIP/Msg/ccsipDisplayMsg:
Sent:
SIP/2.0 100 Trying
Via: SIP/2.0/TCP 192.168.227.169:5060;branch=z9hG4bKwm7hh6EsA4qqU6vErgq5
From: "Darth Vader" <sip:3854285044@DEN1507C2IC05.caas.local:5060>;tag=OnkOw6A
To: "Unknown" <sip:8019831642@10.9.16.50:5060>
Date: Fri, 18 Mar 2016 19:31:47 GMT
Call-ID: 623309f7de732cc39529454f83956e5e@192.168.227.169
CSeq: 1 INVITE
Allow-Events: telephone-event
Server: Cisco-SIPGateway/IOS-15.4.3.M3
Content-Length: 0

213754502: *Mar 18 19:31:47.736: //4966300/E3D0E4C18BDD/SIP/Msg/ccsipDisplayMsg:
Received:
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 216.30.15.250:5060;branch=z9hG4bK73CADE1AB9
From: "Darth Vader" <sip:3854285044@216.30.15.250>;tag=D79AC644-9A1
To: <sip:8019831642@66.2.243.158>;tag=gK0ea67955
Call-ID: E3D21D11-EC7611E5-8BE39BA1-DF32B6B3@216.30.15.250
CSeq: 101 INVITE
Timestamp: 1458329507
Content-Length: 0

213754532: *Mar 18 19:31:48.084: //4966300/E3D0E4C18BDD/SIP/Msg/ccsipDisplayMsg:
Received:
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP 216.30.15.250:5060;branch=z9hG4bK73CADE1AB9
From: "Darth Vader" <sip:3854285044@216.30.15.250>;tag=D79AC644-9A1
To: <sip:8019831642@66.2.243.158>;tag=gK0ea67955
Call-ID: E3D21D11-EC7611E5-8BE39BA1-DF32B6B3@216.30.15.250
CSeq: 101 INVITE
Contact: <sip:8019831642@66.2.243.158:5060>
Allow: INVITE,ACK,CANCEL,BYE,REGISTER,REFER,INFO,SUBSCRIBE,NOTIFY,PRACK,UPDATE,OPTIONS,MESSAGE,PUBLISH
Content-Length: 0

213754533: *Mar 18 19:31:48.088: //4966299/E3D0E4C18BDD/SIP/Msg/ccsipDisplayMsg:
Sent:
SIP/2.0 180 Ringing
Via: SIP/2.0/TCP 192.168.227.169:5060;branch=z9hG4bKwm7hh6EsA4qqU6vErgq5
From: "Darth Vader" <sip:3854285044@DEN1507C2IC05.caas.local:5060>;tag=OnkOw6A
To: "Unknown" <sip:8019831642@10.9.16.50:5060>;tag=D79AC7B4-1D83
Date: Fri, 18 Mar 2016 19:31:47 GMT
Call-ID: 623309f7de732cc39529454f83956e5e@192.168.227.169
CSeq: 1 INVITE
Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY, INFO, REGISTER
Allow-Events: telephone-event
Remote-Party-ID: <sip:8019831642@10.9.16.50>;party=called;screen=no;privacy=off
Contact: <sip:8019831642@10.9.16.50:5060;transport=tcp>
Server: Cisco-SIPGateway/IOS-15.4.3.M3
Content-Length: 0

Everything is fine up to this part.  Nothing indicating a problem.  Then the CUBE sends the CANCEL to the carrier
213754802: *Mar 18 19:32:02.712: //4966300/E3D0E4C18BDD/SIP/Msg/ccsipDisplayMsg:
Sent:
CANCEL sip:8019831642@66.2.243.158:5060 SIP/2.0
Via: SIP/2.0/UDP 216.30.15.250:5060;branch=z9hG4bK73CADE1AB9
From: "Darth Vader" <sip:3854285044@216.30.15.250>;tag=D79AC644-9A1
To: <sip:8019831642@66.2.243.158>
Date: Fri, 18 Mar 2016 19:31:47 GMT
Call-ID: E3D21D11-EC7611E5-8BE39BA1-DF32B6B3@216.30.15.250
CSeq: 101 CANCEL
Max-Forwards: 70
Timestamp: 1458329522
Reason: Q.850;cause=102      < -- notice the cause 102 here
Content-Length: 0


213754803: *Mar 18 19:32:02.712: //4966299/E3D0E4C18BDD/SIP/Msg/ccsipDisplayMsg:
Sent:
SIP/2.0 408 Request Timeout   < -- and the Request Timeout here
Via: SIP/2.0/TCP 192.168.227.169:5060;branch=z9hG4bKwm7hh6EsA4qqU6vErgq5
From: "Darth Vader" <sip:3854285044@DEN1507C2IC05.caas.local:5060>;tag=OnkOw6A
To: "Unknown" <sip:8019831642@10.9.16.50:5060>;tag=D79AC7B4-1D83
Date: Fri, 18 Mar 2016 19:31:47 GMT
Call-ID: 623309f7de732cc39529454f83956e5e@192.168.227.169
CSeq: 1 INVITE
Allow-Events: telephone-event
Server: Cisco-SIPGateway/IOS-15.4.3.M3
Reason: Q.850;cause=102
Content-Length: 0

Also notice the time.  it is exactly 15 seconds after the first invite

213754804: *Mar 18 19:32:02.728: //4966300/E3D0E4C18BDD/SIP/Msg/ccsipDisplayMsg:
Received:
SIP/2.0 200 OK
Via: SIP/2.0/UDP 216.30.15.250:5060;branch=z9hG4bK73CADE1AB9
From: "Darth Vader" <sip:3854285044@216.30.15.250>;tag=D79AC644-9A1
To: <sip:8019831642@66.2.243.158>;tag=gK0ea67955
Call-ID: E3D21D11-EC7611E5-8BE39BA1-DF32B6B3@216.30.15.250
CSeq: 101 CANCEL
Content-Length: 0

213754805: *Mar 18 19:32:02.732: //4966300/E3D0E4C18BDD/SIP/Msg/ccsipDisplayMsg:
Received:
SIP/2.0 487 Request Terminated
Via: SIP/2.0/UDP 216.30.15.250:5060;branch=z9hG4bK73CADE1AB9
From: "Darth Vader" <sip:3854285044@216.30.15.250>;tag=D79AC644-9A1
To: <sip:8019831642@66.2.243.158>;tag=gK0ea67955
Call-ID: E3D21D11-EC7611E5-8BE39BA1-DF32B6B3@216.30.15.250
CSeq: 101 INVITE
Content-Length: 0


So after a lot of searching and trying different things I finally realized this configuration
ip rtcp report interval 3000
!
gateway
 media-inactivity-criteria all
 timer receive-rtcp 5
 timer receive-rte 1200

Here is what I found for these commands

timer receive-rtcp
The SIP Media Inactivity Timer feature enables Cisco gateways to monitor and disconnect Voice-over-IP (VoIP) calls if no Real-Time Control Protocol (RTCP) packets are received within a configurable time period. When RTCP reports are not received by a Cisco gateway, the SIP Media Inactivity Timer feature releases the hung session and its network resources in an orderly manner. These network resources include the gateway digital signal processor (DSP) and time-division multiplexing (TDM) channel resources that are utilized by the hung sessions. Because call signaling is sent to tear down the call, any stateful SIP proxies involved in the call are also notified to clear the state that they have associated with the hung session. The call is also cleared back through the TDM port so that any attached TDM switching equipment also clears its resources.

The SIP Media Inactivity Timer feature requires the configuration of the ip rtcp report interval command and the timer receive-rtcp command to enable detection of RTCP packets by the gateway. When these commands are configured, the gateway uses RTCP report detection, rather than Real-Time Protocol (RTP) packet detection, to determine whether calls on the gateway are still active or should be disconnected. This method is more reliable because there are periods during voice calls when one or both parties are not sending RTP packets.

So the call was going out and ringing and since there are no RTCP packets going through while ringing this timer was exhausting before voicemail could pickup.  I changed the ip rtcp report interval to 6000 making it 30 seconds before the timer would exhaust.  All calls started to work fine after that. 
 

Hope that helps some other people.  Feel free to comment below and please check out my Youtube channel below as well.

https://www.youtube.com/channel/UCa2exyciw-M0BugrzCivodg