Data added by client:


It shows the attempt to call 34882@fwd.pulver.com from my IP phone attached to our proxy sip.bts.sk.
Our proxy is not doing record-routing, the FWD's proxy is doing it.
The CANCEL is sent to the wrong IP address 192.246.69.223 - should go to our  proxy 194.160.23.16 where the INVITE was sent. As a result, the 487 response is repeated until request timeout.


Cisco Systems, Inc. Copyright 2000-2002
Cisco IP phone  MAC: 000b:46e9:b760
Loadid:  SW: P0S3-04-4-00  ARM: PAS3ARM1  Boot: PC030301  DSP: PS03AS30
SIP Phone> debug sip-messages
Enabling bug logging on this terminal - use 'tty mon 0' to disable
debugs: sip-messages
SIP Phone> sip_sm_cc_channel_send_buf_fcn: Sent SIP message: handle=<4>:
message=
<INVITE sip:34882@fwd.pulver.com SIP/2.0
Via: SIP/2.0/UDP 147.175.0.10:5060
From: "Marian Durkovic" <sip:md@bts.sk>;tag=000b46e9b7600015495fde0b-218875d2
To: <sip:34882@fwd.pulver.com>
Call-ID: 000b46e9-b76000f7-296f2879-6f951c60@147.175.0.10
Date: Tue, 16 Sep 2003 08:01:23 GMT
CSeq: 101 INVITE
User-Agent: CSCO/4
Contact: <sip:md@147.175.0.10:5060>
Expires: 180
Content-Type: application/sdp
Content-Length: 245
Accept: application/sdp

v=0
o=Cisco-SIPUA 7544 8401 IN IP4 147.175.0.10
s=SIP Call
c=IN IP4 147.175.0.10
t=0 0
m=audio 29338 RTP/AVP 8 0 18 101
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:18 G729/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
, length=<697>
SIPProcessUDPMessage: recv UDP message from <194.160.23.16>:<50195>:
<SIP/2.0 100 trying -- your call is important to us
Via: SIP/2.0/UDP 147.175.0.10:5060
From: "Marian Durkovic" <sip:md@bts.sk>;tag=000b46e9b7600015495fde0b-218875d2
To: <sip:34882@fwd.pulver.com>
Call-ID: 000b46e9-b76000f7-296f2879-6f951c60@147.175.0.10
CSeq: 101 INVITE
Server: Sip EXpress router (0.8.11pre29 (i386/freebsd))
Content-Length: 0
Warning: 392 194.160.23.16:5060 "Noisy feedback tells:  pid=83990
req_src_ip=147.175.0.10 req_src_port=50280 in_uri=sip:34882@fwd.pulver.com
out_uri=sip:34882@fwd.pulver.com via_cnt==1"

, length=541
sipSPICheckResponse: Response match:
callid=000b46e9-b76000f7-296f2879-6f951c60@147.175.0.10, cseq=101,
cseq_method=INVITE
SIPProcessUDPMessage: recv UDP message from <194.160.23.16>:<50195>:
<SIP/2.0 180 Ringing
Via: SIP/2.0/UDP 147.175.0.10:5060
From: "Marian Durkovic" <sip:md@bts.sk>;tag=000b46e9b7600015495fde0b-218875d2
To: <sip:34882@fwd.pulver.com>;tag=000b46e9b7600015495fde0b-218875d2
Contact: <sip:34882@194.160.23.17:5060>
Record-Route: <sip:34882@192.246.69.223;ftag=000b46e9b7600015495fde0b-218875d2;lr=on>
Call-ID: 000b46e9-b76000f7-296f2879-6f951c60@147.175.0.10
CSeq: 101 INVITE
User-Agent: X-PRO build 1077
Content-Length: 0

, length=462
sipSPICheckResponse: Response match:
callid=000b46e9-b76000f7-296f2879-6f951c60@147.175.0.10, cseq=101,
cseq_method=INVITE
sip_sm_cc_channel_send_buf_fcn: Opened a one-time UDP send channel to server
<192.246.69.223>:<5060>, handle = 3
sip_sm_cc_channel_send_buf_fcn:Sent SIP message to <192.246.69.223>:<5060>,

handle=<3>:
message=
<CANCEL sip:34882@fwd.pulver.com SIP/2.0
Via: SIP/2.0/UDP 147.175.0.10:5060
From: "Marian Durkovic" <sip:md@bts.sk>;tag=000b46e9b7600015495fde0b-218875d2
To: <sip:34882@fwd.pulver.com>
Call-ID: 000b46e9-b76000f7-296f2879-6f951c60@147.175.0.10
Date: Tue, 16 Sep 2003 08:01:30 GMT
CSeq: 101 CANCEL
User-Agent: CSCO/4
Content-Length: 0

