[asterisk-users] Call Waiting broken on ZAP

[John Hyde]

Problem: *Call* *waiting* comes in, I press flash to answer it, and the
first caller gets disconnected after 3 seconds. This is all ZAP - no VOIP.

System:
Analog stations and trunks running on a pair of TDM400's. It does NOT have *
call* *waiting* from the phone company, and I have enabled it in all my conf
files. The trunks are set to FXSKS and the stations are FXOKS. I am not
using *call* progress or busy detect. Also its * 1.2.13 w/ FreePBX2.2.  I
have scoured the net for this, and nobody seems to know.

Here is some logging from a *call*:

Feb 1 17:41:53 DEBUG[6765] chan_zap.c: Requested indication 3 on channel
Zap/5-1
Feb 1 17:41:53 DEBUG[6765] pbx.c: Expression result is '1'
Feb 1 17:41:53 DEBUG[6765] pbx.c: Function result is 's'
Feb 1 17:41:53 DEBUG[6765] pbx.c: Expression result is '1'
Feb 1 17:41:53 DEBUG[6765] pbx.c: Function result is '5'
Feb 1 17:41:53 DEBUG[6765] db.c: Unable to find key '5187152626' in family
'blacklist'
Feb 1 17:41:53 DEBUG[6765] pbx.c: Expression result is '0'
Feb 1 17:41:53 DEBUG[6765] pbx.c: Not taking any branch
Feb 1 17:41:53 DEBUG[6765] chan_zap.c: Took Zap/5-1 off hook
Feb 1 17:41:53 DEBUG[6765] chan_zap.c: Enabled echo cancellation on channel
5
Feb 1 17:41:53 DEBUG[6765] chan_zap.c: Engaged echo training on channel 5
Feb 1 17:41:54 DEBUG[6765] channel.c: Scheduling timer at 160 sample
intervals
Feb 1 17:42:00 DEBUG[6765] chan_zap.c: DTMF digit: 5 on Zap/5-1
Feb 1 17:42:00 DEBUG[6765] channel.c: Scheduling timer at 0 sample intervals

