PSTN hang up call flow issue

Kevin Murphy <[email protected]> Tue, 29 Mar 2005 13:13:53 -0500

Newsgroups	gmane.comp.lib.vovida.vocal
Message-ID	<[email protected]>

Greetings,
  I'm running vovida 1.4 on a redhat 7.3 machine and have noticed problems
with a call flow in which the PSTN side hangs up before a 200 message. 
The Cancel
is getting rejected because the Via's don't match. Has anyone 
experienced this before?
A search of the mailing list yeilds nothing. Thanks in advance. Attached 
is the call trace with debug output.
-Kevin

_______________________________________________
vocal mailing list
[email protected]
To unsubscribe, please go to http://www.vovida.org/mailman/listinfo/vocal

calltrace.txt (text/plain, 16.6 KB)

20050329-123554.769 [09226] DBUG bcSip: SipTransceiver.cxx:421 timeout value exceeded
20050329-123555.780 [09226] DBUG bcSip: SipTransceiver.cxx:421 timeout value exceeded
20050329-123556.789 [09226] DBUG bcSip: SipTransceiver.cxx:421 timeout value exceeded
20050329-123557.799 [09226] DBUG bcSip: SipTransceiver.cxx:421 timeout value exceeded
20050329-123558.663 [09226] DBUG bcSip: SipTransceiver.cxx:483 Received: INVITE [D89DE64D-9FAF11D9-B22ECFDD-C3C66BB7@<pstn gateway ip>]
20050329-123558.664 [09226] DBUG bcSip: SipAgent.cxx:110 updateSipCounter 9
20050329-123558.664 [09226] DBUG bcSip: SipAgent.cxx:117 new value = 7630
20050329-123558.664 [09226] DBUG bcSip: SipAgent.cxx:110 updateSipCounter 14
20050329-123558.664 [09226] DBUG bcSip: SipAgent.cxx:117 new value = 2156
20050329-123558.664 [08201] DBUG bcWorker: Operator.hxx:113 Operator: MrshlOpInvite
20050329-123558.665 [08201] DBUG bcWorker: MrshlOpInvite.cxx:105 SIP message received:
INVITE sip:4439121005@<marshal server ip>:5067;user=phone SIP/2.0
Via: SIP/2.0/UDP <pstn gateway ip>:5060
To: <sip:4439121005@<marshal server ip>;user=phone>
From: "unknown"<sip:<pstn gateway ip>>;tag=17017A94-209C
Date: Tue, 29 Mar 2005 17:35:58 GMT
Call-ID: D89DE64D-9FAF11D9-B22ECFDD-C3C66BB7@<pstn gatway ip>
CSeq: 101 INVITE
Max-Forwards: 6
Expires: 60
Contact: <sip:<pstn gatway ip>:5060>
Supported: timer,100rel
Timestamp: 1112117758
User-Agent: Cisco-SIPGateway/IOS-12.x
Min-SE: 1800
Content-Type: application/sdp
Content-Length: 357
Cisco-Guid: 3634186789-2679050713-2989215709-3284560823
Allow-Events: telephone-event

v=0
o=CiscoSystemsSIP-GW-UserAgent 717 3170 IN IP4 <pstn gateway ip>
s=SIP Call
c=IN IP4 <pstn gateway ip>
t=0 0
m=audio 23636 RTP/AVP 0 18 3 8 100 101
a=rtpmap:0 PCMU/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=yes
a=rtpmap:3 GSM/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:100 X-NSE/8000
a=fmtp:100 192-194
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
,
20050329-123558.665 [08201] INFO bcWorker: Marshal.cxx:942 Original Max-Forwards: Max-Forwards: 6

20050329-123558.665 [08201] INFO bcWorker: Marshal.cxx:962 New Max-Forwards: Max-Forwards: 5