, length=<343>
sip_sm_cc_channel_send_buf_fcn: Closed a one-time UDP send channel handle =
3
SIPProcessUDPMessage: recv UDP message from <194.160.23.16>:<50195>:
<SIP/2.0 487 Request Terminated
Via: SIP/2.0/UDP 147.175.0.10:5060
From: "Marian Durkovic" <sip:md@bts.sk>;tag=000b46e9b7600015495fde0b-218875d2
To: <sip:34882@fwd.pulver.com>;tag=000b46e9b7600015495fde0b-218875d2
Contact: <sip:34882@194.160.23.17:5060>
Record-Route: <sip:34882@192.246.69.223;ftag=000b46e9b7600015495fde0b-218875d2;lr=on>
Call-ID: 000b46e9-b76000f7-296f2879-6f951c60@147.175.0.10
CSeq: 101 INVITE
User-Agent: X-PRO build 1077
Content-Length: 0

, length=473
sipSPICheckResponse: Response mismatch:
(Response:callid=000b46e9-b76000f7-296f2879-6f951c60@147.175.0.10, cseq=101,
cseq_method=INVITE),
(Request: callid=000b46e9-b76000f7-296f2879-6f951c60@147.175.0.10, cseq=101,
cseq_method=CANCEL)
sip_sm_cc_channel_send_buf_fcn: Opened a one-time UDP send channel to server
<192.246.69.223>:<5060>, handle = 3
sip_sm_cc_channel_send_buf_fcn:Sent SIP message to <192.246.69.223>:<5060>,
handle=<3>:
message=
<ACK sip:34882@fwd.pulver.com SIP/2.0
Via: SIP/2.0/UDP 147.175.0.10:5060
From: "Marian Durkovic" <sip:md@bts.sk>;tag=000b46e9b7600015495fde0b-218875d2
To: <sip:34882@fwd.pulver.com>;tag=000b46e9b7600015495fde0b-218875d2
Call-ID: 000b46e9-b76000f7-296f2879-6f951c60@147.175.0.10
Date: Tue, 16 Sep 2003 08:01:30 GMT
CSeq: 101 ACK
Content-Length: 0

, length=<355>
sip_sm_cc_channel_send_buf_fcn: Closed a one-time UDP send channel handle = 3
sipRelDevCoupledMessageStore: Storing for reTx (cseq=101, method=INVITE, to_tag=
<000b46e9b7600015495fde0b-218875d2>)
sip_sm_cc_channel_send_buf_fcn: Opened a one-time UDP send channel to server <147.175.0.10>:<5060>, handle = 3
sip_sm_cc_channel_send_buf_fcn:Sent SIP message to <147.175.0.10>:<5060>, handle=<3>:
message=
<SIP/2.0 400 Bad Request
Via: SIP/2.0/UDP 147.175.0.10:5060
From: "Marian Durkovic" <sip:md@bts.sk>;tag=000b46e9b7600015495fde0b-218875d2
To: <sip:34882@fwd.pulver.com>;tag=000b46e9b7600015495fde0b-218875d2
Call-ID: 000b46e9-b76000f7-296f2879-6f951c60@147.175.0.10
Date: Tue, 16 Sep 2003 08:01:30 GMT
Warning: 399 Bad Request - 'Content length Error'
CSeq: 101 INVITE
Content-Length: 0

, length=<396>
sip_sm_cc_channel_send_buf_fcn: Closed a one-time UDP send channel handle = 3
SIPProcessUDPMessage: recv UDP message from <194.160.23.16>:<50195>:
<SIP/2.0 200 Ok
Via: SIP/2.0/UDP 147.175.0.10:5060
From: "Marian Durkovic" <sip:md@bts.sk>;tag=000b46e9b7600015495fde0b-218875d2
To: <sip:34882@fwd.pulver.com>;tag=000b46e9b7600015495fde0b-218875d2
Contact: <sip:34882@194.160.23.17:5060>
Record-Route: <sip:34882@192.246.69.223;ftag=000b46e9b7600015495fde0b-218875d2;lr=on>
Call-ID: 000b46e9-b76000f7-296f2879-6f951c60@147.175.0.10
CSeq: 101 CANCEL
User-Agent: X-PRO build 1077
Content-Length: 0

, length=457
sipSPICheckResponse: Response match: callid=000b46e9-b76000f7-296f2879-6f951c60@147.175.0.10, cseq=101, cseq_method=CANCEL
SIPProcessUDPMessage: recv UDP message from <194.160.23.16>:<50195>:
<SIP/2.0 487 Request Terminated
Via: SIP/2.0/UDP 147.175.0.10:5060
From: "Marian Durkovic" <sip:md@bts.sk>;tag=000b46e9b7600015495fde0b-218875d2
To: <sip:34882@fwd.pulver.com>;tag=000b46e9b7600015495fde0b-218875d2
Contact: <sip:34882@194.160.23.17:5060>
Record-Route: <sip:34882@192.246.69.223;ftag=000b46e9b7600015495fde0b-218875d2;lr=on>
Call-ID: 000b46e9-b76000f7-296f2879-6f951c60@147.175.0.10
CSeq: 101 INVITE
User-Agent: X-PRO build 1077
Content-Length: 0

