Calls get terminated with "Nobody picked up in 300000ms"

Hi,

I went through forums and google searches and couldn’t find an anser.
All my incomming/outgoing calls get terminated after ca 5 minutes.
I really do not know where to search for this…

This is what log shows:

[Jun 6 12:44:01] DEBUG[12312] app_macro.c: Executed application: Set
[Jun 6 12:44:01] VERBOSE[12312] logger.c: – Executing [[email protected]:11] Set(“Zap/1-1”, "TRUNKOUTCID=“WE” ") in new stack
[Jun 6 12:44:01] DEBUG[12312] app_macro.c: Executed application: Set
[Jun 6 12:44:01] VERBOSE[12312] logger.c: – Executing [[email protected]:12] GotoIf(“Zap/1-1”, “1?trunkcid”) in new stack
[Jun 6 12:44:01] VERBOSE[12312] logger.c: – Goto (macro-outbound-callerid,s,16)
[Jun 6 12:44:01] DEBUG[12312] app_macro.c: Executed application: GotoIf
[Jun 6 12:44:01] VERBOSE[12312] logger.c: – Executing [[email protected]:16] GotoIf(“Zap/1-1”, “0?usercid”) in new stack
[Jun 6 12:44:01] DEBUG[12312] app_macro.c: Executed application: GotoIf
[Jun 6 12:44:01] VERBOSE[12312] logger.c: – Executing [[email protected]:17] Set(“Zap/1-1”, “CALLERID(all)=WE<>”) in new stack
[Jun 6 12:44:01] DEBUG[12312] app_macro.c: Executed application: Set
[Jun 6 12:44:01] VERBOSE[12312] logger.c: – Executing [[email protected]:18] GotoIf(“Zap/1-1”, “1?report”) in new stack
[Jun 6 12:44:01] VERBOSE[12312] logger.c: – Goto (macro-outbound-callerid,s,22)
[Jun 6 12:44:01] DEBUG[12312] app_macro.c: Executed application: GotoIf
[Jun 6 12:44:01] VERBOSE[12312] logger.c: – Executing [[email protected]:22] NoOp(“Zap/1-1”, "CallerID set to “WE” ") in new stack
[Jun 6 12:44:01] DEBUG[12312] app_macro.c: Executed application: Noop
[Jun 6 12:44:01] DEBUG[12312] app_macro.c: Executed application: Macro
[Jun 6 12:44:01] VERBOSE[12312] logger.c: – Executing [[email protected]:12] AGI(“Zap/1-1”, “fixlocalprefix”) in new stack
[Jun 6 12:44:01] VERBOSE[12312] logger.c: – Launched AGI Script /var/lib/asterisk/agi-bin/fixlocalprefix
[Jun 6 12:44:01] VERBOSE[12312] logger.c: – AGI Script fixlocalprefix completed, returning 0
[Jun 6 12:44:01] DEBUG[12312] app_macro.c: Executed application: AGI
[Jun 6 12:44:01] VERBOSE[12312] logger.c: – Executing [[email protected]:13] Set(“Zap/1-1”, “OUTNUM=xxxxx-DIALLED-NO-xxxxx”) in new stack
[Jun 6 12:44:01] DEBUG[12312] app_macro.c: Executed application: Set
[Jun 6 12:44:01] VERBOSE[12312] logger.c: – Executing [[email protected]:14] Set(“Zap/1-1”, “custom=ZAP/4”) in new stack
[Jun 6 12:44:01] DEBUG[12312] app_macro.c: Executed application: Set
[Jun 6 12:44:01] VERBOSE[12312] logger.c: – Executing [[email protected]:15] GotoIf(“Zap/1-1”, “1?gocall”) in new stack
[Jun 6 12:44:01] VERBOSE[12312] logger.c: – Goto (macro-dialout-trunk,s,17)
[Jun 6 12:44:01] DEBUG[12312] app_macro.c: Executed application: GotoIf
[Jun 6 12:44:01] VERBOSE[12312] logger.c: – Executing [[email protected]:17] Macro(“Zap/1-1”, “dialout-trunk-predial-hook|”) in new stack
[Jun 6 12:44:01] WARNING[12312] app_macro.c: Context ‘macro-dialout-trunk-predial-hook’ for macro ‘dialout-trunk-predial-hook’ lacks ‘s’ extension, priority 1
[Jun 6 12:44:01] DEBUG[12312] app_macro.c: Executed application: Macro
[Jun 6 12:44:01] VERBOSE[12312] logger.c: – Executing [[email protected]:18] GotoIf(“Zap/1-1”, “0?bypass|1”) in new stack
[Jun 6 12:44:01] DEBUG[12312] app_macro.c: Executed application: GotoIf
[Jun 6 12:44:01] VERBOSE[12312] logger.c: – Executing [[email protected]:19] GotoIf(“Zap/1-1”, “0?customtrunk”) in new stack
[Jun 6 12:44:01] DEBUG[12312] app_macro.c: Executed application: GotoIf
[Jun 6 12:44:01] VERBOSE[12312] logger.c: – Executing [[email protected]:20] Dial(“Zap/1-1”, “ZAP/4/xxxxx-DIALLED-NO-xxxxx|300|t”) in new stack
[Jun 6 12:44:01] DEBUG[12312] chan_zap.c: Dialing ‘xxxxx-DIALLED-NO-xxxxx’
[Jun 6 12:44:01] DEBUG[12312] chan_zap.c: Deferring dialing…
[Jun 6 12:44:01] VERBOSE[12312] logger.c: – Called 4/xxxxx-DIALLED-NO-xxxxx
[Jun 6 12:44:05] DEBUG[12312] chan_zap.c: Engaged echo training on channel 4
[Jun 6 12:44:07] DEBUG[12312] chan_zap.c: Echo cancellation already on
[Jun 6 12:49:25] VERBOSE[12312] logger.c: – Nobody picked up in 300000 ms
[Jun 6 12:49:25] VERBOSE[12312] logger.c: – Hungup ‘Zap/4-1’
[Jun 6 12:49:25] DEBUG[12312] app_macro.c: Executed application: Dial
[Jun 6 12:49:25] VERBOSE[12312] logger.c: – Executing [[email protected]:21] Goto(“Zap/1-1”, “s-NOANSWER|1”) in new stack
[Jun 6 12:49:25] VERBOSE[12312] logger.c: – Goto (macro-dialout-trunk,s-NOANSWER,1)
[Jun 6 12:49:25] DEBUG[12312] app_macro.c: Executed application: Goto
[Jun 6 12:49:25] VERBOSE[12312] logger.c: – Executing [[email protected]:1] NoOp(“Zap/1-1”, “Dial failed due to trunk reporting NOANSWER - giving up”) in new stack
[Jun 6 12:49:25] DEBUG[12312] app_macro.c: Executed application: Noop
[Jun 6 12:49:25] VERBOSE[12312] logger.c: – Executing [[email protected]:2] PlayTones(“Zap/1-1”, “congestion”) in new stack
[Jun 6 12:49:25] DEBUG[12312] app_macro.c: Executed application: Playtones
[Jun 6 12:49:25] VERBOSE[12312] logger.c: – Executing [[email protected]:3] Congestion(“Zap/1-1”, “20”) in new stack
[Jun 6 12:49:29] VERBOSE[12312] logger.c: == Spawn extension (macro-dialout-trunk, s-NOANSWER, 3) exited non-zero on ‘Zap/1-1’ in macro ‘dialout-trunk’
[Jun 6 12:49:29] VERBOSE[12312] logger.c: == Spawn extension (macro-dialout-trunk, s-NOANSWER, 3) exited non-zero on ‘Zap/1-1’
[Jun 6 12:49:29] VERBOSE[12312] logger.c: – Executing [[email protected]:1] Macro(“Zap/1-1”, “hangupcall|”) in new stack
[Jun 6 12:49:29] VERBOSE[12312] logger.c: – Executing [[email protected]:1] ResetCDR(“Zap/1-1”, “w”) in new stack