20050329-123558.665 [08201] DBUG bcWorker: Marshal.cxx:558 incoming packet IP check successful
20050329-123558.665 [08201] DBUG bcWorker: Marshal.cxx:1010 Incoming, add proxy authorization key
20050329-123558.665 [08201] DBUG bcWorker: MrshlOpInvite.cxx:133 Setting user transport
20050329-123558.665 [08201] DBUG bcWorker: MrshlUserCache.cxx:313 *** Update user transport <user:> <Transport:UDP>
20050329-123558.665 [08201] DBUG bcWorker: VException.cxx:70 Exception at MrshlUserCache.cxx:329 *** User not found in myUserCache ***
20050329-123558.665 [08201] DBUG bcWorker: MrshlOpInvite.cxx:147 Failed to get user data for (), reason VMissingDataException: *** User not found in myUserCache ***
20050329-123558.666 [08201] DBUG bcWorker: SipUdp_impl.cxx:434 got port from Via of 5060
20050329-123558.666 [02051] DBUG Mrshl: SipUdp_impl.cxx:194 Network Address host=<pstn gatway ip>:5060
20050329-123558.667 [08201] DBUG bcWorker: RoundRobinServers.cxx:335 <rs server ip>:6666 is down.  Rehashing to active server
20050329-123558.667 [08201] ERR  bcWorker: RoundRobinServers.cxx:341 No known active servers, default to first server
20050329-123558.667 [08201] DBUG bcWorker: RoundRobinServers.cxx:228 Hash sip:<pstn gateway ip> into server: <rs2 server ip>:6666
20050329-123558.668 [08201] DBUG bcWorker: SipSentRequestDB.cxx:102 Setting transport
20050329-123558.668 [08201] DBUG bcWorker: SipAgent.cxx:110 updateSipCounter 10
20050329-123558.668 [08201] DBUG bcWorker: SipAgent.cxx:117 new value = 10259
20050329-123558.668 [08201] DBUG bcWorker: SipAgent.cxx:110 updateSipCounter 15
20050329-123558.668 [08201] DBUG bcWorker: SipAgent.cxx:117 new value = 4066
20050329-123558.668 [08201] DBUG bcWorker: SipUdp_impl.cxx:457 got host from start line: <rs2 server ip>:6666
20050329-123558.670 [02051] DBUG Mrshl: SipUdp_impl.cxx:194 Network Address host=<rs2 server ip>:6666
20050329-123558.691 [09226] DBUG bcSip: SipTransceiver.cxx:483 Received: STATUS (302) [D89DE64D-9FAF11D9-B22ECFDD-C3C66BB7@<pstn gateway ip>]
20050329-123558.692 [09226] DBUG bcSip: SipAgent.cxx:110 updateSipCounter 11
20050329-123558.692 [09226] DBUG bcSip: SipAgent.cxx:117 new value = 11033
20050329-123558.692 [09226] DBUG bcSip: SipAgent.cxx:110 updateSipCounter 44
20050329-123558.692 [09226] DBUG bcSip: SipAgent.cxx:117 new value = 1911
20050329-123558.692 [08201] DBUG bcWorker: Operator.hxx:113 Operator: MrshlOpStatus
20050329-123558.693 [08201] DBUG bcWorker: MrshlOpStatus.cxx:119 SIP message received:
SIP/2.0 302 Moved Temporarily.
Via: SIP/2.0/UDP <marshal server ip>:5067;rport=6666;received=<rs2 server ip>;branch=z9hG4bK29f80b23798c783ac5ef14325aa4ed71.1
Via: SIP/2.0/UDP <pstn gateway ip>:5060
To: <sip:4439121005@<marshal server ip>;user=phone>
From: "unknown"<sip:<pstn gateway ip>>;tag=17017A94-209C
Call-ID: D89DE64D-9FAF11D9-B22ECFDD-C3C66BB7@<pstn gateway ip>
CSeq: 101 INVITE
Contact: <sip:4439121005@<marshal server ip>:5059;user=phone>
Content-Length: 0