, length=473
sipRelDevCoupledMessageStore: Storing for reTx (cseq=101, method=INVITE, to_tag=<000b46e9b7600015495fde0b-218875d2>)
sip_sm_cc_channel_send_buf_fcn: Opened a one-time UDP send channel to server <192.246.69.223>:<5060>, handle = 3
sip_sm_cc_channel_send_buf_fcn:Sent SIP message to <192.246.69.223>:<5060>, handle=<3>:
message=
<ACK sip:34882@fwd.pulver.com SIP/2.0
Via: SIP/2.0/UDP 147.175.0.10:5060
From: "Marian Durkovic" <sip:md@bts.sk>;tag=000b46e9b7600015495fde0b-218875d2
To: <sip:34882@fwd.pulver.com>;tag=000b46e9b7600015495fde0b-218875d2
Call-ID: 000b46e9-b76000f7-296f2879-6f951c60@147.175.0.10
Date: Tue, 16 Sep 2003 08:01:31 GMT
CSeq: 101 ACK
Content-Length: 0

, length=<355>
sip_sm_cc_channel_send_buf_fcn: Closed a one-time UDP send channel handle = 3
SIPProcessUDPMessage: recv UDP message from <194.160.23.16>:<50195>:
<SIP/2.0 487 Request Terminated
Via: SIP/2.0/UDP 147.175.0.10:5060
From: "Marian Durkovic" <sip:md@bts.sk>;tag=000b46e9b7600015495fde0b-218875d2
To: <sip:34882@fwd.pulver.com>;tag=000b46e9b7600015495fde0b-218875d2
Contact: <sip:34882@194.160.23.17:5060>
Record-Route: <sip:34882@192.246.69.223;ftag=000b46e9b7600015495fde0b-218875d2;lr=on>
Call-ID: 000b46e9-b76000f7-296f2879-6f951c60@147.175.0.10
CSeq: 101 INVITE
User-Agent: X-PRO build 1077
Content-Length: 0

, length=473
sipRelDevCoupledMessageStore: Storing for reTx (cseq=101, method=INVITE, to_tag=<000b46e9b7600015495fde0b-218875d2>)
sip_sm_cc_channel_send_buf_fcn: Opened a one-time UDP send channel to server <192.246.69.223>:<5060>, handle = 3
sip_sm_cc_channel_send_buf_fcn:Sent SIP message to <192.246.69.223>:<5060>, handle=<3>:
message=
<ACK sip:34882@fwd.pulver.com SIP/2.0
Via: SIP/2.0/UDP 147.175.0.10:5060
From: "Marian Durkovic" <sip:md@bts.sk>;tag=000b46e9b7600015495fde0b-218875d2
To: <sip:34882@fwd.pulver.com>;tag=000b46e9b7600015495fde0b-218875d2
Call-ID: 000b46e9-b76000f7-296f2879-6f951c60@147.175.0.10
Date: Tue, 16 Sep 2003 08:01:33 GMT
CSeq: 101 ACK
Content-Length: 0

, length=<355>
sip_sm_cc_channel_send_buf_fcn: Closed a one-time UDP send channel handle = 3
SIPProcessUDPMessage: recv UDP message from <194.160.23.16>:<50195>:
<SIP/2.0 487 Request Terminated
Via: SIP/2.0/UDP 147.175.0.10:5060
From: "Marian Durkovic" <sip:md@bts.sk>;tag=000b46e9b7600015495fde0b-218875d2
To: <sip:34882@fwd.pulver.com>;tag=000b46e9b7600015495fde0b-218875d2
Contact: <sip:34882@194.160.23.17:5060>
Record-Route: <sip:34882@192.246.69.223;ftag=000b46e9b7600015495fde0b-218875d2;lr=on>
Call-ID: 000b46e9-b76000f7-296f2879-6f951c60@147.175.0.10
CSeq: 101 INVITE
User-Agent: X-PRO build 1077
Content-Length: 0

, length=473
sipRelDevCoupledMessageStore: Storing for reTx (cseq=101, method=INVITE, to_tag=<000b46e9b7600015495fde0b-218875d2>)
sip_sm_cc_channel_send_buf_fcn: Opened a one-time UDP send channel to server <19
2.246.69.223>:<5060>, handle = 3
sip_sm_cc_channel_send_buf_fcn:Sent SIP message to <192.246.69.223>:<5060>, handle=<3>:
message=
<ACK sip:34882@fwd.pulver.com SIP/2.0
Via: SIP/2.0/UDP 147.175.0.10:5060
From: "Marian Durkovic" <sip:md@bts.sk>;tag=000b46e9b7600015495fde0b-218875d2
To: <sip:34882@fwd.pulver.com>;tag=000b46e9b7600015495fde0b-218875d2
Call-ID: 000b46e9-b76000f7-296f2879-6f951c60@147.175.0.10
Date: Tue, 16 Sep 2003 08:01:37 GMT
CSeq: 101 ACK
Content-Length: 0

