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.
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@default changed from -1 to 1 on 2