Group with External Line hangs up at 20 seconds, regardless of a line being answered

wdbarker3 · October 8, 2011, 12:39pm

Environment: FreePBX 2.9.0.7, Asterisk 1.8.6.0, Trunk provider CallCentric, Hardware ESXi 4.1 VM with 1 vCPU, 384 MB ram.

Setup: Simple Ring Group of my extension and my cell with music on hold. From an outside line, I call in to an IVR and route to the group. I answer on the cell. Call is terminated at 20 seconds. (Date and Hour stripped off the log, cellphone number changed to 6785551212).

51:21] VERBOSE[17487] netsock2.c:   == Using SIP RTP TOS bits 184
51:21] VERBOSE[17487] netsock2.c:   == Using SIP RTP CoS mark 5
51:21] VERBOSE[17487] app_dial.c:     -- Called SIP/callcentric/16785551212
51:21] VERBOSE[17485] app_dial.c:     -- SIP/347-00000045 is ringing
51:23] VERBOSE[17487] app_dial.c:     -- SIP/callcentric-00000046 is ringing
51:23] VERBOSE[17485] app_dial.c:     -- Local/6785551212@from-internal-8ef6;1 is ringing
51:23] VERBOSE[17487] app_dial.c:     -- SIP/callcentric-00000046 is ringing
51:24] VERBOSE[17487] app_dial.c:     -- SIP/callcentric-00000046 is ringing
51:26] VERBOSE[17487] app_dial.c:     -- SIP/callcentric-00000046 is ringing
51:30] VERBOSE[17487] app_dial.c:     -- SIP/callcentric-00000046 is ringing
51:31] VERBOSE[17487] app_dial.c:     -- SIP/callcentric-00000046 answered Local/6785551212@from-internal-8ef6;2
51:31] VERBOSE[17485] app_dial.c:     -- Local/6785551212@from-internal-8ef6;1 answered SIP/66.193.176.35-00000044
51:31] VERBOSE[17485] pbx.c:     -- Executing [s@macro-auto-blkvm:1] Set("Local/6785551212@from-internal-8ef6;1", "__MACRO_RESULT=") in new stack
51:31] VERBOSE[17485] pbx.c:     -- Executing [s@macro-auto-blkvm:2] Macro("Local/6785551212@from-internal-8ef6;1", "blkvm-clr,") in new stack
51:31] VERBOSE[17485] pbx.c:     -- Executing [s@macro-blkvm-clr:1] Set("Local/6785551212@from-internal-8ef6;1", "SHARED(BLKVM,SIP/66.193.176.35-00000044)=") in new stack
51:31] VERBOSE[17485] pbx.c:     -- Executing [s@macro-blkvm-clr:2] Set("Local/6785551212@from-internal-8ef6;1", "GOSUB_RETVAL=") in new stack
51:31] VERBOSE[17485] pbx.c:     -- Executing [s@macro-blkvm-clr:3] MacroExit("Local/6785551212@from-internal-8ef6;1", "") in new stack
51:31] VERBOSE[17485] pbx.c:     -- Executing [s@macro-auto-blkvm:3] Set("Local/6785551212@from-internal-8ef6;1", "MASTER_CHANNEL(CONNECTEDLINE(num))=6785551212@from-internal/n") in new stack
51:31] VERBOSE[17485] pbx.c:     -- Executing [s@macro-auto-blkvm:4] Set("Local/6785551212@from-internal-8ef6;1", "MASTER_CHANNEL(CONNECTEDLINE(name))=") in new stack
51:31] VERBOSE[17485] res_musiconhold.c:     -- Stopped music on hold on SIP/66.193.176.35-00000044
51:52] VERBOSE[17485] pbx.c:     -- Executing [h@macro-dial:1] Macro("SIP/66.193.176.35-00000044", "hangupcall") in new stack
51:52] VERBOSE[17485] pbx.c:     -- Executing [s@macro-hangupcall:1] GotoIf("SIP/66.193.176.35-00000044", "1?theend") in new stack
51:52] VERBOSE[17485] pbx.c:     -- Goto (macro-hangupcall,s,3)
51:52] VERBOSE[17485] pbx.c:     -- Executing [s@macro-hangupcall:3] Hangup("SIP/66.193.176.35-00000044", "") in new stack
51:52] VERBOSE[17485] app_macro.c:   == Spawn extension (macro-hangupcall, s, 3) exited non-zero on 'SIP/66.193.176.35-00000044' in macro 'hangupcall'
51:52] VERBOSE[17485] features.c:   == Spawn extension (macro-dial, h, 1) exited non-zero on 'SIP/66.193.176.35-00000044'
51:52] VERBOSE[17485] app_macro.c:   == Spawn extension (macro-dial, s, 7) exited non-zero on 'SIP/66.193.176.35-00000044' in macro 'dial'
51:52] VERBOSE[17485] pbx.c:   == Spawn extension (ext-group, 647, 12) exited non-zero on 'SIP/66.193.176.35-00000044'
51:52] VERBOSE[17487] pbx.c:     -- Executing [h@macro-dialout-trunk:1] Macro("Local/6785551212@from-internal-8ef6;2", "hangupcall,") in new stack
51:52] VERBOSE[17487] pbx.c:     -- Executing [s@macro-hangupcall:1] GotoIf("Local/6785551212@from-internal-8ef6;2", "1?theend") in new stack
51:52] VERBOSE[17487] pbx.c:     -- Goto (macro-hangupcall,s,3)
51:52] VERBOSE[17487] pbx.c:     -- Executing [s@macro-hangupcall:3] Hangup("Local/6785551212@from-internal-8ef6;2", "") in new stack
51:52] VERBOSE[17487] app_macro.c:   == Spawn extension (macro-hangupcall, s, 3) exited non-zero on 'Local/6785551212@from-internal-8ef6;2' in macro 'hangupcall'
51:52] VERBOSE[17487] features.c:   == Spawn extension (macro-dialout-trunk, h, 1) exited non-zero on 'Local/6785551212@from-internal-8ef6;2'
51:52] VERBOSE[17487] app_macro.c:   == Spawn extension (macro-dialout-trunk, s, 20) exited non-zero on 'Local/6785551212@from-internal-8ef6;2' in macro 'dialout-trunk'
51:52] VERBOSE[17487] pbx.c:   == Spawn extension (from-internal, 6785551212, 5) exited non-zero on 'Local/6785551212@from-internal-8ef6;2'