, length=<355>
sip_sm_cc_channel_send_buf_fcn: Closed a one-time UDP send channel handle = 3
SIPProcessUDPMessage: recv UDP message from <192.246.69.223>:<50195>:
<SIP/2.0 408 Request Timeout
Via: SIP/2.0/UDP 147.175.0.10:5060
From: "Marian Durkovic" <sip:md@bts.sk>;tag=000b46e9b7600015495fde0b-218875d2
To: <sip:34882@fwd.pulver.com>;tag=a6a1c5f60faecf035a1ae5b6e96e979a-324a
Call-ID: 000b46e9-b76000f7-296f2879-6f951c60@147.175.0.10
CSeq: 101 CANCEL
Server: Free World Dialup (0.8.11rc3 (i386/linux))
Content-Length: 0

, length=368
SIPProcessUDPMessage: recv UDP message from <194.160.23.16>:<50195>:
<SIP/2.0 487 Request Terminated
Via: SIP/2.0/UDP 147.175.0.10:5060
From: "Marian Durkovic" <sip:md@bts.sk>;tag=000b46e9b7600015495fde0b-218875d2
To: <sip:34882@fwd.pulver.com>;tag=000b46e9b7600015495fde0b-218875d2
Contact: <sip:34882@194.160.23.17:5060>
Record-Route: <sip:34882@192.246.69.223;ftag=000b46e9b7600015495fde0b-218875d2;lr=on>
Call-ID: 000b46e9-b76000f7-296f2879-6f951c60@147.175.0.10
CSeq: 101 INVITE
User-Agent: X-PRO build 1077
Content-Length: 0

, length=473
sipRelDevCoupledMessageStore: Storing for reTx (cseq=101, method=INVITE, to_tag=<000b46e9b7600015495fde0b-218875d2>)
sip_sm_cc_channel_send_buf_fcn: Opened a one-time UDP send channel to server <192.246.69.223>:<5060>, handle = 3
sip_sm_cc_channel_send_buf_fcn:Sent SIP message to <192.246.69.223>:<5060>, handle=<3>:
message=
<ACK sip:34882@fwd.pulver.com SIP/2.0
Via: SIP/2.0/UDP 147.175.0.10:5060
From: "Marian Durkovic" <sip:md@bts.sk>;tag=000b46e9b7600015495fde0b-218875d2
To: <sip:34882@fwd.pulver.com>;tag=000b46e9b7600015495fde0b-218875d2
Call-ID: 000b46e9-b76000f7-296f2879-6f951c60@147.175.0.10
Date: Tue, 16 Sep 2003 08:01:41 GMT
CSeq: 101 ACK
Content-Length: 0

, length=<355>
sip_sm_cc_channel_send_buf_fcn: Closed a one-time UDP send channel handle = 3
SIPProcessUDPMessage: recv UDP message from <194.160.23.16>:<50195>:
<SIP/2.0 487 Request Terminated
Via: SIP/2.0/UDP 147.175.0.10:5060
From: "Marian Durkovic" <sip:md@bts.sk>;tag=000b46e9b7600015495fde0b-218875d2
To: <sip:34882@fwd.pulver.com>;tag=000b46e9b7600015495fde0b-218875d2
Contact: <sip:34882@194.160.23.17:5060>
Record-Route: <sip:34882@192.246.69.223;ftag=000b46e9b7600015495fde0b-218875d2;lr=on>
Call-ID: 000b46e9-b76000f7-296f2879-6f951c60@147.175.0.10
CSeq: 101 INVITE
User-Agent: X-PRO build 1077
Content-Length: 0

, length=473
sipRelDevCoupledMessageStore: Storing for reTx (cseq=101, method=INVITE, to_tag=<000b46e9b7600015495fde0b-218875d2>)
sip_sm_cc_channel_send_buf_fcn: Opened a one-time UDP send channel to server <192.246.69.223>:<5060>, handle = 3
sip_sm_cc_channel_send_buf_fcn:Sent SIP message to <192.246.69.223>:<5060>, handle=<3>:
message=
<ACK sip:34882@fwd.pulver.com SIP/2.0
Via: SIP/2.0/UDP 147.175.0.10:5060
From: "Marian Durkovic" <sip:md@bts.sk>;tag=000b46e9b7600015495fde0b-218875d2
To: <sip:34882@fwd.pulver.com>;tag=000b46e9b7600015495fde0b-218875d2
Call-ID: 000b46e9-b76000f7-296f2879-6f951c60@147.175.0.10
Date: Tue, 16 Sep 2003 08:01:45 GMT
CSeq: 101 ACK
Content-Length: 0