,
20050329-123558.693 [08201] DBUG bcWorker: MrshlOpStatus.cxx:175 Received 302
20050329-123558.693 [08201] DBUG bcWorker: MrshlOpStatus.cxx:392 ACK 302 response for INVITE
20050329-123558.693 [08201] DBUG bcWorker: SipEvent.cxx:184 Search transaction for previous command
20050329-123558.693 [08201] DBUG bcWorker: SipEvent.cxx:203 Found command:
20050329-123558.693 [08201] DBUG bcWorker: SipEvent.cxx:204 INVITE sip:4439121005@<rs2 server ip>:6666;user=phone SIP/2.0
Via: SIP/2.0/UDP <marshal server ip>:5067;branch=z9hG4bK29f80b23798c783ac5ef14325aa4ed71.1
Via: SIP/2.0/UDP <pstn gateway ip>:5060
To: <sip:4439121005@<marshal server ip>;user=phone>
From: "unknown"<sip:<pstn gateway ip>>;tag=17017A94-209C
Date: Tue, 29 Mar 2005 17:35:58 GMT
Call-ID: D89DE64D-9FAF11D9-B22ECFDD-C3C66BB7@<pstn gateway ip>
CSeq: 101 INVITE
Proxy-Authorization: XXXXXXX
Max-Forwards: 5
Expires: 60
Record-Route: <sip:4439121005@<marshal server ip>:5067;maddr=<marshal server ip>>
Contact: <sip:<pstn gateway ip>:5060>
Supported: timer,100rel
Timestamp: 1112117758
User-Agent: Cisco-SIPGateway/IOS-12.x
Min-SE: 1800
Content-Type: application/sdp
Content-Length: 357
Cisco-Guid: 3634186789-2679050713-2989215709-3284560823
Allow-Events: telephone-event

v=0
o=CiscoSystemsSIP-GW-UserAgent 717 3170 IN IP4 <pstn gateway ip>
s=SIP Call
c=IN IP4 <pstn gateway ip>
t=0 0
m=audio 23636 RTP/AVP 0 18 3 8 100 101
a=rtpmap:0 PCMU/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=yes
a=rtpmap:3 GSM/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:100 X-NSE/8000
a=fmtp:100 192-194
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16

20050329-123558.697 [08201] DBUG bcWorker: SipSentRequestDB.cxx:102 Setting transport
20050329-123558.698 [08201] DBUG bcWorker: SipAgent.cxx:110 updateSipCounter 10
20050329-123558.698 [08201] DBUG bcWorker: SipAgent.cxx:117 new value = 10260
20050329-123558.698 [08201] DBUG bcWorker: SipAgent.cxx:110 updateSipCounter 17
20050329-123558.698 [08201] DBUG bcWorker: SipAgent.cxx:117 new value = 4014
20050329-123558.698 [08201] DBUG bcWorker: SipUdp_impl.cxx:457 got host from start line: <rs2 server ip>:6666
20050329-123558.699 [08201] DBUG bcWorker: SipEvent.cxx:184 Search transaction for previous command
20050329-123558.699 [08201] DBUG bcWorker: SipEvent.cxx:203 Found command:
20050329-123558.699 [02051] DBUG Mrshl: SipUdp_impl.cxx:194 Network Address host=<rs2 server ip>:6666
20050329-123558.700 [08201] DBUG bcWorker: SipEvent.cxx:204 INVITE sip:4439121005@<rs2 server ip>:6666;user=phone SIP/2.0
Via: SIP/2.0/UDP <marshal server ip>:5067;branch=z9hG4bK29f80b23798c783ac5ef14325aa4ed71.1
Via: SIP/2.0/UDP <pstn gateway ip>:5060
To: <sip:4439121005@<marshal server ip>;user=phone>
From: "unknown"<sip:<pstn gateway ip>>;tag=17017A94-209C
Date: Tue, 29 Mar 2005 17:35:58 GMT
Call-ID: D89DE64D-9FAF11D9-B22ECFDD-C3C66BB7@<pstn gateway ip>
CSeq: 101 INVITE
Proxy-Authorization: XXXXXX
Max-Forwards: 5
Expires: 60
Record-Route: <sip:4439121005@<marshal server ip>:5067;maddr=<marshal server ip>>
Contact: <sip:<pstn gateway ip>:5060>
Supported: timer,100rel
Timestamp: 1112117758
User-Agent: Cisco-SIPGateway/IOS-12.x
Min-SE: 1800
Content-Type: application/sdp
Content-Length: 357
Cisco-Guid: 3634186789-2679050713-2989215709-3284560823
Allow-Events: telephone-event