Setup: Same setup. From an outside line, I call in to an IVR and route to the group. I answer on the local extension. Call is terminated at 20 seconds.

07:14] VERBOSE[18088] netsock2.c:   == Using SIP RTP TOS bits 184
07:14] VERBOSE[18088] netsock2.c:   == Using SIP RTP CoS mark 5
07:14] VERBOSE[18088] app_dial.c:     -- Called SIP/callcentric/16785551212
07:14] VERBOSE[18086] app_dial.c:     -- SIP/347-0000004b is ringing
07:16] VERBOSE[18088] app_dial.c:     -- SIP/callcentric-0000004c is making progress passing it to Local/6785551212@from-internal-657a;2
07:16] VERBOSE[18086] app_dial.c:     -- Local/6785551212@from-internal-657a;1 is making progress passing it to SIP/66.193.176.35-0000004a
07:17] VERBOSE[18088] app_dial.c:     -- SIP/callcentric-0000004c is making progress passing it to Local/6785551212@from-internal-657a;2
07:17] VERBOSE[18086] app_dial.c:     -- Local/6785551212@from-internal-657a;1 is making progress passing it to SIP/66.193.176.35-0000004a
07:17] VERBOSE[18086] app_dial.c:     -- SIP/347-0000004b connected line has changed. Saving it until answer for SIP/66.193.176.35-0000004a
07:17] VERBOSE[18086] app_dial.c:     -- SIP/347-0000004b answered SIP/66.193.176.35-0000004a
07:17] VERBOSE[18086] pbx.c:     -- Executing [s@macro-auto-blkvm:1] Set("SIP/347-0000004b", "__MACRO_RESULT=") in new stack
07:17] VERBOSE[18086] pbx.c:     -- Executing [s@macro-auto-blkvm:2] Macro("SIP/347-0000004b", "blkvm-clr,") in new stack
07:17] VERBOSE[18086] pbx.c:     -- Executing [s@macro-blkvm-clr:1] Set("SIP/347-0000004b", "SHARED(BLKVM,SIP/66.193.176.35-0000004a)=") in new stack
07:17] VERBOSE[18086] pbx.c:     -- Executing [s@macro-blkvm-clr:2] Set("SIP/347-0000004b", "GOSUB_RETVAL=") in new stack
07:17] VERBOSE[18086] pbx.c:     -- Executing [s@macro-blkvm-clr:3] MacroExit("SIP/347-0000004b", "") in new stack
07:17] VERBOSE[18086] pbx.c:     -- Executing [s@macro-auto-blkvm:3] Set("SIP/347-0000004b", "MASTER_CHANNEL(CONNECTEDLINE(num))=347") in new stack
07:17] VERBOSE[18086] pbx.c:     -- Executing [s@macro-auto-blkvm:4] Set("SIP/347-0000004b", "MASTER_CHANNEL(CONNECTEDLINE(name))=Dan Barker") in new stack
07:17] VERBOSE[18088] app_macro.c:   == Spawn extension (macro-dialout-trunk, s, 20) exited non-zero on 'Local/6785551212@from-internal-657a;2' in macro 'dialout-trunk'
07:17] VERBOSE[18088] pbx.c:   == Spawn extension (from-internal, 6785551212, 5) exited non-zero on 'Local/6785551212@from-internal-657a;2'
07:17] VERBOSE[18088] pbx.c:     -- Executing [h@from-internal:1] Hangup("Local/6785551212@from-internal-657a;2", "") in new stack
07:17] VERBOSE[18088] pbx.c:   == Spawn extension (from-internal, h, 1) exited non-zero on 'Local/6785551212@from-internal-657a;2'
07:17] VERBOSE[18086] res_musiconhold.c:     -- Stopped music on hold on SIP/66.193.176.35-0000004a
07:37] VERBOSE[18086] pbx.c:     -- Executing [h@macro-dial:1] Macro("SIP/66.193.176.35-0000004a", "hangupcall") in new stack
07:37] VERBOSE[18086] pbx.c:     -- Executing [s@macro-hangupcall:1] GotoIf("SIP/66.193.176.35-0000004a", "1?theend") in new stack
07:37] VERBOSE[18086] pbx.c:     -- Goto (macro-hangupcall,s,3)
07:37] VERBOSE[18086] pbx.c:     -- Executing [s@macro-hangupcall:3] Hangup("SIP/66.193.176.35-0000004a", "") in new stack
07:37] VERBOSE[18086] app_macro.c:   == Spawn extension (macro-hangupcall, s, 3) exited non-zero on 'SIP/66.193.176.35-0000004a' in macro 'hangupcall'
07:37] VERBOSE[18086] features.c:   == Spawn extension (macro-dial, h, 1) exited non-zero on 'SIP/66.193.176.35-0000004a'
07:37] VERBOSE[18086] app_macro.c:   == Spawn extension (macro-dial, s, 7) exited non-zero on 'SIP/66.193.176.35-0000004a' in macro 'dial'
07:37] VERBOSE[18086] pbx.c:   == Spawn extension (ext-group, 647, 12) exited non-zero on 'SIP/66.193.176.35-0000004a'