, length=<355>
sip_sm_cc_channel_send_buf_fcn: Closed a one-time UDP send channel handle = 3
SIPProcessUDPMessage: recv UDP message from <194.160.23.16>:<50195>:
<SIP/2.0 487 Request Terminated
Via: SIP/2.0/UDP 147.175.0.10:5060
From: "Marian Durkovic" <sip:md@bts.sk>;tag=000b46e9b7600015495fde0b-218875d2
To: <sip:34882@fwd.pulver.com>;tag=000b46e9b7600015495fde0b-218875d2
Contact: <sip:34882@194.160.23.17:5060>
Record-Route: <sip:34882@192.246.69.223;ftag=000b46e9b7600015495fde0b-218875d2;lr=on>
Call-ID: 000b46e9-b76000f7-296f2879-6f951c60@147.175.0.10
CSeq: 101 INVITE
User-Agent: X-PRO build 1077
Content-Length: 0

, length=473
sipRelDevCoupledMessageStore: Storing for reTx (cseq=101, method=INVITE, to_tag=<000b46e9b7600015495fde0b-218875d2>)
sip_sm_cc_channel_send_buf_fcn: Opened a one-time UDP send channel to server <192.246.69.223>:<5060>, handle = 3
sip_sm_cc_channel_send_buf_fcn:Sent SIP message to <192.246.69.223>:<5060>, handle=<3>:
message=
<ACK sip:34882@fwd.pulver.com SIP/2.0
Via: SIP/2.0/UDP 147.175.0.10:5060
From: "Marian Durkovic" <sip:md@bts.sk>;tag=000b46e9b7600015495fde0b-218875d2
To: <sip:34882@fwd.pulver.com>;tag=000b46e9b7600015495fde0b-218875d2
Call-ID: 000b46e9-b76000f7-296f2879-6f951c60@147.175.0.10
Date: Tue, 16 Sep 2003 08:01:49 GMT
CSeq: 101 ACK
Content-Length: 0

, length=<355>
sip_sm_cc_channel_send_buf_fcn: Closed a one-time UDP send channel handle = 3
SIPProcessUDPMessage: recv UDP message from <194.160.23.16>:<50195>:
<SIP/2.0 487 Request Terminated
Via: SIP/2.0/UDP 147.175.0.10:5060
From: "Marian Durkovic" <sip:md@bts.sk>;tag=000b46e9b7600015495fde0b-218875d2
To: <sip:34882@fwd.pulver.com>;tag=000b46e9b7600015495fde0b-218875d2
Contact: <sip:34882@194.160.23.17:5060>
Record-Route: <sip:34882@192.246.69.223;ftag=000b46e9b7600015495fde0b-218875d2;lr=on>
Call-ID: 000b46e9-b76000f7-296f2879-6f951c60@147.175.0.10
CSeq: 101 INVITE
User-Agent: X-PRO build 1077
Content-Length: 0

, length=473
sipRelDevCoupledMessageStore: Storing for reTx (cseq=101, method=INVITE, to_tag=<000b46e9b7600015495fde0b-218875d2>)
sip_sm_cc_channel_send_buf_fcn: Opened a one-time UDP send channel to server <192.246.69.223>:<5060>, handle = 3
sip_sm_cc_channel_send_buf_fcn:Sent SIP message to <192.246.69.223>:<5060>, handle=<3>:
message=
<ACK sip:34882@fwd.pulver.com SIP/2.0
Via: SIP/2.0/UDP 147.175.0.10:5060
From: "Marian Durkovic" <sip:md@bts.sk>;tag=000b46e9b7600015495fde0b-218875d2
To: <sip:34882@fwd.pulver.com>;tag=000b46e9b7600015495fde0b-218875d2
Call-ID: 000b46e9-b76000f7-296f2879-6f951c60@147.175.0.10
Date: Tue, 16 Sep 2003 08:01:52 GMT
CSeq: 101 ACK
Content-Length: 0

, length=<355>
sip_sm_cc_channel_send_buf_fcn: Closed a one-time UDP send channel handle = 3
SIPProcessUDPMessage: recv UDP message from <194.160.23.16>:<50195>:
<INVITE sip:181@147.175.0.10:5060 SIP/2.0
Via: SIP/2.0/UDP 194.160.23.16;branch=z9hG4bK908a.d77b6e83.0
Via: SIP/2.0/UDP  147.175.80.12:5060
From: "Rektorat STU" <sip:0257294111@147.175.80.12>;tag=908757B4-261A
To: <sip:181@bts.sk>
Date: Tue, 16 Sep 2003 08:01:55 GMT
Call-ID: DFB1E779-E75211D7-A892ABB6-30DD61A@147.175.80.12
Supported: timer,100rel
Min-SE:  1800
Cisco-Guid: 3702737831-3880915415-2827987894-51238426
User-Agent: Cisco-SIPGateway/IOS-12.x
Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, COMET, REFER, SUBSCRIBE, NOTIFY, INFO
CSeq: 101 INVITE
Max-Forwards: 5
Remote-Party-ID: <sip:0257294111@147.175.80.12>;party=calling;screen=no;privacy=off
Timestamp: 1063699315
Contact: <sip:0257294111@147.175.80.12:5060>
Expires: 180
Allow-Events: telephone-event
Content-Type: application/sdp
Content-Length: 170