v=0
o=CiscoSystemsSIP-GW-UserAgent 717 3170 IN IP4 <pstn gateway ip>
s=SIP Call
c=IN IP4 <pstn gateway ip>
t=0 0
m=audio 23636 RTP/AVP 0 18 3 8 100 101
a=rtpmap:0 PCMU/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=yes
a=rtpmap:3 GSM/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:100 X-NSE/8000
a=fmtp:100 192-194
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16

20050329-123558.701 [08201] DBUG bcWorker: MrshlOpStatus.cxx:440 incoming, set branch to incoming contact
20050329-123558.701 [08201] DBUG bcWorker: MrshlOpStatus.cxx:642 Return first Contact in list
20050329-123558.702 [08201] DBUG bcWorker: MrshlOpStatus.cxx:570 send Invite to Contact ...
INVITE sip:4439121005@<marshal server ip>:5059;user=phone SIP/2.0
Via: SIP/2.0/UDP <marshal server ip>:5067;branch=z9hG4bKf27f7d113d98acb486200cfb57213ad2.2
Via: SIP/2.0/UDP <pstn gateway ip>:5060
To: <sip:4439121005@<marshal server ip>;user=phone>
From: "unknown"<sip:<pstn gateway ip>>;tag=17017A94-209C
Date: Tue, 29 Mar 2005 17:35:58 GMT
Call-ID: D89DE64D-9FAF11D9-B22ECFDD-C3C66BB7@<pstn gateway ip>
CSeq: 101 INVITE
Proxy-Authorization: XXXXXXXXX
Max-Forwards: 5
Expires: 60
Record-Route: <sip:4439121005@<marshal server ip>:5067;maddr=<marshal server ip>>
Contact: <sip:<pstn gateway ip>:5060>
Supported: timer,100rel
Timestamp: 1112117758
User-Agent: Cisco-SIPGateway/IOS-12.x
Min-SE: 1800
Content-Type: application/sdp
Content-Length: 357
Cisco-Guid: 3634186789-2679050713-2989215709-3284560823
Allow-Events: telephone-event

v=0
o=CiscoSystemsSIP-GW-UserAgent 717 3170 IN IP4 <pstn gateway ip>
s=SIP Call
c=IN IP4 <pstn gateway ip>
t=0 0
m=audio 23636 RTP/AVP 0 18 3 8 100 101
a=rtpmap:0 PCMU/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=yes
a=rtpmap:3 GSM/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:100 X-NSE/8000
a=fmtp:100 192-194
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16

20050329-123558.703 [08201] DBUG bcWorker: SipSentRequestDB.cxx:102 Setting transport
20050329-123558.703 [08201] DBUG bcWorker: SipAgent.cxx:110 updateSipCounter 10
20050329-123558.703 [08201] DBUG bcWorker: SipAgent.cxx:117 new value = 10261
20050329-123558.703 [08201] DBUG bcWorker: SipAgent.cxx:110 updateSipCounter 15
20050329-123558.703 [08201] DBUG bcWorker: SipAgent.cxx:117 new value = 4067
20050329-123558.703 [08201] DBUG bcWorker: SipUdp_impl.cxx:457 got host from start line: <marshal server ip>:5059
20050329-123558.704 [02051] DBUG Mrshl: SipUdp_impl.cxx:194 Network Address host=<marshal server ip>:5059
20050329-123558.715 [09226] DBUG bcSip: SipTransceiver.cxx:483 Received: STATUS (100) [D89DE64D-9FAF11D9-B22ECFDD-C3C66BB7@<pstn gateway ip>]
20050329-123558.716 [09226] DBUG bcSip: SipAgent.cxx:110 updateSipCounter 11
20050329-123558.716 [09226] DBUG bcSip: SipAgent.cxx:117 new value = 11034
20050329-123558.716 [09226] DBUG bcSip: SipAgent.cxx:110 updateSipCounter 28
20050329-123558.716 [09226] DBUG bcSip: SipAgent.cxx:117 new value = 2111
20050329-123558.716 [08201] DBUG bcWorker: Operator.hxx:113 Operator: MrshlOpStatus
20050329-123558.717 [08201] DBUG bcWorker: MrshlOpStatus.cxx:119 SIP message received:
SIP/2.0 100 Trying
Via: SIP/2.0/UDP <marshal server ip>:5067;branch=z9hG4bKf27f7d113d98acb486200cfb57213ad2.2
Via: SIP/2.0/UDP <pstn gateway ip>:5060
To: <sip:4439121005@<marshal server ip>;user=phone>
From: "unknown"<sip:<pstn gateway ip>>;tag=17017A94-209C
Call-ID: D89DE64D-9FAF11D9-B22ECFDD-C3C66BB7@<pstn gateway ip>
CSeq: 101 INVITE
Content-Length: 0

