[asterisk-dev] chan_sip.c - no reply to critical packet
Gregory Boehnlein
damin at nacs.net
Fri Jan 30 14:17:12 CST 2009
Hello,
On 1/14/2008, I migrated a pair of PRI circuits from an Asterisk
server w/ a TE405P to a Cisco 2610-XM w/ Voice Processing cards. We need to
be able to offer re-direction of T.38 calls for specific DIDs over to a
different piece of equipment, and we were not comfortable enough to deploy
Asterisk 1.4 for this specific server. We did some pretty heavy testing and
the move was very smooth. However, over the past few days I have started to
see the following messages on my Asterisk 1.2 server.
[Jan 30 10:50:12] WARNING[11080]: Hanging up call
7592F3FA-EE1C11DD-8E78B0F4-24748FB1 at 207.166.192.180 - no reply to our
critical packet.
Debug output from the Asterisk console shows chan_sip.c attempting to
transmit a "200 OK" back to the Cisco gateway. A packet trace on the switch
port shows the Cisco sending the ACK for the 200 OK, but Asterisk continues
to attempt to re-transmit the 200 OK as if it never saw the ACK. Eventually,
the call hangs up w/ the message listed above. Customers are complaining
about calls being hung up on them midway through a call.
Here is the SIP Call Trace that was taken from a port-mirror of our Asterisk
server via a SIP sniffer. 207.166.192.174 is the Asterisk server and
207.166.192.180 is the Cisco PRI gateway.
Capture Time Protocol StatusCode Source Source Port
Destination
Destination Port
10:49:49.034 SIP Invite 2002 207.166.192.180 49162
207.166.192.174 5060
10:49:49.035 SIP Trying 100 207.166.192.174 5060
207.166.192.180 5060
10:49:49.044 SIP Ringing180 207.166.192.174 5060
207.166.192.180 5060
10:50:09.062 SIP OK 200 207.166.192.174 5060
207.166.192.180 5060
10:50:09.062 RTP RTP 4000 207.166.192.174 17446
207.166.192.180 17578
10:50:09.091 SIP Ack 2003 207.166.192.180 49162
207.166.192.174 5060
10:50:09.115 SIP OK 200 207.166.192.174 5060
207.166.192.180 5060
10:50:09.119 RTP RTP 4000 207.166.192.180 17578
207.166.192.174 17446
10:50:09.128 SIP Ack 2003 207.166.192.180 49162
207.166.192.174 5060
10:50:09.166 SIP OK 200 207.166.192.174 5060
207.166.192.180 5060
10:50:09.190 SIP Ack 2003 207.166.192.180 49162
207.166.192.174 5060
10:50:09.271 SIP OK 200 207.166.192.174 5060
207.166.192.180 5060
10:50:09.283 SIP Ack 2003 207.166.192.180 49162
207.166.192.174 5060
10:50:09.479 SIP OK 200 207.166.192.174 5060
207.166.192.180 5060
10:50:09.493 SIP Ack 2003 207.166.192.180 49162
207.166.192.174 5060
10:50:09.895 SIP OK 200 207.166.192.174 5060
207.166.192.180 5060
10:50:09.907 SIP Ack 2003 207.166.192.180 49162
207.166.192.174 5060
10:50:10.726 SIP OK 200 207.166.192.174 5060
207.166.192.180 5060
10:50:10.739 SIP Ack 2003 207.166.192.180 49162
207.166.192.174 5060
10:50:13.026 RTCP SenderReport 200 207.166.192.180
17579 207.166.192.174 17447
10:51:01.401 SIP SIP-Bye 2005 207.166.192.180
49162 207.166.192.174 5060
Looking at our logs, this problem only seems to be happening with this one
Cisco 2600 gateway and only on calls from the PSTN PRI into the Asterisk
server. I'm going to re-boot it during a maintenance window tonight and see
if that reduces the issue, but this looks more like an Asterisk issue than a
Cisco issue the more I look at it.
I found the following post from 2007, which seems to reference a problem
between Asterisk and Cisco gear (similar to my setup).
http://lists.digium.com/pipermail/asterisk-users/2007-April/184875.html
Before I start digging into things and ripping them apart more, does anyone
have any insight into this?
Below is the console debugging output from the session. I had SIP debugging
as well as verbose debugging enabled:
[Jan 30 10:49:48] Sending to 207.166.192.180 : 5060 (non-NAT)
[Jan 30 10:49:48] Found RTP audio format 0
[Jan 30 10:49:48] Found RTP audio format 18
[Jan 30 10:49:48] Found RTP audio format 101
[Jan 30 10:49:48] Peer audio RTP is at port 207.166.192.180:17578
[Jan 30 10:49:48] Found description format PCMU
[Jan 30 10:49:48] Found description format G729
[Jan 30 10:49:48] Found description format telephone-event
[Jan 30 10:49:48] Capabilities: us - 0x104 (ulaw|g729), peer - audio=0x104
(ulaw|g729)/video=0x0 (nothing), combined - 0x104 (ulaw|g729)
[Jan 30 10:49:48] Non-codec capabilities: us - 0x1 (telephone-event), peer -
0x1 (telephone-event), combined - 0x1 (telephone-event)
[Jan 30 10:49:48] Looking for 2169203080 in inbound (domain 207.166.192.174)
[Jan 30 10:49:48] list_route: hop: <sip:2164864965 at 207.166.192.180:5060>
[Jan 30 10:49:48] Transmitting (no NAT) to 207.166.192.180:5060:
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 207.166.192.180:5060;x-ds0num="ISDN 1/0:23 1/0:DS1
17:DS0";branch=z9hG4bK97234BA;received=207.166.192.180
From: <sip:2164864965 at 207.166.192.180>;tag=5BD698E8-75
To: <sip:2169203080 at 207.166.192.174>
Call-ID: 7592F3FA-EE1C11DD-8E78B0F4-24748FB1 at 207.166.192.180
CSeq: 101 INVITE
User-Agent: N2Net Univoice
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Contact: <sip:2169203080 at 207.166.192.174>
Content-Length: 0
---
[Jan 30 10:49:48] -- Executing Macro("SIP/207.166.192.180-b7536278",
"set-cdr-info-static|13418") in new stack
[Jan 30 10:49:48] -- Executing Set("SIP/207.166.192.180-b7536278",
"CDR(accountcode)=13418") in new stack
[Jan 30 10:49:48] -- Executing Set("SIP/207.166.192.180-b7536278",
"CDR(userfield)=inbound") in new stack
[Jan 30 10:49:48] -- Executing
SetAMAFlags("SIP/207.166.192.180-b7536278", "billing") in new stack
[Jan 30 10:49:48] -- Executing Dial("SIP/207.166.192.180-b7536278",
"SIP/2169203080 at pbx-1") in new stack
[Jan 30 10:49:48] -- Called 2169203080 at pbx-1
[Jan 30 10:49:48] -- SIP/pbx-1-088ac0a8 is ringing
[Jan 30 10:49:48] Transmitting (no NAT) to 207.166.192.180:5060:
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP 207.166.192.180:5060;x-ds0num="ISDN 1/0:23 1/0:DS1
17:DS0";branch=z9hG4bK97234BA;received=207.166.192.180
From: <sip:2164864965 at 207.166.192.180>;tag=5BD698E8-75
To: <sip:2169203080 at 207.166.192.174>;tag=as7f89f1a4
Call-ID: 7592F3FA-EE1C11DD-8E78B0F4-24748FB1 at 207.166.192.180
CSeq: 101 INVITE
User-Agent: N2Net Univoice
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Contact: <sip:2169203080 at 207.166.192.174>
Content-Length: 0
---
[Jan 30 10:49:49] Receiving INFO!
[Jan 30 10:49:49] Transmitting (no NAT) to 207.166.192.180:5060:
SIP/2.0 403 Unauthorized
Via: SIP/2.0/UDP 207.166.192.180:5060;x-ds0num="ISDN 1/0:23 1/0:DS1
17:DS0";branch=z9hG4bK9724104E;received=207.166.192.180
From: <sip:2164864965 at 207.166.192.180>;tag=5BD698E8-75
To: <sip:2169203080 at 207.166.192.174>;tag=as7f89f1a4
Call-ID: 7592F3FA-EE1C11DD-8E78B0F4-24748FB1 at 207.166.192.180
CSeq: 102 INFO
User-Agent: N2Net Univoice
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Content-Length: 0
[Jan 30 10:50:08] We're at 207.166.192.174 port 17446
[Jan 30 10:50:08] Adding codec 0x4 (ulaw) to SDP
[Jan 30 10:50:08] Adding codec 0x100 (g729) to SDP
[Jan 30 10:50:08] Adding non-codec 0x1 (telephone-event) to SDP
[Jan 30 10:50:08] Reliably Transmitting (no NAT) to 207.166.192.180:5060:
SIP/2.0 200 OK
Via: SIP/2.0/UDP 207.166.192.180:5060;x-ds0num="ISDN 1/0:23 1/0:DS1
17:DS0";branch=z9hG4bK97234BA;received=207.166.192.180
From: <sip:2164864965 at 207.166.192.180>;tag=5BD698E8-75
To: <sip:2169203080 at 207.166.192.174>;tag=as7f89f1a4
Call-ID: 7592F3FA-EE1C11DD-8E78B0F4-24748FB1 at 207.166.192.180
CSeq: 101 INVITE
User-Agent: N2Net Univoice
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Contact: <sip:2169203080 at 207.166.192.174>
Content-Type: application/sdp
Content-Length: 267
v=0
o=root 9987 9987 IN IP4 207.166.192.174
s=session
c=IN IP4 207.166.192.174
t=0 0
m=audio 17446 RTP/AVP 0 18 101
a=rtpmap:0 PCMU/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
---
[Jan 30 10:50:08] -- Attempting native bridge of
SIP/207.166.192.180-b7536278 and SIP/pbx-1-088ac0a8
[Jan 30 10:50:09] Retransmitting #1 (no NAT) to 207.166.192.180:5060:
SIP/2.0 200 OK
Via: SIP/2.0/UDP 207.166.192.180:5060;x-ds0num="ISDN 1/0:23 1/0:DS1
17:DS0";branch=z9hG4bK97234BA;received=207.166.192.180
From: <sip:2164864965 at 207.166.192.180>;tag=5BD698E8-75
To: <sip:2169203080 at 207.166.192.174>;tag=as7f89f1a4
Call-ID: 7592F3FA-EE1C11DD-8E78B0F4-24748FB1 at 207.166.192.180
CSeq: 101 INVITE
User-Agent: N2Net Univoice
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Contact: <sip:2169203080 at 207.166.192.174>
Content-Type: application/sdp
Content-Length: 267
v=0
o=root 9987 9987 IN IP4 207.166.192.174
s=session
c=IN IP4 207.166.192.174
t=0 0
m=audio 17446 RTP/AVP 0 18 101
a=rtpmap:0 PCMU/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
---
[Jan 30 10:50:09] Retransmitting #2 (no NAT) to 207.166.192.180:5060:
SIP/2.0 200 OK
Via: SIP/2.0/UDP 207.166.192.180:5060;x-ds0num="ISDN 1/0:23 1/0:DS1
17:DS0";branch=z9hG4bK97234BA;received=207.166.192.180
From: <sip:2164864965 at 207.166.192.180>;tag=5BD698E8-75
To: <sip:2169203080 at 207.166.192.174>;tag=as7f89f1a4
Call-ID: 7592F3FA-EE1C11DD-8E78B0F4-24748FB1 at 207.166.192.180
CSeq: 101 INVITE
User-Agent: N2Net Univoice
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Contact: <sip:2169203080 at 207.166.192.174>
Content-Type: application/sdp
Content-Length: 267
v=0
o=root 9987 9987 IN IP4 207.166.192.174
s=session
c=IN IP4 207.166.192.174
t=0 0
m=audio 17446 RTP/AVP 0 18 101
a=rtpmap:0 PCMU/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
---
[Jan 30 10:50:09] Retransmitting #3 (no NAT) to 207.166.192.180:5060:
SIP/2.0 200 OK
Via: SIP/2.0/UDP 207.166.192.180:5060;x-ds0num="ISDN 1/0:23 1/0:DS1
17:DS0";branch=z9hG4bK97234BA;received=207.166.192.180
From: <sip:2164864965 at 207.166.192.180>;tag=5BD698E8-75
To: <sip:2169203080 at 207.166.192.174>;tag=as7f89f1a4
Call-ID: 7592F3FA-EE1C11DD-8E78B0F4-24748FB1 at 207.166.192.180
CSeq: 101 INVITE
User-Agent: N2Net Univoice
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Contact: <sip:2169203080 at 207.166.192.174>
Content-Type: application/sdp
Content-Length: 267
v=0
o=root 9987 9987 IN IP4 207.166.192.174
s=session
c=IN IP4 207.166.192.174
t=0 0
m=audio 17446 RTP/AVP 0 18 101
a=rtpmap:0 PCMU/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
[Jan 30 10:50:09] Retransmitting #4 (no NAT) to 207.166.192.180:5060:
SIP/2.0 200 OK
Via: SIP/2.0/UDP 207.166.192.180:5060;x-ds0num="ISDN 1/0:23 1/0:DS1
17:DS0";branch=z9hG4bK97234BA;received=207.166.192.180
From: <sip:2164864965 at 207.166.192.180>;tag=5BD698E8-75
To: <sip:2169203080 at 207.166.192.174>;tag=as7f89f1a4
Call-ID: 7592F3FA-EE1C11DD-8E78B0F4-24748FB1 at 207.166.192.180
CSeq: 101 INVITE
User-Agent: N2Net Univoice
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Contact: <sip:2169203080 at 207.166.192.174>
Content-Type: application/sdp
Content-Length: 267
v=0
o=root 9987 9987 IN IP4 207.166.192.174
s=session
c=IN IP4 207.166.192.174
t=0 0
m=audio 17446 RTP/AVP 0 18 101
a=rtpmap:0 PCMU/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
---
[Jan 30 10:50:09] Retransmitting #5 (no NAT) to 207.166.192.180:5060:
SIP/2.0 200 OK
Via: SIP/2.0/UDP 207.166.192.180:5060;x-ds0num="ISDN 1/0:23 1/0:DS1
17:DS0";branch=z9hG4bK97234BA;received=207.166.192.180
From: <sip:2164864965 at 207.166.192.180>;tag=5BD698E8-75
To: <sip:2169203080 at 207.166.192.174>;tag=as7f89f1a4
Call-ID: 7592F3FA-EE1C11DD-8E78B0F4-24748FB1 at 207.166.192.180
CSeq: 101 INVITE
User-Agent: N2Net Univoice
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Contact: <sip:2169203080 at 207.166.192.174>
Content-Type: application/sdp
Content-Length: 267
v=0
o=root 9987 9987 IN IP4 207.166.192.174
s=session
c=IN IP4 207.166.192.174
t=0 0
m=audio 17446 RTP/AVP 0 18 101
a=rtpmap:0 PCMU/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
---
[Jan 30 10:50:10] Retransmitting #6 (no NAT) to 207.166.192.180:5060:
SIP/2.0 200 OK
Via: SIP/2.0/UDP 207.166.192.180:5060;x-ds0num="ISDN 1/0:23 1/0:DS1
17:DS0";branch=z9hG4bK97234BA;received=207.166.192.180
From: <sip:2164864965 at 207.166.192.180>;tag=5BD698E8-75
To: <sip:2169203080 at 207.166.192.174>;tag=as7f89f1a4
Call-ID: 7592F3FA-EE1C11DD-8E78B0F4-24748FB1 at 207.166.192.180
CSeq: 101 INVITE
User-Agent: N2Net Univoice
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Contact: <sip:2169203080 at 207.166.192.174>
Content-Type: application/sdp
Content-Length: 267
v=0
o=root 9987 9987 IN IP4 207.166.192.174
s=session
c=IN IP4 207.166.192.174
t=0 0
m=audio 17446 RTP/AVP 0 18 101
a=rtpmap:0 PCMU/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
[Jan 30 10:50:12] WARNING[11080]: chan_sip.c:1229 retrans_pkt: Maximum
retries exceeded on transmission
7592F3FA-EE1C11DD-8E78B0F4-24748FB1 at 207.166.192.180 for seqno 101 (Critical
Response)
[Jan 30 10:50:12] WARNING[11080]: chan_sip.c:1246 retrans_pkt: Hanging up
call 7592F3FA-EE1C11DD-8E78B0F4-24748FB1 at 207.166.192.180 - no reply to our
critical packet.
[Jan 30 10:50:12] == Spawn extension (inbound, 2169203080, 2) exited
non-zero on 'SIP/207.166.192.180-b7536278'
[Jan 30 10:50:12] Destroying call
'7592F3FA-EE1C11DD-8E78B0F4-24748FB1 at 207.166.192.180'
More information about the asterisk-dev
mailing list