v=0
o=CiscoSystemsSIP-GW-UserAgent 3822 3727 IN IP4 147.175.80.12
s=SIP Call
c=IN IP4 147.175.80.12
t=0 0
m=audio 18906 RTP/AVP 8
a=rtpmap:8 PCMA/8000
a=ptime:20
, length=1011
sipSPICheckRequest: in_to_tag:<>, in_from_tag:<908757B4-261A>, stored=<>
sipRelDevCoupledMessageStore: Storing for reTx (cseq=101, method=INVITE, to_tag=<>)
sip_sm_cc_channel_send_buf_fcn: Sent SIP message: handle=<2>:
message=
<SIP/2.0 100 Trying
Via: SIP/2.0/UDP 194.160.23.16;branch=z9hG4bK908a.d77b6e83.0,SIP/2.0/UDP  147.175.80.12:5060
From: "Rektorat STU" <sip:0257294111@147.175.80.12>;tag=908757B4-261A
To: <sip:181@bts.sk>
Call-ID: DFB1E779-E75211D7-A892ABB6-30DD61A@147.175.80.12
Date: Tue, 16 Sep 2003 08:01:54 GMT
CSeq: 101 INVITE
Server: CSCO/4
Contact: <sip:181@147.175.0.10:5060>
Content-Length: 0

, length=<396>
sipRelDevCoupledMessageStore: Storing for reTx (cseq=101, method=INVITE, to_tag=
<000b46e9b760001669e576e0-03391e46>)
sip_sm_cc_channel_send_buf_fcn: Sent SIP message: handle=<2>:
message=
<SIP/2.0 180 Ringing
Via: SIP/2.0/UDP 194.160.23.16;branch=z9hG4bK908a.d77b6e83.0,SIP/2.0/UDP  147.175.80.12:5060
From: "Rektorat STU" <sip:0257294111@147.175.80.12>;tag=908757B4-261A
To: <sip:181@bts.sk>;tag=000b46e9b760001669e576e0-03391e46
Call-ID: DFB1E779-E75211D7-A892ABB6-30DD61A@147.175.80.12
Date: Tue, 16 Sep 2003 08:01:55 GMT
CSeq: 101 INVITE
Server: CSCO/4
Contact: <sip:181@147.175.0.10:5060>
Content-Length: 0

, length=<435>
SIPProcessUDPMessage: recv UDP message from <194.160.23.16>:<50195>:
<SIP/2.0 487 Request Terminated
Via: SIP/2.0/UDP 147.175.0.10:5060
From: "Marian Durkovic" <sip:md@bts.sk>;tag=000b46e9b7600015495fde0b-218875d2
To: <sip:34882@fwd.pulver.com>;tag=000b46e9b7600015495fde0b-218875d2
Contact: <sip:34882@194.160.23.17:5060>
Record-Route: <sip:34882@192.246.69.223;ftag=000b46e9b7600015495fde0b-218875d2;l
r=on>
Call-ID: 000b46e9-b76000f7-296f2879-6f951c60@147.175.0.10
CSeq: 101 INVITE
User-Agent: X-PRO build 1077
Content-Length: 0

, length=473
sipRelDevCoupledMessageStore: Storing for reTx (cseq=101, method=INVITE, to_tag=<000b46e9b7600015495fde0b-218875d2>)
sip_sm_cc_channel_send_buf_fcn: Opened a one-time UDP send channel to server <192.246.69.223>:<5060>, handle = 3
sip_sm_cc_channel_send_buf_fcn:Sent SIP message to <192.246.69.223>:<5060>, handle=<3>:
message=
<ACK sip:34882@fwd.pulver.com SIP/2.0
Via: SIP/2.0/UDP 147.175.0.10:5060
From: "Marian Durkovic" <sip:md@bts.sk>;tag=000b46e9b7600015495fde0b-218875d2
To: <sip:34882@fwd.pulver.com>;tag=000b46e9b7600015495fde0b-218875d2
Call-ID: 000b46e9-b76000f7-296f2879-6f951c60@147.175.0.10
Date: Tue, 16 Sep 2003 08:01:56 GMT
CSeq: 101 ACK
Content-Length: 0