In the log, you dial ZAP/4, which implies a single (analog?) line, but there is in the log a Hungup ‘Zap/4-1’, which seems to denote a channel with multiple ports, like a PRI line.

From http://www.voip-info.org/wiki/index.php?page=Asterisk+Zap+channels

chanspec: specifies which Zap channel or channel group, as defined in the configuration file, you want to use. It can be one of three types:

  • one of the letters g, G, r, or R followed by a Zap channel group number. See “Dialing a Group”, below.
  • for analog Zap interfaces: a simple channel number. Example: 1 means Zap channel 1.
  • for PRI Zap interfaces: a span number, then a hyphen, then a port number. Example: 1-2 means Zap span 1, port 2.

this should be only outgoing calls. All outgoing calls are set to ring for 5 minutes, if the channel is not answered within 5 minutes it will terminate. This can happen if you were calling a destination that operated on early media for an extended period of time without ever answering the channel, which is only possible on a digital channel such as a PRI or SIP channel. Alternatively, if you are trying to detect progress tones on an analog zap channel and that is not working properly, I think this could happen. Detecting progress tones is very experimental and un-reliable. If this happens on all calls, I suspect it is something like that and you need to change those zapata configuration parameters.

I have just one analog TDM400P22 card with 2 FXS (channel 1-2) and 2 FXO (channel 3-4).