Note: If allowed to fall through to voicemail, the voicemail will continue for as long as the caller keeps talking.

[code]Trunk:
host=callcentric.com
secret=SUPERSECRET
type=peer
context=from-sip-external-custom
fromdomain=callcentric.com
fromuser=17775551212
insecure=port,invite
defaultuser=17775551212

Asterisk SIP Settings:
NAT, SRV Lookup(enabled), sendrpid(yes), trustrpid(n0), context(from-sip-external-custom)

[from-sip-external-custom]
; Hack for CallCentric not to appear unknown
exten => _.,1,NoOp(Received incoming SIP connection from unknown peer to ${EXTEN})
exten => _.,n,Set(DID=${IF($["${EXTEN:1:2}"=""]?s:${EXTEN})})
exten => _.,n,Goto(s,1)
exten => s,1,GotoIf($["${DID}"!=“17775551212”]?from-sip-external,${DID},1)
exten => s,n,Set(MYVAR=${SIP_HEADER(TO):5})
exten => s,n,Set(DID=${MYVAR:0:11})
exten => s,n,Goto(from-pstn,${DID},1)
exten => h,1,Macro(hangupcall)

[/code]

alan · October 8, 2011, 1:12pm

This sounds like a firewall problem. Perhaps your routed is dropping the RTP stream.

wdbarker3 · October 8, 2011, 1:50pm

I did a tcpdump on both the inside (eth1) and outside (eth2) of the firewall. There were about 6,000 RTP packets on each. I spot checked a few of them and they all passed the firewall OK.

I was under the impression that if I had 2-way audio my firewall was working. I certainly do have 2-way audio! Everything is working exactly as I want except Follow Me.

I’m using groups only because they are simpler and exhibit the same issue. If there are other packets the firewall might not be handling, I certainly would like to know about that! I understood that all the new asterisk versions were NAT friendly and didn’t need any firewall updates. In my case, none have been necessary to get this all working except Follow Me.

