(SOLVED) Fast busy but the phone still rings (twice)

Asterisk Asterisk Support
1

I’m not sure what happened. These phones use to work and suddenly stopped. Now all incoming calls get a fast busy signal. It doesn’t appear to be congestion. The extension being called rings anyway and shows the caller ID. After I hang up that call, the phone rings again showing my caller id again. This happens every time.

I’m using the distro version of FreePBX 2.10 and asterisk version 1.8.9.3. I’ve been trouble shooting for days. It appears to be a timing issue. Lots of delay before any phone action. In debug, I get an initial hit right away, then a pause before any other activity. I’d say the pause is around 3 to 5 seconds.

Thanks for any help.

2

If you have been debugging it, where are the Asterisk logs?

3

Here’s the log:

[2012-03-26 16:57:13] VERBOSE[-1] chan_sip.c: Really destroying SIP dialog ‘3feba8b84ffad7c53a38b8e6518b08db@10.11.100.12:5060’ Method: INVITE
[2012-03-26 16:57:13] VERBOSE[-1] chan_sip.c:
<— SIP read from UDP:184.72.227.214:5060 —>
INVITE sip:5625552550@xx.xx.xx.xx:5060;received=184.72.227.214:5060 SIP/2.0
Record-Route: sip:pb2proxy-pro-aws03.phonebooth.net:5060;lr=on;did=7a8.c103f456
Via: SIP/2.0/UDP pb2proxy-pro-aws03.phonebooth.net;branch=z9hG4bK67dd.211ee075.0
Via: SIP/2.0/UDP 184.106.130.224;received=184.106.130.224;rport=5060;branch=z9hG4bK01KKQK1Z46tNc
Max-Forwards: 53
From: "WIRELESS CALLER " sip:+15625551212@184.106.130.224;tag=9ZyvXeB8tQ9mg
To: sip:s@xx.xx.xx.xx:5060;received=184.72.227.214:5060
Call-ID: 340abee6-f242-122f-8d9e-40404edf54cf
CSeq: 26067042 INVITE
Contact: sip:mod_sofia@184.106.130.224:5060
User-Agent: FreeSWITCH-mod_sofia/1.0.4-hacked
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, MESSAGE, SUBSCRIBE, NOTIFY, REFER, UPDATE, REGISTER, INFO
Supported: precondition, path, replaces
Allow-Events: talk, refer
Privacy: none
Content-Type: application/sdp
Content-Disposition: session
Content-Length: 316
P-Asserted-Identity: "WIRELESS CALLER " sip:+15625551212@184.106.130.224

v=0
o=Sonus_UAC 26003 15518 IN IP4 192.168.47.68
s=SIP Media Capabilities
c=IN IP4 67.231.4.99
t=0 0
m=audio 20998 RTP/AVP 0 18 96 101
a=rtpmap:0 PCMU/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:96 iLBC/8000
a=fmtp:96 mode=30
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=maxptime:30
<------------->
[2012-03-26 16:57:13] VERBOSE[-1] chan_sip.c: — (19 headers 14 lines) —
[2012-03-26 16:57:13] VERBOSE[-1] chan_sip.c: Ignoring this INVITE request
[2012-03-26 16:57:13] VERBOSE[-1] chan_sip.c:
<— Transmitting (NAT) to 184.72.227.214:5060 —>
SIP/2.0 100 Trying
Via: SIP/2.0/UDP pb2proxy-pro-aws03.phonebooth.net;branch=z9hG4bK67dd.211ee075.0;received=184.72.227.214;rport=5060
Via: SIP/2.0/UDP 184.106.130.224;received=184.106.130.224;rport=5060;branch=z9hG4bK01KKQK1Z46tNc
Record-Route: sip:pb2proxy-pro-aws03.phonebooth.net:5060;lr=on;did=7a8.c103f456
From: "WIRELESS CALLER " sip:+15625551212@184.106.130.224;tag=9ZyvXeB8tQ9mg
To: sip:s@xx.xx.xx.xx:5060;received=184.72.227.214:5060
Call-ID: 340abee6-f242-122f-8d9e-40404edf54cf
CSeq: 26067042 INVITE
Server: FPBX-2.10.0(1.8.9.3)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
Contact: sip:5625552550@xx.xx.xx.xx:5060
Content-Length: 0