When I pick up an extension or a trunk is choosen by asterisk this multiport switch part “-1” is always added.

For example:

Picking up telephone on extension 1 or 2:

-- Starting simple switch on 'Zap/1-1'
-- Hungup 'Zap/1-1'
-- Starting simple switch on 'Zap/2-1'
-- Hungup 'Zap/2-1'

Receiving a call on channel 4:

-- Starting simple switch on 'Zap/4-1'
-- Executing [[email protected]:1] NoOp("Zap/4-1", "Entering from-zaptel with DID == ") in new stack
-- Executing [[email protected]:2] Ringing("Zap/4-1", "") in new stack
-- Executing [[email protected]:3] Set("Zap/4-1", "DID=s") in new stack
-- Executing [[email protected]:4] NoOp("Zap/4-1", "DID is now s") in new stack
-- Executing [[email protected]:5] GotoIf("Zap/4-1", "1?zapok:notzap") in new stack
-- Goto (from-zaptel,s,8)
-- Executing [[email protected]:8] NoOp("Zap/4-1", "Is a Zaptel Channel") in new stack
-- Executing [[email protected]:9] Set("Zap/4-1", "CHAN=4-1") in new stack
-- Executing [[email protected]:10] Set("Zap/4-1", "CHAN=4") in new stack
-- Executing [[email protected]:11] Macro("Zap/4-1", "from-zaptel-4|s|1") in new stack

*CLI> zap show channels
Chan Extension Context MOH Interpret
pseudo from-zaptel default
1 from-internal default
2 from-internal default
3 from-zaptel default
4 from-zaptel default

My config is following:

[]# cat /etc/zaptel.conf
fxoks=1
fxoks=2
fxsks=3
fxsks=4

[]# cat /etc/asterisk/zapata.conf

[channels]

; include zap extensions defined in AMP
#include zapata_additional.conf

answeronpolarityswitch=yes
hanguponpolarityswitch=yes
immediate=yes

;context=from-pstn
context=from-zaptel
signalling=fxs_ks
faxdetect=incoming
usecallerid=yes
callerid=asreceived
echocancel=yes
callprogress=no
busydetect=no
echocancelwhenbridged=no
echotraining=800
;group=0
channel=3

context=from-zaptel
signalling=fxs_ks
faxdetect=incoming
usecallerid=yes
callerid=asreceived
echocancel=yes
callprogress=no
busydetect=no
echocancelwhenbridged=no
echotraining=800
;group=0
channel=4

Thanks a lot for your help.

I’m not trying to do anything fancy (at least not that I would know of) - it’s just basic FreePBX setup and I probably made some config mistake and just do not know where to look for it.

All regular ZAP calls (incomming and outgoing) get cut after ca 5 min. I’m not even checking any SIP to ZAP calls nor PRI (as I do not have a PRI card).

Not sure if it’s connected in any way but I’m also unable to transfer calls from one extension to another. Flash or hold buttons on telephone don’t have any effect during a call and only double # works.

Basically I have left all default FreePBX settings and have just configured 4 ZAP channels and incomming/outgoing routes.