,
20050329-123558.717 [08201] DBUG bcWorker: MrshlOpStatus.cxx:128 Received 100, no processing required
20050329-123559.202 [09226] DBUG bcSip: SipTransceiver.cxx:483 Received: STATUS (180) [D89DE64D-9FAF11D9-B22ECFDD-C3C66BB7@<pstn gateway ip>]
20050329-123559.203 [09226] DBUG bcSip: SipAgent.cxx:110 updateSipCounter 11
20050329-123559.203 [09226] DBUG bcSip: SipAgent.cxx:117 new value = 11035
20050329-123559.203 [09226] DBUG bcSip: SipAgent.cxx:110 updateSipCounter 30
20050329-123559.203 [09226] DBUG bcSip: SipAgent.cxx:117 new value = 84
20050329-123559.204 [08201] DBUG bcWorker: Operator.hxx:113 Operator: MrshlOpStatus
20050329-123559.204 [08201] DBUG bcWorker: MrshlOpStatus.cxx:119 SIP message received:
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP <marshal server ip>:5067;branch=z9hG4bKf27f7d113d98acb486200cfb57213ad2.2
Via: SIP/2.0/UDP <pstn gateway ip>:5060
To: <sip:4439121005@<marshal server ip>;user=phone>;tag=as65bbce47
From: "unknown"<sip:<pstn gateway ip>>;tag=17017A94-209C
Call-ID: D89DE64D-9FAF11D9-B22ECFDD-C3C66BB7@<pstn gateway ip>
CSeq: 101 INVITE
Contact: <sip:4439121005@<pbx server ip>>
Allow: INVITE,ACK,CANCEL,OPTIONS,BYE,REFER
User-Agent: Asterisk PBX
Content-Length: 0