<------------>
[2012-03-26 16:57:13] VERBOSE[-1] chan_sip.c: Audio is at 18982
[2012-03-26 16:57:13] VERBOSE[-1] chan_sip.c: Adding codec 0x4 (ulaw) to SDP
[2012-03-26 16:57:13] VERBOSE[-1] chan_sip.c: Adding codec 0x100 (g729) to SDP
[2012-03-26 16:57:13] VERBOSE[-1] chan_sip.c: Adding non-codec 0x1 (telephone-event) to SDP
[2012-03-26 16:57:13] VERBOSE[-1] chan_sip.c:
<— Transmitting (NAT) to 184.72.227.214:5060 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP pb2proxy-pro-aws03.phonebooth.net;branch=z9hG4bK67dd.211ee075.0;received=184.72.227.214;rport=5060
Via: SIP/2.0/UDP 184.106.130.224;received=184.106.130.224;rport=5060;branch=z9hG4bK01KKQK1Z46tNc
Record-Route: sip:pb2proxy-pro-aws03.phonebooth.net:5060;lr=on;did=7a8.c103f456
From: "WIRELESS CALLER " sip:+15625551212@184.106.130.224;tag=9ZyvXeB8tQ9mg
To: sip:s@xx.xx.xx.xx:5060;received=184.72.227.214:5060;tag=as59522ff0
Call-ID: 340abee6-f242-122f-8d9e-40404edf54cf
CSeq: 26067042 INVITE
Server: FPBX-2.10.0(1.8.9.3)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
Contact: sip:5625552550@xx.xx.xx.xx:5060
Content-Type: application/sdp
Content-Length: 277

v=0
o=root 817371500 817371501 IN IP4 xx.xx.xx.xx
s=Asterisk PBX 1.8.9.3
c=IN IP4 xx.xx.xx.xx
t=0 0
m=audio 18982 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=ptime:20
a=sendrecv

<------------>
[2012-03-26 16:57:13] WARNING[-1] chan_sip.c: Retransmission timeout reached on transmission 31fbf207-f242-122f-8d9e-40404edf54cf for seqno 26067041 (Critical Response) – See wiki.asterisk.org/wiki/display/ … nsmissions
Packet timed out after 10017ms with no response
[2012-03-26 16:57:13] WARNING[-1] chan_sip.c: Hanging up call 31fbf207-f242-122f-8d9e-40404edf54cf - no reply to our critical packet (see wiki.asterisk.org/wiki/display/ … nsmissions).
[2012-03-26 16:57:13] WARNING[-1] chan_sip.c: Retransmission timeout reached on transmission 340abee6-f242-122f-8d9e-40404edf54cf for seqno 26067042 (Critical Response) – See wiki.asterisk.org/wiki/display/ … nsmissions
Packet timed out after 10010ms with no response
[2012-03-26 16:57:13] WARNING[-1] chan_sip.c: Hanging up call 340abee6-f242-122f-8d9e-40404edf54cf - no reply to our critical packet (see wiki.asterisk.org/wiki/display/ … nsmissions).
[2012-03-26 16:57:13] VERBOSE[-1] chan_sip.c: Retransmitting #1 (NAT) to 50.56.59.168:5060:
REGISTER sip:trunk2.phonebooth.net SIP/2.0
Via: SIP/2.0/UDP xx.xx.xx.xx:5060;branch=z9hG4bK55752c1f;rport
Max-Forwards: 70
From: sip:bacctname@trunk2.phonebooth.net;tag=as28e0ac17
To: sip:bacctname@trunk2.phonebooth.net
Call-ID: 3adc891531c1824f1699556d5706b49a@127.0.0.1
CSeq: 112 REGISTER
User-Agent: FPBX-2.10.0(1.8.9.3)
Authorization: Digest username=“bacctname”, realm=“trunk.phonebooth.net”, algorithm=MD5, uri=“sip:trunk2.phonebooth.net”, nonce=“364ce4fd-34da-41a9-9660-70eeb7fb4ff3”, response=“e7e4b837f14bbd8467a53403f7751d4a”, qop=auth, cnonce=“28b25901”, nc=0000000a
Expires: 120
Contact: sip:s@xx.xx.xx.xx:5060
Content-Length: 0