Feb 1 17:42:00 DEBUG[6765] pbx.c: Oooh, got something to jump out with
('5')!
Feb 1 17:42:01 DEBUG[6765] chan_zap.c: DTMF digit: 0 on Zap/5-1
Feb 1 17:42:02 DEBUG[6765] chan_zap.c: DTMF digit: 0 on Zap/5-1
Feb 1 17:42:02 DEBUG[6765] pbx.c: Function result is ''
Feb 1 17:42:02 DEBUG[6765] pbx.c: Function result is '5187152626'
Feb 1 17:42:02 DEBUG[6765] pbx.c: Expression result is '0'
Feb 1 17:42:02 DEBUG[6765] pbx.c: Not taking any branch
Feb 1 17:42:02 DEBUG[6765] pbx.c: Expression result is '0'
Feb 1 17:42:02 DEBUG[6765] pbx.c: Not taking any branch
Feb 1 17:42:02 DEBUG[6765] pbx.c: Function result is '5187152626'
Feb 1 17:42:02 DEBUG[6765] db.c: Unable to find key '5187152626/user' in
family 'DEVICE'
Feb 1 17:42:02 DEBUG[6765] func_db.c: DB: DEVICE/5187152626/user not found
in database.
Feb 1 17:42:02 DEBUG[6765] pbx.c: Function result is ''
Feb 1 17:42:02 DEBUG[6765] db.c: Unable to find key '/cidname' in family
'AMPUSER'
Feb 1 17:42:02 DEBUG[6765] func_db.c: DB: AMPUSER//cidname not found in
database.
Feb 1 17:42:02 DEBUG[6765] pbx.c: Function result is ''
Feb 1 17:42:02 DEBUG[6765] pbx.c: Expression result is '1'
Feb 1 17:42:02 DEBUG[6765] pbx.c: Expression result is '0'
Feb 1 17:42:02 DEBUG[6765] pbx.c: Not taking any branch
Feb 1 17:42:02 DEBUG[6765] pbx.c: Expression result is '1'
Feb 1 17:42:02 DEBUG[6765] pbx.c: Expression result is '-1'
Feb 1 17:42:02 DEBUG[6765] pbx.c: Function result is '64'
Feb 1 17:42:02 DEBUG[6765] pbx.c: Expression result is '1'
Feb 1 17:42:02 DEBUG[6765] pbx.c: Function result is '"" <5187152626>'
Feb 1 17:42:02 DEBUG[6765] db.c: Unable to find key '500' in family 'CFU'
Feb 1 17:42:02 DEBUG[6765] func_db.c: DB: CFU/500 not found in database.
Feb 1 17:42:02 DEBUG[6765] pbx.c: Function result is ''
Feb 1 17:42:02 DEBUG[6765] pbx.c: Expression result is '1'
Feb 1 17:42:02 DEBUG[6765] pbx.c: Expression result is '0'
Feb 1 17:42:02 DEBUG[6765] pbx.c: Expression result is '1'
Feb 1 17:42:02 DEBUG[6765] pbx.c: Function result is '15'
Feb 1 17:42:02 DEBUG[6765] pbx.c: Function result is '0'
Feb 1 17:42:02 DEBUG[6765] pbx.c: Expression result is '0'
Feb 1 17:42:02 VERBOSE[6765] logger.c:
recordingcheck|20070201-174202|1170380512.151: Inbound recording enabled.
Feb 1 17:42:02 VERBOSE[6765] logger.c:
recordingcheck|20070201-174202|1170380512.151: CALLFILENAME=
20070201-174202-1170380512.151
Feb 1 17:42:02 DEBUG[6765] channel.c: Spy MixMonitor added to channel
Zap/5-1
Feb 1 17:42:02 VERBOSE[6765] logger.c: dialparties.agi: Starting New
Dialparties.agi
Feb 1 17:42:02 VERBOSE[6765] logger.c: dialparties.agi: priority is 1
Feb 1 17:42:02 VERBOSE[6765] logger.c: dialparties.agi: Caller ID name is
'unknown' number is '5187152626'
Feb 1 17:42:02 VERBOSE[6765] logger.c: dialparties.agi: Methodology of ring
is 'none'
Feb 1 17:42:02 DEBUG[6765] db.c: Unable to find key '500' in family 'CF'
Feb 1 17:42:02 DEBUG[6765] db.c: Unable to find key '500' in family 'DND'
Feb 1 17:42:02 DEBUG[6765] db.c: Unable to find key '500' in family 'CFB'
Feb 1 17:42:02 DEBUG[6765] db.c: Unable to find key '500' in family 'CFU'
Feb 1 17:42:02 DEBUG[6765] chan_zap.c: Requested indication 3 on channel
Zap/5-1
Feb 1 17:42:02 DEBUG[6765] channel.c: Building translator from ulaw to
SLINEAR for spies on channel Zap/5-1
Feb 1 17:42:03 DEBUG[6765] chan_zap.c: Exception on 13, channel 2
Feb 1 17:42:03 DEBUG[6765] chan_zap.c: Got event Ring/Answered(2) on channel
2 (index 0)
Feb 1 17:42:03 DEBUG[6765] chan_zap.c: Enabled echo cancellation on channel
2
Feb 1 17:42:03 DEBUG[6765] chan_zap.c: Engaged echo training on channel 2
Feb 1 17:42:03 DEBUG[6765] chan_zap.c: channel 2 answered
Feb 1 17:42:03 DEBUG[6765] chan_zap.c: Requested indication -1 on channel
Zap/5-1
Feb 1 17:42:23 NOTICE[6774] chan_zap.c: Got event 18 (Ring Begin)...
Feb 1 17:42:25 NOTICE[6774] chan_zap.c: Got event 2 (Ring/Answered)...
Feb 1 17:42:25 DEBUG[6774] chan_zap.c: Requested indication 3 on channel
Zap/6-1
Feb 1 17:42:25 DEBUG[6774] pbx.c: Expression result is '1'
Feb 1 17:42:25 DEBUG[6774] pbx.c: Function result is 's'
Feb 1 17:42:25 DEBUG[6774] pbx.c: Expression result is '1'
Feb 1 17:42:25 DEBUG[6774] pbx.c: Function result is '6'
Feb 1 17:42:25 DEBUG[6774] pbx.c: Expression result is '0'
Feb 1 17:42:25 DEBUG[6774] pbx.c: Not taking any branch
Feb 1 17:42:25 DEBUG[6774] chan_zap.c: Took Zap/6-1 off hook
Feb 1 17:42:25 DEBUG[6774] chan_zap.c: Enabled echo cancellation on channel
6
Feb 1 17:42:25 DEBUG[6774] chan_zap.c: Engaged echo training on channel 6
Feb 1 17:42:28 DEBUG[6774] channel.c: Scheduling timer at 160 sample
intervals
Feb 1 17:42:32 DEBUG[6774] chan_zap.c: DTMF digit: 5 on Zap/6-1
Feb 1 17:42:32 DEBUG[6774] channel.c: Scheduling timer at 0 sample intervals