AdHominem · October 9, 2011, 2:44am

I would contact Callcentric support. I use Callcentric without the hack you show, and with a hack that they recommend to sip_general_custom.conf which you aren’t using, but which may be duplicated in the Advanced SIP Settings you use, and I do not have this problem.

SkykingOH · October 9, 2011, 5:19am

The 20 seconds is the Asterisk RTP default timeout. I doubt callcentric will be of any help.

If you use the RTP debug command you should be able to sort this out. It will be a NAT setting issue.

wdbarker3 · October 9, 2011, 12:04pm

Would you please share with the group the modification you made in sip_general_custom.conf? I, for one, would appreciate it.

UPDATE:

I removed from-sip-external-custom (replacing with from-pstn) and retested. Everything failed in the same way as with that dialplan in use, but inbound DID routing didn’t work (this code is nowhere near the outbound timer/answered/groups code).

I put from-sip-external-custom back.

wdbarker3 · October 9, 2011, 11:45am

Since all the RTP packets from the outside pass through the firewall to the asterisk box, and all the RTP packets from the asterisk box pass through the firewall to the appropriate destination, for what would I look in my RTP traces? The audio is fine, in both directions.

SkykingOH · October 9, 2011, 6:28pm


Anomalous behavior right before it fails.  Watch, it will be very clear.

I will bet you a fine steak  this is a firewall problem (assuming you have your externip and localnet settings correct in the SIP settings module).

Anomalous behavior right before it fails. Watch, it will be very clear.

I will bet you a fine steak this is a firewall problem (assuming you have your externip and localnet settings correct in the SIP settings module).

wdbarker3 · October 9, 2011, 8:40pm

I see a series of RTP messages, a “Got From” and a “Sent To” approximately alternating. They are From/To both Callcentric and the IP Phone. There are about 50 of each per second while the connection stays up, and then asterisk takes down the connection with " – Executing [h@macro-dial:1] Macro(“SIP/66.193.176.35-00000029”, “hangupcall”) in new stack". I don’t know how to look for something anomalous as you have not described any specific behavior.

Please, have a look. A trace is at ftp.visioncomm.com, anonymous, get full.zip. Another set of eyes will be quite welcome.

And yes, My NAT settings match my setup. My External IP is correct. My internal IPs are 172.30.0.190 is the Freepbx box and 172.30.0.191 is the Polycom IP321. 7775551212 is my Callcentric Account, 6785551212 is the external line calling in and 6781212555 is my cellphone.

obelisk · October 9, 2011, 9:49pm

Callcentric wants you to disable session timers, more details on their asterisk page:

http://www.callcentric.com/support/device/asterisk/1_6

SkykingOH · October 9, 2011, 11:01pm

You can try callcentrics solution, just use the sip config module, don’t edit the files directly.

wdbarker3 · October 10, 2011, 1:07am

I found suggestions for those settings in http://www.callcentric.com/support/device/freepbx earlier, but since they didn’t change the symptoms in any way, I had removed them.

session-timers refuse
session-expires 180
session-minse 90
session-refresher uas

I put them back in using Asterisk SIP Settings under Other SIP Settings. FreePBX placed them in /etc/asterisk/sip_general_additional.conf. I believe that is the correct spot, however, my system still hangs up at 20 seconds, even if I answer. I’ll leave the session timer settings in place for now.

SkykingOH · October 10, 2011, 2:23am

I still have the steak on your firewall.

What kind of firewall is it? Do you have all types of SIP/NAT/RTP helper or other transforms turned off?

wdbarker3 · October 10, 2011, 10:39am

Linux from scratch 6.3, Kernel 2.6.27.4, ipv4/ip_forward.

Identical results with/without the following:

iptables -t nat -I PREROUTING 1 -p udp -m udp -m multiport --dports sip,10000:20000 -d 76.97.152.43 -j DNAT --to-destination 172.30.0.190

Ummmm. I’m getting hungry for some steak.

wdbarker3 · October 10, 2011, 3:02pm

That rule is a port-forward rule, for inbound traffic to find my FreePBX, if I had any extensions outside the firewall (which I don’t). The problem symptoms are identical with or without that rule in place. It is normally not there but was included for illustration.

Let’s drop this thread about the firewall. You “feel” it is the firewall, but can’t point to any missing traffic in the trace nor any items for me to look for other than anomalous - which doesn’t really mean anything.