[2012-03-26 16:57:13] VERBOSE[-1] chan_sip.c: Reliably Transmitting (NAT) to 192.168.0.52:11470:
OPTIONS sip:1014@192.168.101.105:5060 SIP/2.0
Via: SIP/2.0/UDP 10.11.100.12:5060;branch=z9hG4bK0b1576c2;rport
Max-Forwards: 70
From: “Unknown” sip:Unknown@10.11.100.12;tag=as403d5b81
To: sip:1014@192.168.101.105:5060
Contact: sip:Unknown@10.11.100.12:5060
Call-ID: 0ce742d11d17df375320cee9111d89fc@10.11.100.12:5060
CSeq: 102 OPTIONS
User-Agent: FPBX-2.10.0(1.8.9.3)
Date: Mon, 26 Mar 2012 23:57:13 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
Content-Length: 0

[2012-03-26 16:57:13] VERBOSE[-1] chan_sip.c: Retransmitting #2 (NAT) to 50.56.59.168:5060:
REGISTER sip:trunk2.phonebooth.net SIP/2.0
Via: SIP/2.0/UDP xx.xx.xx.xx:5060;branch=z9hG4bK55752c1f;rport
Max-Forwards: 70
From: sip:bacctname@trunk2.phonebooth.net;tag=as28e0ac17
To: sip:bacctname@trunk2.phonebooth.net
Call-ID: 3adc891531c1824f1699556d5706b49a@127.0.0.1
CSeq: 112 REGISTER
User-Agent: FPBX-2.10.0(1.8.9.3)
Authorization: Digest username=“bacctname”, realm=“trunk.phonebooth.net”, algorithm=MD5, uri=“sip:trunk2.phonebooth.net”, nonce=“364ce4fd-34da-41a9-9660-70eeb7fb4ff3”, response=“e7e4b837f14bbd8467a53403f7751d4a”, qop=auth, cnonce=“28b25901”, nc=0000000a
Expires: 120
Contact: sip:s@xx.xx.xx.xx:5060
Content-Length: 0

[2012-03-26 16:57:13] VERBOSE[-1] app_macro.c: == Spawn extension (macro-vm, s-CHANUNAVAIL, 2) exited non-zero on ‘SIP/fpbx-2-bacctname-00000017’ in macro ‘vm’
[2012-03-26 16:57:13] VERBOSE[-1] chan_sip.c:
<— SIP read from UDP:184.72.227.214:5060 —>
INVITE sip:5625552550@xx.xx.xx.xx:5060;received=184.72.227.214:5060 SIP/2.0
Record-Route: sip:pb2proxy-pro-aws03.phonebooth.net:5060;lr=on;did=7a8.c103f456
Via: SIP/2.0/UDP pb2proxy-pro-aws03.phonebooth.net;branch=z9hG4bK67dd.211ee075.0
Via: SIP/2.0/UDP 184.106.130.224;received=184.106.130.224;rport=5060;branch=z9hG4bK01KKQK1Z46tNc
Max-Forwards: 53
From: "WIRELESS CALLER " sip:+15625551212@184.106.130.224;tag=9ZyvXeB8tQ9mg
To: sip:s@xx.xx.xx.xx:5060;received=184.72.227.214:5060
Call-ID: 340abee6-f242-122f-8d9e-40404edf54cf
CSeq: 26067042 INVITE
Contact: sip:mod_sofia@184.106.130.224:5060
User-Agent: FreeSWITCH-mod_sofia/1.0.4-hacked
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, MESSAGE, SUBSCRIBE, NOTIFY, REFER, UPDATE, REGISTER, INFO
Supported: precondition, path, replaces
Allow-Events: talk, refer
Privacy: none
Content-Type: application/sdp
Content-Disposition: session
Content-Length: 316
P-Asserted-Identity: "WIRELESS CALLER " sip:+15625551212@184.106.130.224