Feb 1 17:42:32 DEBUG[6774] pbx.c: Oooh, got something to jump out with
('5')!
Feb 1 17:42:32 DEBUG[6774] chan_zap.c: DTMF digit: 0 on Zap/6-1
Feb 1 17:42:33 DEBUG[6774] chan_zap.c: DTMF digit: 0 on Zap/6-1
Feb 1 17:42:33 DEBUG[6774] pbx.c: Function result is ''
Feb 1 17:42:33 DEBUG[6774] pbx.c: Function result is ''
Feb 1 17:42:33 DEBUG[6774] pbx.c: Expression result is '0'
Feb 1 17:42:33 DEBUG[6774] pbx.c: Not taking any branch
Feb 1 17:42:33 DEBUG[6774] pbx.c: Expression result is '0'
Feb 1 17:42:33 DEBUG[6774] pbx.c: Not taking any branch
Feb 1 17:42:33 DEBUG[6774] pbx.c: Function result is ''
Feb 1 17:42:33 DEBUG[6774] db.c: Unable to find key '/user' in family
'DEVICE'
Feb 1 17:42:33 DEBUG[6774] func_db.c: DB: DEVICE//user not found in
database.
Feb 1 17:42:33 DEBUG[6774] pbx.c: Function result is ''
Feb 1 17:42:33 DEBUG[6774] db.c: Unable to find key '/cidname' in family
'AMPUSER'
Feb 1 17:42:33 DEBUG[6774] func_db.c: DB: AMPUSER//cidname not found in
database.
Feb 1 17:42:33 DEBUG[6774] pbx.c: Function result is ''
Feb 1 17:42:33 DEBUG[6774] pbx.c: Expression result is '1'
Feb 1 17:42:33 DEBUG[6774] pbx.c: Expression result is '0'
Feb 1 17:42:33 DEBUG[6774] pbx.c: Not taking any branch
Feb 1 17:42:33 DEBUG[6774] pbx.c: Expression result is '1'
Feb 1 17:42:33 DEBUG[6774] pbx.c: Expression result is '-1'
Feb 1 17:42:33 DEBUG[6774] pbx.c: Function result is '64'
Feb 1 17:42:33 DEBUG[6774] pbx.c: Expression result is '1'
Feb 1 17:42:33 DEBUG[6774] pbx.c: Function result is '"" <>'
Feb 1 17:42:33 DEBUG[6774] db.c: Unable to find key '500' in family 'CFU'
Feb 1 17:42:33 DEBUG[6774] func_db.c: DB: CFU/500 not found in database.
Feb 1 17:42:33 DEBUG[6774] pbx.c: Function result is ''
Feb 1 17:42:33 DEBUG[6774] pbx.c: Expression result is '1'
Feb 1 17:42:33 DEBUG[6774] pbx.c: Expression result is '0'
Feb 1 17:42:33 DEBUG[6774] pbx.c: Expression result is '1'
Feb 1 17:42:33 DEBUG[6774] pbx.c: Function result is '15'
Feb 1 17:42:33 DEBUG[6774] pbx.c: Function result is '0'
Feb 1 17:42:33 DEBUG[6774] pbx.c: Expression result is '0'
Feb 1 17:42:33 VERBOSE[6774] logger.c:
recordingcheck|20070201-174233|1170380539.153: Inbound recording enabled.
Feb 1 17:42:33 VERBOSE[6774] logger.c:
recordingcheck|20070201-174233|1170380539.153: CALLFILENAME=
20070201-174233-1170380539.153
Feb 1 17:42:33 DEBUG[6774] channel.c: Spy MixMonitor added to channel
Zap/6-1
Feb 1 17:42:33 VERBOSE[6774] logger.c: dialparties.agi: Starting New
Dialparties.agi
Feb 1 17:42:33 VERBOSE[6774] logger.c: dialparties.agi: priority is 1
Feb 1 17:42:33 VERBOSE[6774] logger.c: dialparties.agi: Caller ID name is
'unknown' number is 'unknown'
Feb 1 17:42:33 VERBOSE[6774] logger.c: dialparties.agi: Methodology of ring
is 'none'
Feb 1 17:42:33 DEBUG[6774] db.c: Unable to find key '500' in family 'CF'
Feb 1 17:42:33 DEBUG[6774] db.c: Unable to find key '500' in family 'DND'
Feb 1 17:42:33 DEBUG[6774] db.c: Unable to find key '500' in family 'CFB'
Feb 1 17:42:33 DEBUG[6774] db.c: Unable to find key '500' in family 'CFU'
Feb 1 17:42:33 DEBUG[6774] chan_zap.c: Already have a dsp on Zap/2-2?
Feb 1 17:42:33 DEBUG[6774] chan_zap.c: Requested indication 3 on channel
Zap/6-1
Feb 1 17:42:33 DEBUG[6774] channel.c: Building translator from ulaw to
SLINEAR for spies on channel Zap/6-1
Feb 1 17:42:33 DEBUG[6765] chan_zap.c: DTMF digit: D on Zap/2-1
Feb 1 17:42:33 DEBUG[6765] chan_zap.c: Got some DTMF, but it's for the CAS
Feb 1 17:42:35 DEBUG[6765] chan_zap.c: Exception on 13, channel 2
Feb 1 17:42:35 DEBUG[6765] chan_zap.c: Got event On hook(1) on channel 2
(index 0)
Feb 1 17:42:35 DEBUG[6765] chan_zap.c: Swapping 1 and 0
Feb 1 17:42:35 DEBUG[6765] chan_zap.c: Released sub 1 of channel 2
Feb 1 17:42:36 DEBUG[6765] chan_zap.c: disabled echo cancellation on channel
2
Feb 1 17:42:36 DEBUG[6765] channel.c: Didn't get a frame from channel:
Zap/2-1
Feb 1 17:42:36 DEBUG[6765] channel.c: Bridge stops bridging channels Zap/5-1
and Zap/2-1
Feb 1 17:42:36 DEBUG[6765] chan_zap.c: Hangup: channel: 2 index = -1, normal
= 13, callwait = -1, thirdcall = -1
Feb 1 17:42:36 DEBUG[6765] app_dial.c: Exiting with DIALSTATUS=ANSWER.
Feb 1 17:42:36 DEBUG[6774] chan_zap.c: Restoring owner of channel 2 on event
2
Feb 1 17:42:36 DEBUG[6774] chan_zap.c: Requested indication -1 on channel
Zap/6-1
Feb 1 17:42:36 ERROR[6765] cdr_addon_mysql.c: cdr_mysql: cannot connect to
database server localhost. CDR will not be spooled.
Feb 1 17:42:36 DEBUG[6765] cdr_addon_mysql.c: cdr_mysql: inserting a CDR
record.
Feb 1 17:42:36 DEBUG[6765] cdr_addon_mysql.c: cdr_mysql: SQL command as
follows: INSERT INTO cdr
(calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid)
VALUES ('2007-02-01 17:41:53','5187152626','5187152626','500','ivr-3',
'Zap/5-1','Zap/2-1','ResetCDR','w',43,43,'ANSWERED',3,'','1170380512.151')
Feb 1 17:42:36 WARNING[6765] cdr.c: CDR on channel 'Zap/5-1' not posted
Feb 1 17:42:36 WARNING[6765] cdr.c: CDR on channel 'Zap/5-1' lacks end
Feb 1 17:42:36 DEBUG[6765] pbx.c: Expression result is '1'
Feb 1 17:42:36 DEBUG[6765] pbx.c: Expression result is '1'
Feb 1 17:42:41 DEBUG[6765] channel.c: Spy MixMonitor removed from channel
Zap/5-1
Feb 1 17:42:41 DEBUG[6765] chan_zap.c: Hangup: channel: 5 index = 0, normal
= 16, callwait = -1, thirdcall = -1
Feb 1 17:42:41 DEBUG[6765] chan_zap.c: disabled echo cancellation on channel
5
Feb 1 17:42:41 DEBUG[6765] chan_zap.c: Set option TDD MODE, value: OFF(0) on
Zap/5-1
Feb 1 17:42:41 DEBUG[6765] chan_zap.c: Updated conferencing on 5, with 0
conference users
Feb 1 17:43:11 DEBUG[6774] chan_zap.c: Exception on 17, channel 6
Feb 1 17:43:11 DEBUG[6774] chan_zap.c: Got event On hook(1) on channel 6
(index 0)
Feb 1 17:43:11 DEBUG[6774] chan_zap.c: disabled echo cancellation on channel
6
Feb 1 17:43:11 DEBUG[6774] channel.c: Didn't get a frame from channel:
Zap/6-1
Feb 1 17:43:11 DEBUG[6774] channel.c: Bridge stops bridging channels Zap/6-1
and Zap/2-2
Feb 1 17:43:11 DEBUG[6774] chan_zap.c: Hangup: channel: 2 index = 0, normal
= 13, callwait = -1, thirdcall = -1
Feb 1 17:43:11 DEBUG[6774] chan_zap.c: disabled echo cancellation on channel
2
Feb 1 17:43:11 DEBUG[6774] chan_zap.c: Set option TDD MODE, value: OFF(0) on
Zap/2-2
Feb 1 17:43:11 DEBUG[6774] chan_zap.c: Updated conferencing on 2, with 0
conference users
Feb 1 17:43:11 DEBUG[6774] app_dial.c: Exiting with DIALSTATUS=ANSWER.
Feb 1 17:43:11 ERROR[6774] cdr_addon_mysql.c: cdr_mysql: cannot connect to
database server localhost. CDR will not be spooled.
Feb 1 17:43:11 DEBUG[6774] cdr_addon_mysql.c: cdr_mysql: inserting a CDR
record.
Feb 1 17:43:11 DEBUG[6774] cdr_addon_mysql.c: cdr_mysql: SQL command as
follows: INSERT INTO cdr
(calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid)
VALUES ('2007-02-01 17:42:25','','','500','ivr-3',
'Zap/6-1','Zap/2-2','ResetCDR','w',46,46,'ANSWERED',3,'','1170380539.153')
Feb 1 17:43:11 WARNING[6774] cdr.c: CDR on channel 'Zap/6-1' not posted
Feb 1 17:43:11 WARNING[6774] cdr.c: CDR on channel 'Zap/6-1' lacks end
Feb 1 17:43:11 DEBUG[6774] pbx.c: Expression result is '1'
Feb 1 17:43:11 DEBUG[6774] pbx.c: Expression result is '1'
Feb 1 17:43:11 DEBUG[6774] channel.c: Spy MixMonitor removed from channel
Zap/6-1
Feb 1 17:43:11 DEBUG[6774] chan_zap.c: Hangup: channel: 6 index = 0, normal
= 17, callwait = -1, thirdcall = -1
Feb 1 17:43:11 DEBUG[6774] chan_zap.c: disabled echo cancellation on channel
6
Feb 1 17:43:11 DEBUG[6774] chan_zap.c: Set option TDD MODE, value: OFF(0) on
Zap/6-1
Feb 1 17:43:11 DEBUG[6774] chan_zap.c: Updated conferencing on 6, with 0
conference users
Feb 1 17:43:12 WARNING[2797] chan_zap.c: zt hook failed: Device or resource
busy
Feb 1 17:43:14 DEBUG[6789] chan_zap.c: Exception on 13, channel 2
Feb 1 17:43:14 DEBUG[6789] chan_zap.c: Got event On hook(1) on channel 2
(index 0)
Feb 1 17:43:14 DEBUG[6789] chan_zap.c: disabled echo cancellation on channel
2
Feb 1 17:43:14 DEBUG[6789] chan_zap.c: waitfordigit returned < 0...
Feb 1 17:43:14 DEBUG[6789] chan_zap.c: Hangup: channel: 2 index = 0, normal
= 13, callwait = -1, thirdcall = -1
Feb 1 17:43:14 DEBUG[6789] chan_zap.c: disabled echo cancellation on channel
2
Feb 1 17:43:14 DEBUG[6789] chan_zap.c: Set option TDD MODE, value: OFF(0) on
Zap/2-1
Feb 1 17:43:14 DEBUG[6789] chan_zap.c: Updated conferencing on 2, with 0
conference users
Feb 1 17:43:18 DEBUG[2797] chan_zap.c: Message status for
500 at defaultchanged from -1 to 1 on 2
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.digium.com/pipermail/asterisk-users/attachments/20070202/e9a236fe/attachment-0001.htm