I appreciate your efforts on my behalf, but I need a response with some concrete solution or debugging steps. I don’t believe firewall is a part of this problem and can only be convinced otherwise by sniffer traces or other concrete debugging steps. “Feelings” are not the way to debug datacomm issues.

I still may want that steak, however.

SkykingOH · October 10, 2011, 2:51pm

I have never use the NAT in iptables.

This looks like a port forward rule. I am thinking you have asymmetric NAT and one side of the xlate is being closed in the session.

SkykingOH · October 10, 2011, 3:10pm

Sorry my feelings are useless, let me be more businesslike.

Every time I have seen the 20 second disconnect problem it is caused be one of the following:

1 - Misconfigured sip nat settings in Aserisk
2 - Firewall issues

Take your call centric trunk out of the picture. Try a softphone from the outside and play a message that is more than 20 seconds long.

wdbarker3 · October 10, 2011, 3:29pm

You sound so certain. Let’s play some more. Please remember, I am very new to asterisk. Setting up CallCentric without the “anonymous” setting took a bit of research, then getting it to route inbound DIDs to different IVRs took a hack and don’t get me started on the quality of the doc to make a Polyphone IP321 load it’s brains from the FreePBX FTP server! Now everything I’ve tried is working flawlessly except this one feature (and one message in error).

Do you have the time to explain how I might “Try a softphone from the outside”? My guess (I’d rather not guess) is to put that port forward rule back into my firewall, connect my laptop to the WAN switch and run X-Lite on it, and connect to FreePBX as an Extension. Then leave myself a 45 second message and then have Comedian play it back. You may mean something completely different.

As to “Misconfigured sip nat settings”. Please correct me if I’m wrong. There are only 4 things to set. The “External” IP, that it is static, the Internal Network and the fact that there is a NAT firewall in play. I have “Yes”, “Static”, “76.97.152.43” and “172.30.0.0 255.255.255.0”.

SkykingOH · October 10, 2011, 3:40pm

It’s not playing, you indicated little experience yet you are dismissive of network issues.

So yes, put the rule back in for 5060 UDP and 10000-20000 UDP, take x-lite off net and try to register to 76.97.152.43

Have a conversation with another extension or play one of the built in messages that is longer than 20 seconds. Does not matter. Dial *60 and listen to the time a few times.

wdbarker3 · October 10, 2011, 4:04pm

I can’t believe I hit submit before I finished my last reply. I wanted to be absolutely certain I was not in error about my NAT setup BEFORE I hit submit. You see, I have two WAN subnets. So, I did my test with a sniffer on the WAN side on the “wrong” ethernet card and there was zero traffic from Callcentric. Good - sanity check 1 passed. Then, I ran that same sniffer filter (tcpdump -i eth2 net 204.11.192.0/24) on the correct ethernet card and I noticed that the first “anomalous” traffic was FROM Callcentric:

...
Thousands of these
...
11:45:32.533596 IP alpha1.callcentric.com.49866 > c-76-97-152-43.hsd1.ga.comcast.net.10584: UDP, length 172
11:45:32.545011 IP c-76-97-152-43.hsd1.ga.comcast.net.10584 > alpha1.callcentric.com.49866: UDP, length 172
11:45:32.553700 IP alpha1.callcentric.com.49866 > c-76-97-152-43.hsd1.ga.comcast.net.10584: UDP, length 172
11:45:32.565043 IP c-76-97-152-43.hsd1.ga.comcast.net.10584 > alpha1.callcentric.com.49866: UDP, length 172
11:45:32.569963 IP alpha1.callcentric.com.49866 > c-76-97-152-43.hsd1.ga.comcast.net.10584: UDP, length 172
11:45:32.585016 IP c-76-97-152-43.hsd1.ga.comcast.net.10584 > alpha1.callcentric.com.49866: UDP, length 172
... and then, at the point it hung up on me ...
11:45:32.585110 IP alpha1.callcentric.com.sip > c-76-97-152-43.hsd1.ga.comcast.net.sip: SIP, length: 285

I was VERY curious what that SIP packet was all about so I repeated the sniffer with more details:

3791	37.417100	204.11.192.34	76.97.152.43	SIP	Status: 408 Request Timeout

That packet is Callcentric hanging up on me. I need to review my reservation and be certain FreePBX is passing, or open a ticket with Callcentric and find out why they are ignoring,

session-timers=refuse
session-expires=180
session-minse=90
session-refresher=uas

Do you concur?

BTW, I am VERY experienced in NAT, firewalls, routing and network traffic, I am inexperienced in asterisk.