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

Hello,

I have a permanent problem with my A400P22.
All my outgoing calls are terminated after default timeout (300sec)

I have searched through forums but wasn't able to find any solution to this.
Where can I look to troubleshoot this problem?


This is what I see in Asterisk log:

This is what log shows:

[Jun 6 12:44] DEBUG[12312] app_macro.c: Executed application: Set
[Jun 6 12:44] VERBOSE[12312] logger.c: -- Executing [s@macro-outbound-callerid] Set("Zap/1-1", "TRUNKOUTCID="WE" ") in new stack
[Jun 6 12:44] DEBUG[12312] app_macro.c: Executed application: Set
[Jun 6 12:44] VERBOSE[12312] logger.c: -- Executing [s@macro-outbound-callerid] GotoIf("Zap/1-1", "1?trunkcid") in new stack
[Jun 6 12:44] VERBOSE[12312] logger.c: -- Goto (macro-outbound-callerid,s,16)
[Jun 6 12:44] DEBUG[12312] app_macro.c: Executed application: GotoIf
[Jun 6 12:44] VERBOSE[12312] logger.c: -- Executing [s@macro-outbound-callerid] GotoIf("Zap/1-1", "0?usercid") in new stack
[Jun 6 12:44] DEBUG[12312] app_macro.c: Executed application: GotoIf
[Jun 6 12:44] VERBOSE[12312] logger.c: -- Executing [s@macro-outbound-callerid] Set("Zap/1-1", "CALLERID(all)=WE<>") in new stack
[Jun 6 12:44] DEBUG[12312] app_macro.c: Executed application: Set
[Jun 6 12:44] VERBOSE[12312] logger.c: -- Executing [s@macro-outbound-callerid] GotoIf("Zap/1-1", "1?report") in new stack
[Jun 6 12:44] VERBOSE[12312] logger.c: -- Goto (macro-outbound-callerid,s,22)
[Jun 6 12:44] DEBUG[12312] app_macro.c: Executed application: GotoIf
[Jun 6 12:44] VERBOSE[12312] logger.c: -- Executing [s@macro-outbound-callerid] NoOp("Zap/1-1", "CallerID set to "WE" ") in new stack
[Jun 6 12:44] DEBUG[12312] app_macro.c: Executed application: Noop
[Jun 6 12:44] DEBUG[12312] app_macro.c: Executed application: Macro
[Jun 6 12:44] VERBOSE[12312] logger.c: -- Executing [s@macro-dialout-trunk] AGI("Zap/1-1", "fixlocalprefix") in new stack
[Jun 6 12:44] VERBOSE[12312] logger.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/fixlocalprefix
[Jun 6 12:44] VERBOSE[12312] logger.c: -- AGI Script fixlocalprefix completed, returning 0
[Jun 6 12:44] DEBUG[12312] app_macro.c: Executed application: AGI
[Jun 6 12:44] VERBOSE[12312] logger.c: -- Executing [s@macro-dialout-trunk] Set("Zap/1-1", "OUTNUM=xxxxx-DIALLED-NO-xxxxx") in new stack
[Jun 6 12:44] DEBUG[12312] app_macro.c: Executed application: Set
[Jun 6 12:44] VERBOSE[12312] logger.c: -- Executing [s@macro-dialout-trunk] Set("Zap/1-1", "custom=ZAP/4") in new stack
[Jun 6 12:44] DEBUG[12312] app_macro.c: Executed application: Set
[Jun 6 12:44] VERBOSE[12312] logger.c: -- Executing [s@macro-dialout-trunk] GotoIf("Zap/1-1", "1?gocall") in new stack
[Jun 6 12:44] VERBOSE[12312] logger.c: -- Goto (macro-dialout-trunk,s,17)
[Jun 6 12:44] DEBUG[12312] app_macro.c: Executed application: GotoIf
[Jun 6 12:44] VERBOSE[12312] logger.c: -- Executing [s@macro-dialout-trunk] Macro("Zap/1-1", "dialout-trunk-predial-hook|") in new stack
[Jun 6 12:44] 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] DEBUG[12312] app_macro.c: Executed application: Macro
[Jun 6 12:44] VERBOSE[12312] logger.c: -- Executing [s@macro-dialout-trunk] GotoIf("Zap/1-1", "0?bypass|1") in new stack
[Jun 6 12:44] DEBUG[12312] app_macro.c: Executed application: GotoIf
[Jun 6 12:44] VERBOSE[12312] logger.c: -- Executing [s@macro-dialout-trunk] GotoIf("Zap/1-1", "0?customtrunk") in new stack
[Jun 6 12:44] DEBUG[12312] app_macro.c: Executed application: GotoIf
[Jun 6 12:44] VERBOSE[12312] logger.c: -- Executing [s@macro-dialout-trunk] Dial("Zap/1-1", "ZAP/4/xxxxx-DIALLED-NO-xxxxx|300|t") in new stack
[Jun 6 12:44] DEBUG[12312] chan_zap.c: Dialing 'xxxxx-DIALLED-NO-xxxxx'
[Jun 6 12:44] DEBUG[12312] chan_zap.c: Deferring dialing...
[Jun 6 12:44] VERBOSE[12312] logger.c: -- Called 4/xxxxx-DIALLED-NO-xxxxx
[Jun 6 12:44] DEBUG[12312] chan_zap.c: Engaged echo training on channel 4
[Jun 6 12:44] DEBUG[12312] chan_zap.c: Echo cancellation already on
[Jun 6 12:49] VERBOSE[12312] logger.c: -- Nobody picked up in 300000 ms
[Jun 6 12:49] VERBOSE[12312] logger.c: -- Hungup 'Zap/4-1'
[Jun 6 12:49] DEBUG[12312] app_macro.c: Executed application: Dial
[Jun 6 12:49] VERBOSE[12312] logger.c: -- Executing [s@macro-dialout-trunk] Goto("Zap/1-1", "s-NOANSWER|1") in new stack
[Jun 6 12:49] VERBOSE[12312] logger.c: -- Goto (macro-dialout-trunk,s-NOANSWER,1)
[Jun 6 12:49] DEBUG[12312] app_macro.c: Executed application: Goto
[Jun 6 12:49] VERBOSE[12312] logger.c: -- Executing [s-NOANSWER@macro-dialout-trunk] NoOp("Zap/1-1", "Dial failed due to trunk reporting NOANSWER - giving up") in new stack
[Jun 6 12:49] DEBUG[12312] app_macro.c: Executed application: Noop
[Jun 6 12:49] VERBOSE[12312] logger.c: -- Executing [s-NOANSWER@macro-dialout-trunk] PlayTones("Zap/1-1", "congestion") in new stack
[Jun 6 12:49] DEBUG[12312] app_macro.c: Executed application: Playtones
[Jun 6 12:49] VERBOSE[12312] logger.c: -- Executing [s-NOANSWER@macro-dialout-trunk] Congestion("Zap/1-1", "20") in new stack
[Jun 6 12:49] 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] VERBOSE[12312] logger.c: == Spawn extension (macro-dialout-trunk, s-NOANSWER, 3) exited non-zero on 'Zap/1-1'
[Jun 6 12:49] VERBOSE[12312] logger.c: -- Executing [h@macro-dialout-trunk] Macro("Zap/1-1", "hangupcall|") in new stack
[Jun 6 12:49] VERBOSE[12312] logger.c: -- Executing [s@macro-hangupcall] ResetCDR("Zap/1-1", "w") in new stack

hello:
please check what is this for "Called 4/xxxxx-DIALLED-NO-xxxxx". are you sure the /xxxxx-DIALLED-NO-xxxxx is available and port 4 is connected?
please show us the zapata.conf and your dialplan.
regards!
James.zhu

James,
thanks for your help..
It seems I have fixed this problem with help from Good Guys from FreePBX. I'm describing solutions - maybe it can help someone else.

We are using OpenVox cards outside USA so we need settings other than standard FCC, beside loadzone and defaultzone options in /etc/zaptel.conf you have to specify
options wctdm opermode=COUNTRY_NAME
in /etc/modprobe.conf (or other appriopriate place ie: /etc/modprobe.d/zaptel)

Another thing we have switched "callprogress" option to yes in /etc/asterisk/zapata.conf.
In Asterisk 1.4 callprogress is still experimentall and can monitor FCC compliant lines only, so it definately should be set do no (default) on any non-US line.
After changing settings everything works ok.

Greetings,
Hanke.