, length=<355>
sip_sm_cc_channel_send_buf_fcn: Closed a one-time UDP send channel handle = 3
sipRelDevCoupledMessageStore: Storing for reTx (cseq=101, method=INVITE, to_tag=<000b46e9b760001669e576e0-03391e46>)
sip_sm_cc_channel_send_buf_fcn: Sent SIP message: handle=<2>:
message=
<SIP/2.0 200 OK
Via: SIP/2.0/UDP 194.160.23.16;branch=z9hG4bK908a.d77b6e83.0,SIP/2.0/UDP  147.175.80.12:5060
From: "Rektorat STU" <sip:0257294111@147.175.80.12>;tag=908757B4-261A
To: <sip:181@bts.sk>;tag=000b46e9b760001669e576e0-03391e46
Call-ID: DFB1E779-E75211D7-A892ABB6-30DD61A@147.175.80.12
Date: Tue, 16 Sep 2003 08:01:59 GMT
CSeq: 101 INVITE
Server: CSCO/4
Contact: <sip:181@147.175.0.10:5060>
Content-Type: application/sdp
Content-Length: 139

v=0
o=Cisco-SIPUA 7577 1841 IN IP4 147.175.0.10
s=SIP Call
c=IN IP4 147.175.0.10
t=0 0
m=audio 29340 RTP/AVP 8
a=rtpmap:8 PCMA/8000
, length=<602>
SIPProcessUDPMessage: recv UDP message from <147.175.80.12>:<64454>:
<ACK sip:181@147.175.0.10:5060 SIP/2.0
Via: SIP/2.0/UDP  147.175.80.12:5060
From: "Rektorat STU" <sip:0257294111@147.175.80.12>;tag=908757B4-261A
To: <sip:181@bts.sk>;tag=000b46e9b760001669e576e0-03391e46
Date: Tue, 16 Sep 2003 08:01:55 GMT
Call-ID: DFB1E779-E75211D7-A892ABB6-30DD61A@147.175.80.12
Max-Forwards: 6
Content-Length: 0
CSeq: 101 ACK

, length=357
sipSPICheckRequest: Call ID match: same call id.
sipSPICheckRequest: in_to_tag:<000b46e9b760001669e576e0-03391e46>, in_from_tag:<908757B4-261A>, stored=<000b46e9b760001669e576e0-03391e46>
SIPSPIAddRouteHeaders: Route info not available; will not add Route header.
sip_sm_cc_channel_send_buf_fcn: Opened a one-time UDP send channel to server <147.175.80.12>:<5060>, handle = 3
sip_sm_cc_channel_send_buf_fcn:Sent SIP message to <147.175.80.12>:<5060>, handl
e=<3>:
message=
<BYE sip:0257294111@147.175.80.12:5060 SIP/2.0
Via: SIP/2.0/UDP 147.175.0.10:5060
From: <sip:181@bts.sk>;tag=000b46e9b760001669e576e0-03391e46
To: "Rektorat STU" <sip:0257294111@147.175.80.12>;tag=908757B4-261A
Call-ID: DFB1E779-E75211D7-A892ABB6-30DD61A@147.175.80.12
Date: Tue, 16 Sep 2003 08:02:19 GMT
CSeq: 101 BYE
User-Agent: CSCO/4
Content-Length: 0

, length=<366>
sip_sm_cc_channel_send_buf_fcn: Closed a one-time UDP send channel handle = 3
SIPProcessUDPMessage: recv UDP message from <147.175.80.12>:<50195>:
<SIP/2.0 200 OK
Via: SIP/2.0/UDP 147.175.0.10:5060
From: <sip:181@bts.sk>;tag=000b46e9b760001669e576e0-03391e46
To: "Rektorat STU" <sip:0257294111@147.175.80.12>;tag=908757B4-261A
Date: Tue, 16 Sep 2003 08:02:20 GMT
Call-ID: DFB1E779-E75211D7-A892ABB6-30DD61A@147.175.80.12
Server: Cisco-SIPGateway/IOS-12.x
Content-Length: 0


More data needed:


Please capture debug sip-messages for phone in this scenario.

Cisco belive this is resolved in latest versions of the software.

debugs:

[01:52:18] sip_sm_cc_channel_send_buf_fcn: Closed a one-time UDP send channel handle = 3
[01:52:18] SIPSPIAddRouteHeaders: Route info not available; will not add Route header.
[01:52:18] sip_sm_cc_channel_send_buf_fcn: Opened a one-time UDP send channel to server <172.18.106.248>:<5060>, handle = 3

[01:52:18] sip_sm_cc_channel_send_buf_fcn:Sent SIP message to <172.18.106.248>:<5060>, handle=<3>:
message=
<INVITE sip:15786@cisco.com;user=phone SIP/2.0
Via: SIP/2.0/UDP 10.83.145.171:5060
From: "Tomas de Leon" <sip:15770@cisco.com>;tag=0003e311f82900263b515659-1a25a324
To: <sip:15786@cisco.com;user=phone>
Call-ID: 0003e311-f8291c5c-3ee29375-1cbc8e3f@10.83.145.171
Date: Thu, 11 Sep 2003 05:52:18 GMT
CSeq: 102 INVITE
User-Agent: CSCO/5
Contact: <sip:15770@10.83.145.171:5060>
Proxy-Authorization: Digest username="15770",realm="CISCO",uri="sip:172.18.106.248",response="17bed582ecdf8b4d79448e6a77a5816e",nonce="3f600dd8",cnonce="39ba8893",qop=auth,nc=00000001,algorithm=MD5
Expires: 180
Content-Type: application/sdp
Content-Length: 249
Remote-Party-ID: "Tomas de Leon" <sip:15770@10.83.145.171>;party=calling;id-type=subscriber;privacy=off;screen=no

v=0
o=Cisco-SIPUA 12455 28073 IN IP4 10.83.145.171
s=SIP Call
c=IN IP4 10.83.145.171
t=0 0
m=audio 26490 RTP/AVP 18 0 8 101
a=rtpmap:18 G729/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
>, length=<1012>

[01:52:18] sip_sm_cc_channel_send_buf_fcn: Closed a one-time UDP send channel handle = 3
[01:52:18] SIPProcessUDPMessage: recv UDP message from <172.18.106.248>:<11214>:
<SIP/2.0 100 Trying
Via: SIP/2.0/UDP 10.83.145.171:5060;received=10.83.145.171
Call-ID: 0003e311-f8291c5c-3ee29375-1cbc8e3f@10.83.145.171
From: "Tomas de Leon" <sip:15770@cisco.com>;tag=0003e311f82900263b515659-1a25a324
To: <sip:15786@cisco.com;user=phone>
CSeq: 102 INVITE
Content-Length: 0

>, length=300

[01:52:18] sipSPICheckResponse: Response match: callid=0003e311-f8291c5c-3ee29375-1cbc8e3f@10.83.145.171, cseq=102, cseq_method=INVITE
[01:52:18] SIPProcessUDPMessage: recv UDP message from <172.18.106.248>:<11726>:
<SIP/2.0 180 Ringing
Via: SIP/2.0/UDP 10.83.145.171:5060;received=10.83.145.171
From: "Tomas de Leon" <sip:15770@cisco.com>;tag=0003e311f82900263b515659-1a25a324
To: <sip:15786@cisco.com;user=phone>;tag=000a416b840d000468abd7c2-59088753
Call-ID: 0003e311-f8291c5c-3ee29375-1cbc8e3f@10.83.145.171
Date: Thu, 11 Sep 2003 05:52:19 GMT
CSeq: 102 INVITE
Server: CSCO/5
Contact: <sip:15786@172.18.106.174:5060>
Record-Route: <sip:15786@cisco.com:5060;user=phone;maddr=172.18.106.248;transport=udp>
Content-Length: 0

>, length=524
[01:52:18] sipSPICheckResponse: Response match: callid=0003e311-f8291c5c-3ee29375-1cbc8e3f@10.83.145.171, cseq=102, cseq_method=INVITE


*** SAME AS INVITE ***

[01:52:23] sip_sm_cc_channel_send_buf_fcn: Opened a one-time UDP send channel to server <172.18.106.248>:<5060>, handle = 3
[01:52:23] sip_sm_cc_channel_send_buf_fcn:Sent SIP message to <172.18.106.248>:<5060>, handle=<3>:
message=
<CANCEL sip:15786@cisco.com;user=phone SIP/2.0
Via: SIP/2.0/UDP 10.83.145.171:5060
From: "Tomas de Leon" <sip:15770@cisco.com>;tag=0003e311f82900263b515659-1a25a324
To: <sip:15786@cisco.com;user=phone>
Call-ID: 0003e311-f8291c5c-3ee29375-1cbc8e3f@10.83.145.171
Date: Thu, 11 Sep 2003 05:52:24 GMT
CSeq: 102 CANCEL
User-Agent: CSCO/5
Content-Length: 0
Proxy-Authorization: Digest username="15770",realm="CISCO",uri="sip:172.18.106.248",response="9e55d874837bc04e478c9b7204aeae66",nonce="3f600dd8",cnonce="2f430ad7",qop=auth,nc=00000002,algorithm=MD5

>, length=<560>



(1) Short problem description:

SIP signalling bug (CANCEL)

(2) Longer problem description (what happens):

IP phone sends out INVITE message and receives 100 & 180 responses with Record-Route: header. If user hangs up before the call is answered, IP phone sends CANCEL to the sip URI found in Record-Route: header. This is a bug, since CANCELs should always go to the same sip URI where the INVITE was sent. If the first proxy does not use Record-Route, the called phone doesn't get the CANCEL and rings forever (or until absolute timeout).

(7) Would you classify this as:

(A) Bug/malfunction: Can not deploy before fixed

(8) Version:

7940 with software version 4.4.

(9) Contact Information:

Marian Durkovic <md@SPAM.bts.sk>

(11) Report:

Date: Tue, 24 Jun 2003 14:51:10 +0200
Message-ID: <20030624145110.A27523@us.svf.stuba.sk>