v=0
o=Sonus_UAC 26003 15518 IN IP4 192.168.47.68
s=SIP Media Capabilities
c=IN IP4 67.231.4.99
t=0 0
m=audio 20998 RTP/AVP 0 18 96 101
a=rtpmap:0 PCMU/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:96 iLBC/8000
a=fmtp:96 mode=30
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=maxptime:30
<------------->
[2012-03-26 16:57:13] VERBOSE[-1] app_macro.c: == Spawn extension (macro-exten-vm, s, 21) exited non-zero on ‘SIP/fpbx-2-bacctname-00000017’ in macro ‘exten-vm’
[2012-03-26 16:57:13] VERBOSE[-1] chan_sip.c: — (19 headers 14 lines) —
[2012-03-26 16:57:13] VERBOSE[-1] app_macro.c: == Spawn extension (macro-vm, s-CHANUNAVAIL, 2) exited non-zero on ‘SIP/fpbx-1-bacctname-00000019’ in macro ‘vm’
[2012-03-26 16:57:13] VERBOSE[-1] chan_sip.c: Ignoring this INVITE request
[2012-03-26 16:57:13] VERBOSE[-1] pbx.c: == Spawn extension (from-did-direct, 1014, 2) exited non-zero on ‘SIP/fpbx-2-bacctname-00000017’
[2012-03-26 16:57:13] VERBOSE[-1] chan_sip.c:
<— Transmitting (NAT) to 184.72.227.214:5060 —>
SIP/2.0 100 Trying
Via: SIP/2.0/UDP pb2proxy-pro-aws03.phonebooth.net;branch=z9hG4bK67dd.211ee075.0;received=184.72.227.214;rport=5060
Via: SIP/2.0/UDP 184.106.130.224;received=184.106.130.224;rport=5060;branch=z9hG4bK01KKQK1Z46tNc
Record-Route: sip:pb2proxy-pro-aws03.phonebooth.net:5060;lr=on;did=7a8.c103f456
From: "WIRELESS CALLER " sip:+15625551212@184.106.130.224;tag=9ZyvXeB8tQ9mg
To: sip:s@xx.xx.xx.xx:5060;received=184.72.227.214:5060
Call-ID: 340abee6-f242-122f-8d9e-40404edf54cf
CSeq: 26067042 INVITE
Server: FPBX-2.10.0(1.8.9.3)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
Contact: sip:5625552550@xx.xx.xx.xx:5060
Content-Length: 0

<------------>
[2012-03-26 16:57:13] VERBOSE[-1] pbx.c: – Executing [h@from-did-direct:1] Macro(“SIP/fpbx-2-bacctname-00000017”, “hangupcall,”) in new stack
[2012-03-26 16:57:13] VERBOSE[-1] chan_sip.c: Audio is at 18982
[2012-03-26 16:57:13] VERBOSE[-1] chan_sip.c: Adding codec 0x4 (ulaw) to SDP
[2012-03-26 16:57:13] VERBOSE[-1] chan_sip.c: Adding codec 0x100 (g729) to SDP
[2012-03-26 16:57:13] VERBOSE[-1] chan_sip.c: Adding non-codec 0x1 (telephone-event) to SDP
[2012-03-26 16:57:13] VERBOSE[-1] chan_sip.c:
<— Transmitting (NAT) to 184.72.227.214:5060 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP pb2proxy-pro-aws03.phonebooth.net;branch=z9hG4bK67dd.211ee075.0;received=184.72.227.214;rport=5060
Via: SIP/2.0/UDP 184.106.130.224;received=184.106.130.224;rport=5060;branch=z9hG4bK01KKQK1Z46tNc
Record-Route: sip:pb2proxy-pro-aws03.phonebooth.net:5060;lr=on;did=7a8.c103f456
From: "WIRELESS CALLER " sip:+15625551212@184.106.130.224;tag=9ZyvXeB8tQ9mg
To: sip:s@xx.xx.xx.xx:5060;received=184.72.227.214:5060;tag=as59522ff0
Call-ID: 340abee6-f242-122f-8d9e-40404edf54cf
CSeq: 26067042 INVITE
Server: FPBX-2.10.0(1.8.9.3)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
Contact: sip:5625552550@xx.xx.xx.xx:5060
Content-Type: application/sdp
Content-Length: 277

v=0
o=root 817371500 817371502 IN IP4 xx.xx.xx.xx
s=Asterisk PBX 1.8.9.3
c=IN IP4 xx.xx.xx.xx
t=0 0
m=audio 18982 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=ptime:20
a=sendrecv

<------------>
[2012-03-26 16:57:13] VERBOSE[-1] pbx.c: – Executing [s@macro-hangupcall:1] GotoIf(“SIP/fpbx-2-bacctname-00000017”, “1?theend”) in new stack
[2012-03-26 16:57:13] VERBOSE[-1] app_macro.c: == Spawn extension (macro-exten-vm, s, 21) exited non-zero on ‘SIP/fpbx-1-bacctname-00000019’ in macro ‘exten-vm’
[2012-03-26 16:57:13] VERBOSE[-1] pbx.c: – Goto (macro-hangupcall,s,3)
[2012-03-26 16:57:13] VERBOSE[-1] pbx.c: – Executing [s@macro-hangupcall:3] Hangup(“SIP/fpbx-2-bacctname-00000017”, “”) in new stack
[2012-03-26 16:57:13] VERBOSE[-1] pbx.c: == Spawn extension (from-did-direct, 1014, 2) exited non-zero on ‘SIP/fpbx-1-bacctname-00000019’
[2012-03-26 16:57:13] VERBOSE[-1] app_macro.c: == Spawn extension (macro-hangupcall, s, 3) exited non-zero on ‘SIP/fpbx-2-bacctname-00000017’ in macro ‘hangupcall’
[2012-03-26 16:57:13] VERBOSE[-1] pbx.c: – Executing [h@from-did-direct:1] Macro(“SIP/fpbx-1-bacctname-00000019”, “hangupcall,”) in new stack
[2012-03-26 16:57:13] VERBOSE[-1] pbx.c: == Spawn extension (from-did-direct, h, 1) exited non-zero on ‘SIP/fpbx-2-bacctname-00000017’
[2012-03-26 16:57:13] VERBOSE[-1] chan_sip.c: Scheduling destruction of SIP dialog ‘31fbf207-f242-122f-8d9e-40404edf54cf’ in 6400 ms (Method: INVITE)
[2012-03-26 16:57:13] VERBOSE[-1] pbx.c: – Executing [s@macro-hangupcall:1] GotoIf(“SIP/fpbx-1-bacctname-00000019”, “1?theend”) in new stack
[2012-03-26 16:57:13] VERBOSE[-1] pbx.c: – Goto (macro-hangupcall,s,3)
[2012-03-26 16:57:13] VERBOSE[-1] chan_sip.c: set_destination: Parsing sip:pb2proxy-pro-rsp03.phonebooth.net:5060;lr=on;did=5e9.edd8dcf5 for address/port to send to
[2012-03-26 16:57:13] VERBOSE[-1] pbx.c: – Executing [s@macro-hangupcall:3] Hangup(“SIP/fpbx-1-bacctname-00000019”, “”) in new stack
[2012-03-26 16:57:13] VERBOSE[-1] app_macro.c: == Spawn extension (macro-hangupcall, s, 3) exited non-zero on ‘SIP/fpbx-1-bacctname-00000019’ in macro ‘hangupcall’
[2012-03-26 16:57:13] VERBOSE[-1] pbx.c: == Spawn extension (from-did-direct, h, 1) exited non-zero on ‘SIP/fpbx-1-bacctname-00000019’
[2012-03-26 16:57:13] VERBOSE[-1] chan_sip.c: Scheduling destruction of SIP dialog ‘340abee6-f242-122f-8d9e-40404edf54cf’ in 6400 ms (Method: INVITE)
[2012-03-26 16:57:13] VERBOSE[-1] chan_sip.c: set_destination: Parsing sip:pb2proxy-pro-aws03.phonebooth.net:5060;lr=on;did=7a8.c103f456 for address/port to send to
[2012-03-26 16:57:13] VERBOSE[-1] chan_sip.c:
<— SIP read from UDP:192.168.0.52:11470 —>
SIP/2.0 200 OK
To: sip:1014@192.168.101.105:5060;tag=6f33c670886a4dei0
From: “Unknown” sip:Unknown@10.11.100.12;tag=as7664dfe9
Call-ID: 3554c696679b11a537fe705325d67cdd@10.11.100.12:5060

4

Looks like your responses are not reaching the caller.

5

I’m obviously a newb. When I set this up, I used the self configure string option in freepbx to add the phone numbers and trunks to the system through SIPSTATION. Pretty much after that I had some issues with the firewall and resolved them and was able to make in and out bound calls with any problems. Then over time, the system degraded to a point where I always get a fast busy signal on all inbound calls no matter what number they go to. I really can’t be much more out of the box than that.

I have the sip server sitting on the ORANGE network of an IPCOP firewall with port 5060 forwarded to the server but limited only the phonebooth.net IP addresses for the trunks and rtp ports 10001-20000 for everywhere. I had a problem with the firewall until I set rtp.conf to start using rtp at upperlimit=10001 as it’s default was to start at 10000. Then everything passed.

Now when you say it doesn’t look like my responses are not reaching the caller… where would the problem be. I see a communication path between my server and phonebooth.com. I’m getting the call notification which I think is on the line:
SIP read …
INVITE.
On the next group of instructions, it says

[quote=“ljr0”]<— Transmitting (NAT) to 184.72.227.214:5060 —>
SIP/2.0 100 Trying[/quote]
so it appears that I am sending …

Then I see a SIP/2.0 200 OK
Doesn’t this mean I have established communication? Where is it failing?

What bothers me is that I get this retransmission critical error…

But that timeout must be horrendously small sine according to the log, everything took place at 16:57:13. all within 1000ms.

How do I troubleshoot this?

Thanks

6

You are sending but the other side is not receiving. After checking that the destination and contact addresses are right, you need to debug this in your network, not in Asterisk.

7

When you say the other side is not receiving, is that the phone or the sip provider?

I’m registered to the sip provider so, obviously it must be receiving and the phone does ring. It just rings after the server sent a signal that the phone is busy.

8

I found the problem. I was forwarding TCP 5060 through the firewall.

When I originally set this up, I wasn’t forwarding 5060 through the firewall at all and it worked fine for several weeks. Once this problem showed up, I ran a firewall test through SIPSTATION and it failed, so I added 5060 but in order to secure that port from hacking, I added just the phonebooth.com servers to it’s ACL. Then the firewall test passed and I never looked back. I didn’t think it was the issue anyway because it worked without forwarding them at all before.

I found staring at my setup for hours on end sometimes makes the problem reveal itself and it worked this time as well. When I discovered I was forward TCP and changed it to UDP, the call and sound worked fine.

Thanks for your help.