,
20050329-123559.204 [08201] DBUG bcWorker: MrshlOpStatus.cxx:155 Received 180/183, bill for ringtime
20050329-123559.204 [08201] DBUG bcWorker: MrshlOpStatus.cxx:252 Start billing ring From: , To: 4439121005, CallId: D89DE64D-9FAF11D9-B22ECFDD-C3C66BB7@<pstn gateway ip>
20050329-123559.204 [08201] DBUG bcWorker: CdrInterface.cxx:302 Call Ringing, call ID:D89DE64D-9FAF11D9-B22ECFDD-C3C66BB7@<pstn gateway ip>
20050329-123559.204 [08201] DBUG bcWorker: MrshlOpStatus.cxx:308 forward based on Via
20050329-123559.205 [08201] DBUG bcWorker: MrshlOpStatus.cxx:199 Forward status
20050329-123559.205 [08201] DBUG bcWorker: SipUdp_impl.cxx:434 got port from Via of 5060
20050329-123559.218 [02051] DBUG Mrshl: SipUdp_impl.cxx:194 Network Address host=<pstn gateway ip>:5060
20050329-123600.208 [09226] DBUG bcSip: SipTransceiver.cxx:421 timeout value exceeded
20050329-123601.219 [09226] DBUG bcSip: SipTransceiver.cxx:421 timeout value exceeded
20050329-123602.229 [09226] DBUG bcSip: SipTransceiver.cxx:421 timeout value exceeded
20050329-123603.228 [09226] DBUG bcSip: SipTransceiver.cxx:483 Received: CANCEL [D89DE64D-9FAF11D9-B22ECFDD-C3C66BB7@<pstn gateway ip>]
20050329-123603.229 [09226] DBUG bcSip: SipAgent.cxx:110 updateSipCounter 9
20050329-123603.229 [09226] DBUG bcSip: SipAgent.cxx:117 new value = 7631
20050329-123603.229 [09226] DBUG bcSip: SipAgent.cxx:110 updateSipCounter 20
20050329-123603.229 [09226] DBUG bcSip: SipAgent.cxx:117 new value = 82
20050329-123603.229 [08201] DBUG bcWorker: Operator.hxx:113 Operator: MrshlOpCancel
20050329-123603.230 [08201] DBUG bcWorker: MrshlOpCancel.cxx:107 SIP message received:
CANCEL sip:4439121005@<marshal server ip>:5067;user=phone SIP/2.0
Via: SIP/2.0/UDP <pstn gateway ip>:5060
To: <sip:4439121005@<marshal server ip>;user=phone>
From: "unknown"<sip:<pstn gateway ip>>;tag=17017A94-209C
Date: Tue, 29 Mar 2005 17:35:58 GMT
Call-ID: D89DE64D-9FAF11D9-B22ECFDD-C3C66BB7@<pstn gateway ip>
CSeq: 101 CANCEL
Max-Forwards: 6
Timestamp: 1112117763
Content-Length: 0

,
20050329-123603.230 [08201] INFO bcWorker: Marshal.cxx:942 Original Max-Forwards: Max-Forwards: 6

20050329-123603.230 [08201] INFO bcWorker: Marshal.cxx:962 New Max-Forwards: Max-Forwards: 5

20050329-123603.230 [08201] DBUG bcWorker: Marshal.cxx:558 incoming packet IP check successful
20050329-123603.230 [08201] DBUG bcWorker: Marshal.cxx:1010 Incoming, add proxy authorization key
20050329-123603.237 [08201] INFO bcWorker: SipEvent.cxx:229 Check each matching command
20050329-123603.237 [08201] INFO bcWorker: SipEvent.cxx:234 Check this command
20050329-123603.237 [08201] DBUG bcWorker: SipEvent.cxx:258 found command, but Via's don't match
20050329-123603.237 [08201] INFO bcWorker: SipEvent.cxx:234 Check this command
20050329-123603.237 [08201] INFO bcWorker: SipEvent.cxx:234 Check this command
20050329-123603.238 [08201] DBUG bcWorker: SipEvent.cxx:258 found command, but Via's don't match
20050329-123603.238 [08201] INFO bcWorker: SipEvent.cxx:234 Check this command
20050329-123603.238 [08201] ERR  bcWorker: SipEvent.cxx:243 This command is not a SIP command
20050329-123603.238 [08201] ERR  bcWorker: SipEvent.cxx:266 no matching command
20050329-123603.239 [08201] ERR  bcWorker: Marshal.cxx:1174 no matching request for cancel, return 481
20050329-123603.242 [08201] DBUG bcWorker: SipUdp_impl.cxx:434 got port from Via of 5060
20050329-123603.244 [02051] DBUG Mrshl: SipUdp_impl.cxx:194 Network Address host=<pstn gateway>:5060
20050329-123604.238 [09226] DBUG bcSip: SipTransceiver.cxx:421 timeout value exceeded
20050329-123605.249 [09226] DBUG bcSip: SipTransceiver.cxx:421 timeout value exceeded
20050329-123606.259 [09226] DBUG bcSip: SipTransceiver.cxx:421 timeout value exceeded
20050329-123607.270 [09226] DBUG bcSip: SipTransceiver.cxx:421 timeout value exceeded
20050329-123608.279 [09226] DBUG bcSip: SipTransceiver.cxx:421 timeout value exceeded
20050329-123609.289 [09226] DBUG bcSip: SipTransceiver.cxx:421 timeout value exceeded