Still can’t get it to work properly ;(
Outgoing calls are being cut off after those 5 minutes…
Incomming calls are fine.
Can you point me where should I start looking to fix this problem?

Where can I at least change this timeout setting to make it longer?

In your log, you see a line

[Jun 6 12:44:01] VERBOSE[12312] logger.c: – Executing [[email protected]:20] Dial(“Zap/1-1”, “ZAP/4/xxxxx-DIALLED-NO-xxxxx|300|t”) in new stack

Where the 300 is the timeout

If you look at macro-dialout-trunk, s, priority 20, you see

exten => s,n,Dial(${OUT_${DIAL_TRUNK}}/{OUTNUM},300,${DIAL_OUT_OPTIONS})

Which you could change (WARNING: changes standard FreePbx file, use at your own risk!) in

exten => s,n,Dial(${OUT_${DIAL_TRUNK}}/{OUTNUM},${DIAL_OUT_OPTIONS})

Basicly, since the call progress monitoring on the analog line is still experimental and unreliable, it looks like Asterisk doesn’t ‘hear’ the phone being picked up, assumes it is still ringing, and thereford acts as it supposed to after the time out. When you remove the time out, Asterisk has no reason to terminate the call.

Please note that this change would cause outgoing calls to never time out. This might cause problems if asterisk also fails to recognize when the call is tertminated and keeps the line open indefinately. I am not sure if Asterisk determines call terminating by '‘listening’ to the line as well.

Assuming this is a quality Zap card (e.g. from a vendor like Digium, Sangoma, Rhino, Pika, …) you should be able to contact their support and work with them to get your zapata.conf configurations set properly, their support should be included with the card purchase. The FXO card shoud be answering the line immediately and if it is not, you could encounter other problems. I suggest you take advantage of that support from the vendors. That is where you problem is. Changing the timeout is not a good option as it avoids fixing the real problem.

Hanke,

You don’t say what country you are in, but the default setup for zaptel cards is US based and if you are not in the US it might not be seeing the proper line signaling which would also cause this issue. So if you are in a different country please check on proper setup for zaptel drivers for your country and telco service. UK service for example needs special settings.

Thank’s a lot for your help…

This is a OpenVox A400P22 and I’m trying to set this card to work in polish zone - have 2 setups working in Germany ok.
loadzone and defaultzone are set to pl, there’s country = pl in indications.conf

Philippe wrote: "The FXO card shoud be answering the line immediately and if it is not, you could encounter other problems."
My asterisk notices incomming calls with some delay - ie:

  • when someone calls in I can hear rings on this line with a phone attached directly to this line. But Asterisk notices it ca 2 seconds later.
    When the caller hangs up asterisk rings the extension slightly longer than the phone connected directly…

Nevertheless I’ll try to get some help from card vendor and will post results here.

for incoming it will wait a bit to get the CID. I am referring to outgoing calls, as soon as you do the Dial() the card should be answering. If not, something is not configured correctly, and that is what is creating you 300 second issue.

I’ll bet that you need to set some special value besides those two lines for Poland. Check here http://www.voipinfo.org/wiki/view/Asterisk+config+indications.conf to start. Like I said earier there is a additional special setting that is needed for the UK and I can’t remember what it was, something in the /etc/modprobe.conf file for zaptel or was it something special in the /etc/sysconfig/zaptel file. I can’t find it quickly. but it told the driver to do something on load that made it act differently. So might be same for you.

Found it. try this…

in /etc/modprobe.conf add
options wctdm opermode=pl

See page 16 at http://www.novavox.co.uk/docs/install-guides/novavox-asterisk-card-installation-issues.pdf and/or search for “options wctdm opermode=”

You’ll find referances to the info here for the UK http://www.voipuser.org/forum_topic_2743.html but it is basicly the same thing for other countries that do not use the US FCC singnaling standards.

You’re great :slight_smile: thanks a lot for support!

It looks like a callprogress=yes messes things up…
I’ve had it on and that was the source of problems… After switching it back to no calls seem to just last… :slight_smile:

Just to quote Voip-info wiki:
"The callprogress feature is highly experimental and can easily detect false answers, so don’t count on it being very accurate. Also, it is currently configured only for standard U.S. phone tones. Default: no"
So the answer to my whole problem seems to be RTFM…

Funny as I have been switching it off and on before with no luck. In the meantime I have added opermode option to wctdm (it takes a country full name, so it should be opermode=POLAND in this case).

So once again Muchos Gracias Signores :slight_smile: