[asterisk-users] Dead Incoming call - Sangoma A200

Fri Dec 21 19:49:14 CST 2007

Hello List,

I am having a strange issue with a trixbox system we installed for a client, and I would appreciate any help on this one. The issue is that occasionally when they go to answer an inbound call from the Sangoma A200 - there is no one there, and they are presented with dial tone. The calling party is hung up.

A bit of background:

The client actually has two systems install (one at each location). Both systems are identical:

Intel Server x3250
Dual Core Xenon Processor
1GB RAM
Raid 1 160GB HDD's
Sangoma A200 to interface to 2 PSTN lines.

The odd thing is that only one of the systems is having this issue....

Making this one even more frustrating is that it only happens two or three times a day on this production box. Testing that I have done out of hours has been unable to re-produce the issue as of yet. I have enabled verbose debugging, and I have included below what I believe is the relevant section of the logs for when the issue occurs.

As a quick overview, this was an incoming call on Zaptel channel 2, which was went to a ring group, and started to call SIP extension 203. This is when the call hung up.

If there is any other information that I can provide to help, please let me know. This is a very frustrating issue...

Log Output:

Dec 21 13:43:48 NOTICE[15840] chan_zap.c: Got event 18 (Ring Begin)...
Dec 21 13:43:48 VERBOSE[15840] logger.c:     -- Executing NoOp("Zap/2-1", "Entering from-zaptel with DID == ") in new stack
Dec 21 13:43:48 VERBOSE[15840] logger.c:     -- Executing Ringing("Zap/2-1", "") in new stack
Dec 21 13:43:48 DEBUG[15840] chan_zap.c: Requested indication 3 on channel Zap/2-1 Dec 21 13:43:48 DEBUG[15840] pbx.c: Expression result is '1'
Dec 21 13:43:48 DEBUG[15840] pbx.c: Function result is 's'
Dec 21 13:43:48 VERBOSE[15840] logger.c:     -- Executing Set("Zap/2-1", "DID=s") in new stack
Dec 21 13:43:48 VERBOSE[15840] logger.c:     -- Executing NoOp("Zap/2-1", "DID is now s") in new stack
Dec 21 13:43:48 DEBUG[15840] pbx.c: Expression result is '1'
Dec 21 13:43:48 VERBOSE[15840] logger.c:     -- Executing GotoIf("Zap/2-1", "1?zapok:notzap") in new stack
Dec 21 13:43:48 VERBOSE[15840] logger.c:     -- Goto (from-zaptel,s,8)
Dec 21 13:43:48 VERBOSE[15840] logger.c:     -- Executing NoOp("Zap/2-1", "Is a Zaptel Channel") in new stack
Dec 21 13:43:48 VERBOSE[15840] logger.c:     -- Executing Set("Zap/2-1", "CHAN=2-1") in new stack
Dec 21 13:43:48 DEBUG[15840] pbx.c: Function result is '2'
Dec 21 13:43:48 VERBOSE[15840] logger.c:     -- Executing Set("Zap/2-1", "CHAN=2") in new stack
Dec 21 13:43:48 VERBOSE[15840] logger.c:     -- Executing Macro("Zap/2-1", "from-zaptel-2|s|1") in new stack
Dec 21 13:43:48 VERBOSE[15840] logger.c:     -- Executing NoOp("Zap/2-1", "Entering macro-from-zaptel-2 with DID = s") in new stack
Dec 21 13:43:48 DEBUG[15840] app_macro.c: Executed application: Noop
Dec 21 13:43:48 VERBOSE[15840] logger.c:     -- Executing Gosub("Zap/2-1", "app-blacklist-check|s|1") in new stack
Dec 21 13:43:48 DEBUG[15840] app_macro.c: Executed application: Gosub Dec 21 13:43:48 DEBUG[15840] app_macro.c: Incrementing gosub_level
Dec 21 13:43:48 VERBOSE[15840] logger.c:     -- Executing LookupBlacklist("Zap/2-1", "") in new stack
Dec 21 13:43:48 DEBUG[15840] app_macro.c: Executed application: LookupBlacklist Dec 21 13:43:48 DEBUG[15840] pbx.c: Expression result is '0'
Dec 21 13:43:48 VERBOSE[15840] logger.c:     -- Executing GotoIf("Zap/2-1", "0?blacklisted") in new stack
Dec 21 13:43:48 DEBUG[15840] pbx.c: Not taking any branch Dec 21 13:43:48 DEBUG[15840] app_macro.c: Executed application: GotoIf
Dec 21 13:43:48 VERBOSE[15840] logger.c:     -- Executing Return("Zap/2-1", "") in new stack
Dec 21 13:43:48 DEBUG[15840] app_macro.c: Executed application: Return Dec 21 13:43:48 DEBUG[15840] app_macro.c: Decrementing gosub_level
Dec 21 13:43:48 VERBOSE[15840] logger.c:     -- Executing Gosub("Zap/2-1", "cidlookup|cidlookup_1|1") in new stack
Dec 21 13:43:48 DEBUG[15840] app_macro.c: Executed application: Gosub Dec 21 13:43:48 DEBUG[15840] app_macro.c: Incrementing gosub_level
Dec 21 13:43:48 VERBOSE[15840] logger.c:     -- Executing LookupCIDName("Zap/2-1", "") in new stack
Dec 21 13:43:48 DEBUG[15840] app_macro.c: Executed application: LookupCIDName
Dec 21 13:43:48 VERBOSE[15840] logger.c:     -- Executing Return("Zap/2-1", "") in new stack
Dec 21 13:43:48 DEBUG[15840] app_macro.c: Executed application: Return Dec 21 13:43:48 DEBUG[15840] app_macro.c: Decrementing gosub_level
Dec 21 13:43:48 VERBOSE[15840] logger.c:     -- Executing Set("Zap/2-1", "__FROM_DID=s") in new stack
Dec 21 13:43:48 DEBUG[15840] app_macro.c: Executed application: Set Dec 21 13:43:48 DEBUG[15840] pbx.c: Function result is ''
Dec 21 13:43:48 DEBUG[15840] pbx.c: Expression result is '0'
Dec 21 13:43:48 VERBOSE[15840] logger.c:     -- Executing GotoIf("Zap/2-1", "0 ?cidok") in new stack
Dec 21 13:43:48 DEBUG[15840] pbx.c: Not taking any branch Dec 21 13:43:48 DEBUG[15840] app_macro.c: Executed application: GotoIf Dec 21 13:43:48 DEBUG[15840] pbx.c: Function result is ''
Dec 21 13:43:48 VERBOSE[15840] logger.c:     -- Executing Set("Zap/2-1", "CALLERID(name)=") in new stack
Dec 21 13:43:48 DEBUG[15840] app_macro.c: Executed application: Set Dec 21 13:43:48 DEBUG[15840] pbx.c: Function result is '"" <>'
Dec 21 13:43:48 VERBOSE[15840] logger.c:     -- Executing NoOp("Zap/2-1", "CallerID is "" <>") in new stack
Dec 21 13:43:48 DEBUG[15840] app_macro.c: Executed application: Noop
Dec 21 13:43:48 VERBOSE[15840] logger.c:     -- Executing Goto("Zap/2-1", "timeconditions|1|1") in new stack
Dec 21 13:43:48 VERBOSE[15840] logger.c:     -- Goto (timeconditions,1,1)
Dec 21 13:43:48 DEBUG[15840] app_macro.c: Executed application: Goto
Dec 21 13:43:48 VERBOSE[15840] logger.c:   == Channel 'Zap/2-1' jumping out of macro 'from-zaptel-2'
Dec 21 13:43:48 VERBOSE[15840] logger.c:     -- Executing GotoIfTime("Zap/2-1", "08:00-18:00|mon-fri|*|*?ext-group|600|1") in new stack
Dec 21 13:43:48 VERBOSE[15840] logger.c:     -- Goto (ext-group,600,1)
Dec 21 13:43:48 VERBOSE[15840] logger.c:     -- Executing Macro("Zap/2-1", "user-callerid|") in new stack
Dec 21 13:43:48 DEBUG[15840] pbx.c: Function result is ''
Dec 21 13:43:48 DEBUG[15840] pbx.c: Function result is ''
Dec 21 13:43:48 VERBOSE[15840] logger.c:     -- Executing NoOp("Zap/2-1", "user-callerid:  ") in new stack
Dec 21 13:43:48 DEBUG[15840] app_macro.c: Executed application: Noop Dec 21 13:43:48 DEBUG[15840] pbx.c: Expression result is '1'
Dec 21 13:43:48 DEBUG[15840] pbx.c: Function result is ''
Dec 21 13:43:48 DEBUG[15840] pbx.c: Function result is ''
Dec 21 13:43:48 VERBOSE[15840] logger.c:     -- Executing Set("Zap/2-1", "AMPUSER=") in new stack
Dec 21 13:43:48 DEBUG[15840] app_macro.c: Executed application: Set Dec 21 13:43:48 DEBUG[15840] pbx.c: Expression result is '0'
Dec 21 13:43:48 VERBOSE[15840] logger.c:     -- Executing GotoIf("Zap/2-1", "0?report") in new stack
Dec 21 13:43:48 DEBUG[15840] pbx.c: Not taking any branch Dec 21 13:43:48 DEBUG[15840] app_macro.c: Executed application: GotoIf Dec 21 13:43:48 DEBUG[15840] pbx.c: Expression result is '0'
Dec 21 13:43:48 VERBOSE[15840] logger.c:     -- Executing GotoIf("Zap/2-1", "0?start") in new stack
Dec 21 13:43:48 DEBUG[15840] pbx.c: Not taking any branch Dec 21 13:43:48 DEBUG[15840] app_macro.c: Executed application: GotoIf Dec 21 13:43:48 DEBUG[15840] pbx.c: Function result is ''
Dec 21 13:43:48 VERBOSE[15840] logger.c:     -- Executing Set("Zap/2-1", "REALCALLERIDNUM=") in new stack
Dec 21 13:43:48 DEBUG[15840] app_macro.c: Executed application: Set
Dec 21 13:43:48 VERBOSE[15840] logger.c:     -- Executing NoOp("Zap/2-1", "REALCALLERIDNUM is ") in new stack
Dec 21 13:43:48 DEBUG[15840] app_macro.c: Executed application: NoOp Dec 21 13:43:48 DEBUG[15840] db.c: Unable to find key '/user' in family 'DEVICE'
Dec 21 13:43:48 DEBUG[15840] func_db.c: DB: DEVICE//user not found in database.
Dec 21 13:43:48 DEBUG[15840] pbx.c: Function result is ''
Dec 21 13:43:48 VERBOSE[15840] logger.c:     -- Executing Set("Zap/2-1", "AMPUSER=") in new stack
Dec 21 13:43:48 DEBUG[15840] app_macro.c: Executed application: Set Dec 21 13:43:48 DEBUG[15840] db.c: Unable to find key '/cidname' in family 'AMPUSER'
Dec 21 13:43:48 DEBUG[15840] func_db.c: DB: AMPUSER//cidname not found in database.
Dec 21 13:43:48 DEBUG[15840] pbx.c: Function result is ''
Dec 21 13:43:48 VERBOSE[15840] logger.c:     -- Executing Set("Zap/2-1", "AMPUSERCIDNAME=") in new stack
Dec 21 13:43:48 DEBUG[15840] app_macro.c: Executed application: Set Dec 21 13:43:48 DEBUG[15840] pbx.c: Expression result is '1'
Dec 21 13:43:48 VERBOSE[15840] logger.c:     -- Executing GotoIf("Zap/2-1", "1?report") in new stack
Dec 21 13:43:48 VERBOSE[15840] logger.c:     -- Goto (macro-user-callerid,s,13)
Dec 21 13:43:48 DEBUG[15840] app_macro.c: Executed application: GotoIf
Dec 21 13:43:48 VERBOSE[15840] logger.c:     -- Executing NoOp("Zap/2-1", "TTL:  ARG1: ") in new stack
Dec 21 13:43:48 DEBUG[15840] app_macro.c: Executed application: Noop Dec 21 13:43:48 DEBUG[15840] pbx.c: Expression result is '0'
Dec 21 13:43:48 VERBOSE[15840] logger.c:     -- Executing GotoIf("Zap/2-1", "0?continue") in new stack
Dec 21 13:43:48 DEBUG[15840] pbx.c: Not taking any branch Dec 21 13:43:48 DEBUG[15840] app_macro.c: Executed application: GotoIf Dec 21 13:43:48 DEBUG[15840] pbx.c: Expression result is '1'
Dec 21 13:43:48 DEBUG[15840] pbx.c: Expression result is '-1'
Dec 21 13:43:48 DEBUG[15840] pbx.c: Function result is '64'
Dec 21 13:43:48 VERBOSE[15840] logger.c:     -- Executing Set("Zap/2-1", "__TTL=64") in new stack
Dec 21 13:43:48 DEBUG[15840] app_macro.c: Executed application: Set Dec 21 13:43:48 DEBUG[15840] pbx.c: Expression result is '1'
Dec 21 13:43:48 VERBOSE[15840] logger.c:     -- Executing GotoIf("Zap/2-1", "1?continue") in new stack
Dec 21 13:43:48 VERBOSE[15840] logger.c:     -- Goto (macro-user-callerid,s,23)
Dec 21 13:43:48 DEBUG[15840] app_macro.c: Executed application: GotoIf Dec 21 13:43:48 DEBUG[15840] pbx.c: Function result is '"" <>'
Dec 21 13:43:48 VERBOSE[15840] logger.c:     -- Executing NoOp("Zap/2-1", "Using CallerID "" <>") in new stack
Dec 21 13:43:48 DEBUG[15840] app_macro.c: Executed application: NoOp Dec 21 13:43:48 DEBUG[15840] pbx.c: Expression result is '1'
Dec 21 13:43:48 VERBOSE[15840] logger.c:     -- Executing GotoIf("Zap/2-1", "1?skipdb") in new stack
Dec 21 13:43:48 VERBOSE[15840] logger.c:     -- Goto (ext-group,600,4)
Dec 21 13:43:48 VERBOSE[15840] logger.c:     -- Executing Set("Zap/2-1", "__NODEST=") in new stack
Dec 21 13:43:48 VERBOSE[15840] logger.c:     -- Executing Set("Zap/2-1", "__BLKVM_OVERRIDE=BLKVM/600/Zap/2-1") in new stack
Dec 21 13:43:48 VERBOSE[15840] logger.c:     -- Executing Set("Zap/2-1", "__BLKVM_BASE=600") in new stack
Dec 21 13:43:48 VERBOSE[15840] logger.c:     -- Executing Set("Zap/2-1", "DB(BLKVM/600/Zap/2-1)=TRUE") in new stack
Dec 21 13:43:48 VERBOSE[15840] logger.c:     -- Executing Set("Zap/2-1", "RRNODEST=") in new stack
Dec 21 13:43:48 VERBOSE[15840] logger.c:     -- Executing Set("Zap/2-1", "__NODEST=600") in new stack
Dec 21 13:43:48 DEBUG[15840] pbx.c: Expression result is '1'
Dec 21 13:43:48 VERBOSE[15840] logger.c:     -- Executing GotoIf("Zap/2-1", "1?REPCID") in new stack
Dec 21 13:43:48 VERBOSE[15840] logger.c:     -- Goto (ext-group,600,15)
Dec 21 13:43:48 DEBUG[15840] pbx.c: Function result is ''
Dec 21 13:43:48 VERBOSE[15840] logger.c:     -- Executing NoOp("Zap/2-1", "CALLERID(name) is ") in new stack
Dec 21 13:43:48 VERBOSE[15840] logger.c:     -- Executing Set("Zap/2-1", "_RGPREFIX=Leongatha:") in new stack
Dec 21 13:43:48 DEBUG[15840] pbx.c: Function result is ''
Dec 21 13:43:48 VERBOSE[15840] logger.c:     -- Executing Set("Zap/2-1", "CALLERID(name)=Leongatha:") in new stack
Dec 21 13:43:48 VERBOSE[15840] logger.c:     -- Executing Set("Zap/2-1", "RecordMethod=Group") in new stack
Dec 21 13:43:48 VERBOSE[15840] logger.c:     -- Executing Macro("Zap/2-1", "record-enable|203-202-200-201-208-209-206|Group") in new stack
Dec 21 13:43:48 DEBUG[15840] pbx.c: Function result is '0'
Dec 21 13:43:48 DEBUG[15840] pbx.c: Expression result is '0'
Dec 21 13:43:48 VERBOSE[15840] logger.c:     -- Executing GotoIf("Zap/2-1", "0?2:4") in new stack
Dec 21 13:43:48 VERBOSE[15840] logger.c:     -- Goto (macro-record-enable,s,4)
Dec 21 13:43:48 DEBUG[15840] app_macro.c: Executed application: GotoIf Dec 21 13:43:48 DEBUG[15840] pbx.c: Function result is '20071221-134348'
Dec 21 13:43:48 VERBOSE[15840] logger.c:     -- Executing AGI("Zap/2-1", "recordingcheck|20071221-134348|1198205023.1657") in new stack
Dec 21 13:43:48 VERBOSE[15840] logger.c:     -- Launched AGI Script /var/lib/asterisk/agi-bin/recordingcheck
Dec 21 13:43:48 VERBOSE[15840] logger.c:     -- AGI Script recordingcheck completed, returning 0
Dec 21 13:43:48 DEBUG[15840] app_macro.c: Executed application: AGI
Dec 21 13:43:48 VERBOSE[15840] logger.c:     -- Executing NoOp("Zap/2-1", "No recording needed") in new stack
Dec 21 13:43:48 DEBUG[15840] app_macro.c: Executed application: Noop
Dec 21 13:43:48 VERBOSE[15840] logger.c:     -- Executing Set("Zap/2-1", "RingGroupMethod=hunt") in new stack
Dec 21 13:43:48 VERBOSE[15840] logger.c:     -- Executing Macro("Zap/2-1", "dial|20||203-202-200-201-208-209-206") in new stack
Dec 21 13:43:48 DEBUG[15840] pbx.c: Expression result is '1'
Dec 21 13:43:48 VERBOSE[15840] logger.c:     -- Executing GotoIf("Zap/2-1", "1?dial") in new stack
Dec 21 13:43:48 VERBOSE[15840] logger.c:     -- Goto (macro-dial,s,3)
Dec 21 13:43:48 DEBUG[15840] app_macro.c: Executed application: GotoIf
Dec 21 13:43:48 VERBOSE[15840] logger.c:     -- Executing AGI("Zap/2-1", "dialparties.agi") in new stack
Dec 21 13:43:48 VERBOSE[15840] logger.c:     -- Launched AGI Script /var/lib/asterisk/agi-bin/dialparties.agi
Dec 21 13:43:48 VERBOSE[15840] logger.c:   dialparties.agi: Starting New Dialparties.agi
Dec 21 13:43:48 DEBUG[15847] manager.c: Manager received command 'login'
Dec 21 13:43:48 VERBOSE[15847] logger.c:   == Parsing '/etc/asterisk/manager.conf': Dec 21 13:43:48 VERBOSE[15847] logger.c:   == Parsing '/etc/asterisk/manager.conf': Found
Dec 21 13:43:48 VERBOSE[15847] logger.c:   == Parsing '/etc/asterisk/manager_custom.conf': Dec 21 13:43:48 VERBOSE[15847] logger.c:   == Parsing '/etc/asterisk/manager_custom.conf': Found
Dec 21 13:43:48 DEBUG[15847] acl.c: 0.0.0.0/0.0.0.0/0.0.0.0 appended to acl for peer Dec 21 13:43:48 DEBUG[15847] acl.c: 127.0.0.1/255.255.255.0/255.255.255.0 appended to acl for peer Dec 21 13:43:48 DEBUG[15847] acl.c: ##### Testing 127.0.0.1 with 0.0.0.0 Dec 21 13:43:48 DEBUG[15847] acl.c: ##### Testing 127.0.0.1 with 127.0.0.0
Dec 21 13:43:48 VERBOSE[15847] logger.c:   == Manager 'admin' logged on from 127.0.0.1
Dec 21 13:43:48 VERBOSE[15840] logger.c:   dialparties.agi: Caller ID name is 'Leongatha:' number is 'unknown'
Dec 21 13:43:48 VERBOSE[15840] logger.c:   dialparties.agi: USE_CONFIRMATION:  'FALSE'
Dec 21 13:43:48 VERBOSE[15840] logger.c:   dialparties.agi: RINGGROUP_INDEX:   ''
Dec 21 13:43:48 VERBOSE[15840] logger.c:   dialparties.agi: Methodology of ring is  'hunt'
Dec 21 13:43:48 VERBOSE[15840] logger.c:     --  dialparties.agi: Added extension 203 to extension map
Dec 21 13:43:48 VERBOSE[15840] logger.c:     --  dialparties.agi: Added extension 202 to extension map
Dec 21 13:43:48 VERBOSE[15840] logger.c:     --  dialparties.agi: Added extension 200 to extension map
Dec 21 13:43:48 VERBOSE[15840] logger.c:     --  dialparties.agi: Added extension 201 to extension map
Dec 21 13:43:48 VERBOSE[15840] logger.c:     --  dialparties.agi: Added extension 208 to extension map
Dec 21 13:43:48 VERBOSE[15840] logger.c:     --  dialparties.agi: Added extension 209 to extension map
Dec 21 13:43:48 VERBOSE[15840] logger.c:     --  dialparties.agi: Added extension 206 to extension map
Dec 21 13:43:48 DEBUG[15840] db.c: Unable to find key '203' in family 'CF'
Dec 21 13:43:48 VERBOSE[15840] logger.c:     --  dialparties.agi: Extension 203 cf is disabled
Dec 21 13:43:48 DEBUG[15840] db.c: Unable to find key '202' in family 'CF'
Dec 21 13:43:48 VERBOSE[15840] logger.c:     --  dialparties.agi: Extension 202 cf is disabled
Dec 21 13:43:48 DEBUG[15840] db.c: Unable to find key '200' in family 'CF'
Dec 21 13:43:48 VERBOSE[15840] logger.c:     --  dialparties.agi: Extension 200 cf is disabled
Dec 21 13:43:48 DEBUG[15840] db.c: Unable to find key '201' in family 'CF'
Dec 21 13:43:48 VERBOSE[15840] logger.c:     --  dialparties.agi: Extension 201 cf is disabled
Dec 21 13:43:48 DEBUG[15840] db.c: Unable to find key '208' in family 'CF'
Dec 21 13:43:48 VERBOSE[15840] logger.c:     --  dialparties.agi: Extension 208 cf is disabled
Dec 21 13:43:48 DEBUG[15840] db.c: Unable to find key '209' in family 'CF'
Dec 21 13:43:48 VERBOSE[15840] logger.c:     --  dialparties.agi: Extension 209 cf is disabled
Dec 21 13:43:48 DEBUG[15840] db.c: Unable to find key '206' in family 'CF'
Dec 21 13:43:48 VERBOSE[15840] logger.c:     --  dialparties.agi: Extension 206 cf is disabled
Dec 21 13:43:48 DEBUG[15840] db.c: Unable to find key '203' in family 'DND'
Dec 21 13:43:48 VERBOSE[15840] logger.c:     --  dialparties.agi: Extension 203 do not disturb is disabled
Dec 21 13:43:48 DEBUG[15840] db.c: Unable to find key '202' in family 'DND'
Dec 21 13:43:48 VERBOSE[15840] logger.c:     --  dialparties.agi: Extension 202 do not disturb is disabled
Dec 21 13:43:48 DEBUG[15840] db.c: Unable to find key '200' in family 'DND'
Dec 21 13:43:48 VERBOSE[15840] logger.c:     --  dialparties.agi: Extension 200 do not disturb is disabled
Dec 21 13:43:48 DEBUG[15840] db.c: Unable to find key '201' in family 'DND'
Dec 21 13:43:48 VERBOSE[15840] logger.c:     --  dialparties.agi: Extension 201 do not disturb is disabled
Dec 21 13:43:48 DEBUG[15840] db.c: Unable to find key '208' in family 'DND'
Dec 21 13:43:48 VERBOSE[15840] logger.c:     --  dialparties.agi: Extension 208 do not disturb is disabled
Dec 21 13:43:48 DEBUG[15840] db.c: Unable to find key '209' in family 'DND'
Dec 21 13:43:48 VERBOSE[15840] logger.c:     --  dialparties.agi: Extension 209 do not disturb is disabled
Dec 21 13:43:48 DEBUG[15840] db.c: Unable to find key '206' in family 'DND'
Dec 21 13:43:48 VERBOSE[15840] logger.c:     --  dialparties.agi: Extension 206 do not disturb is disabled
Dec 21 13:43:48 DEBUG[15840] db.c: Unable to find key '203' in family 'CFB'
Dec 21 13:43:48 DEBUG[15840] db.c: Unable to find key '203' in family 'CFU'
Dec 21 13:43:48 VERBOSE[15840] logger.c:        >  dialparties.agi: extnum 203 has:  cw: 1; hascfb: 0 [] hascfu: 0 []
Dec 21 13:43:48 DEBUG[15840] db.c: Unable to find key '202' in family 'CFB'
Dec 21 13:43:48 DEBUG[15840] db.c: Unable to find key '202' in family 'CFU'
Dec 21 13:43:48 VERBOSE[15840] logger.c:        >  dialparties.agi: extnum 202 has:  cw: 1; hascfb: 0 [] hascfu: 0 []
Dec 21 13:43:48 DEBUG[15840] db.c: Unable to find key '200' in family 'CFB'
Dec 21 13:43:48 DEBUG[15840] db.c: Unable to find key '200' in family 'CFU'
Dec 21 13:43:48 VERBOSE[15840] logger.c:        >  dialparties.agi: extnum 200 has:  cw: 1; hascfb: 0 [] hascfu: 0 []
Dec 21 13:43:48 DEBUG[15840] db.c: Unable to find key '201' in family 'CFB'
Dec 21 13:43:48 DEBUG[15840] db.c: Unable to find key '201' in family 'CFU'
Dec 21 13:43:48 VERBOSE[15840] logger.c:        >  dialparties.agi: extnum 201 has:  cw: 1; hascfb: 0 [] hascfu: 0 []
Dec 21 13:43:48 DEBUG[15840] db.c: Unable to find key '208' in family 'CFB'
Dec 21 13:43:48 DEBUG[15840] db.c: Unable to find key '208' in family 'CFU'
Dec 21 13:43:48 VERBOSE[15840] logger.c:        >  dialparties.agi: extnum 208 has:  cw: 1; hascfb: 0 [] hascfu: 0 []
Dec 21 13:43:48 DEBUG[15840] db.c: Unable to find key '209' in family 'CFB'
Dec 21 13:43:48 DEBUG[15840] db.c: Unable to find key '209' in family 'CFU'
Dec 21 13:43:48 VERBOSE[15840] logger.c:        >  dialparties.agi: extnum 209 has:  cw: 1; hascfb: 0 [] hascfu: 0 []
Dec 21 13:43:48 DEBUG[15840] db.c: Unable to find key '206' in family 'CFB'
Dec 21 13:43:48 DEBUG[15840] db.c: Unable to find key '206' in family 'CFU'
Dec 21 13:43:48 VERBOSE[15840] logger.c:        >  dialparties.agi: extnum 206 has:  cw: 1; hascfb: 0 [] hascfu: 0 []
Dec 21 13:43:48 VERBOSE[15840] logger.c:        >  dialparties.agi: NODEST: 600 adding M(auto-blkvm) to dialopts: M(auto-blkvm)
Dec 21 13:43:48 VERBOSE[15840] logger.c:        >  dialparties.agi: NODEST: 600 blkvm enabled macro already in dialopts: M(auto-blkvm)
Dec 21 13:43:48 DEBUG[15847] manager.c: Manager received command 'Logoff'
Dec 21 13:43:48 VERBOSE[15847] logger.c:   == Manager 'admin' logged off from 127.0.0.1
Dec 21 13:43:48 VERBOSE[15840] logger.c:     -- AGI Script dialparties.agi completed, returning 0
Dec 21 13:43:48 DEBUG[15840] app_macro.c: Executed application: AGI
Dec 21 13:43:48 VERBOSE[15840] logger.c:     -- Executing NoOp("Zap/2-1", "Returned from dialparties with hunt groups to dial ") in new stack
Dec 21 13:43:48 DEBUG[15840] app_macro.c: Executed application: NoOp
Dec 21 13:43:48 VERBOSE[15840] logger.c:     -- Executing Set("Zap/2-1", "HuntLoop=0") in new stack
Dec 21 13:43:48 DEBUG[15840] app_macro.c: Executed application: Set Dec 21 13:43:48 DEBUG[15840] pbx.c: Expression result is '1'
Dec 21 13:43:48 VERBOSE[15840] logger.c:     -- Executing GotoIf("Zap/2-1", "1?30 ") in new stack
Dec 21 13:43:48 VERBOSE[15840] logger.c:     -- Goto (macro-dial,s,30)
Dec 21 13:43:48 DEBUG[15840] app_macro.c: Executed application: GotoIf
Dec 21 13:43:48 VERBOSE[15840] logger.c:     -- Executing Set("Zap/2-1", "HuntMember=HuntMember0") in new stack
Dec 21 13:43:48 DEBUG[15840] app_macro.c: Executed application: Set Dec 21 13:43:48 DEBUG[15840] pbx.c: Expression result is '1'
Dec 21 13:43:48 DEBUG[15840] pbx.c: Expression result is '1'
Dec 21 13:43:48 DEBUG[15840] pbx.c: Expression result is '1'
Dec 21 13:43:48 VERBOSE[15840] logger.c:     -- Executing GotoIf("Zap/2-1", "1?32:35 ") in new stack
Dec 21 13:43:48 VERBOSE[15840] logger.c:     -- Goto (macro-dial,s,32)
Dec 21 13:43:48 DEBUG[15840] app_macro.c: Executed application: GotoIf Dec 21 13:43:48 DEBUG[15840] pbx.c: Expression result is '1'
Dec 21 13:43:48 DEBUG[15840] pbx.c: Function result is '203'
Dec 21 13:43:48 VERBOSE[15840] logger.c:     -- Executing Set("Zap/2-1", "CT_EXTEN=203") in new stack
Dec 21 13:43:48 DEBUG[15840] app_macro.c: Executed application: Set
Dec 21 13:43:48 VERBOSE[15840] logger.c:     -- Executing Set("Zap/2-1", "DB(CALLTRACE/203)=unknown") in new stack
Dec 21 13:43:48 DEBUG[15840] app_macro.c: Executed application: Set
Dec 21 13:43:48 VERBOSE[15840] logger.c:     -- Executing Goto("Zap/2-1", "s|42") in new stack
Dec 21 13:43:48 VERBOSE[15840] logger.c:     -- Goto (macro-dial,s,42)
Dec 21 13:43:48 DEBUG[15840] app_macro.c: Executed application: Goto
Dec 21 13:43:48 VERBOSE[15840] logger.c:     -- Executing Dial("Zap/2-1", "SIP/203|20|M(auto-blkvm) ") in new stack
Dec 21 13:43:48 DEBUG[15840] chan_sip.c: Setting NAT on RTP to 0 Dec 21 13:43:48 DEBUG[15840] chan_sip.c: Outgoing Call for 203
Dec 21 13:43:48 VERBOSE[15840] logger.c:     -- Called 203
Dec 21 13:43:48 DEBUG[3788] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '64c1f5541d03656d3fe430ce00c9a4c6 at 192.168.1.6' Request 102: Found Dec 21 13:43:48 DEBUG[3788] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '64c1f5541d03656d3fe430ce00c9a4c6 at 192.168.1.6' Request 102: Found
Dec 21 13:43:48 VERBOSE[15840] logger.c:     -- SIP/203-09632e30 is ringing
Dec 21 13:43:48 DEBUG[15840] chan_zap.c: Requested indication 3 on channel Zap/2-1 Dec 21 13:43:49 DEBUG[15840] chan_zap.c: Exception on 13, channel 2 Dec 21 13:43:49 DEBUG[15840] chan_zap.c: Got event Ring/Answered(2) on channel 2 (index 0) Dec 21 13:43:49 DEBUG[15840] chan_zap.c: Setting IDLE polarity due to ring. Old polarity was 0 Dec 21 13:43:51 DEBUG[15840] chan_zap.c: Exception on 13, channel 2 Dec 21 13:43:51 DEBUG[15840] chan_zap.c: Got event Ring Begin(18) on channel 2 (index 0) Dec 21 13:43:52 DEBUG[15840] chan_zap.c: Exception on 13, channel 2 Dec 21 13:43:52 DEBUG[15840] chan_zap.c: Got event Ring/Answered(2) on channel 2 (index 0) Dec 21 13:43:52 DEBUG[15840] chan_zap.c: Setting IDLE polarity due to ring. Old polarity was 0 Dec 21 13:43:59 DEBUG[3788] chan_sip.c: Acked pending invite 102 Dec 21 13:43:59 DEBUG[3788] chan_sip.c: Stopping retransmission on '64c1f5541d03656d3fe430ce00c9a4c6 at 192.168.1.6' of Request 102: Match Found Dec 21 13:43:59 DEBUG[3788] chan_sip.c: build_route: Contact hop: <sip:203 at 192.168.1.108:5060> Dec 21 13:43:59 DEBUG[3398] channel.c: Avoiding initial deadlock for 'SIP/203-09632e30'
Dec 21 13:43:59 VERBOSE[15840] logger.c:     -- SIP/203-09632e30 answered Zap/2-1
Dec 21 13:43:59 VERBOSE[15840] logger.c:     -- Executing Set("SIP/203-09632e30", "__MACRO_RESULT=") in new stack
Dec 21 13:43:59 DEBUG[15840] app_macro.c: Executed application: Set
Dec 21 13:43:59 VERBOSE[15840] logger.c:     -- Executing DBdel("SIP/203-09632e30", "BLKVM/600/Zap/2-1") in new stack
Dec 21 13:43:59 VERBOSE[15840] logger.c:     -- DBdel: family=BLKVM, key=600/Zap/2-1
Dec 21 13:43:59 DEBUG[15840] app_macro.c: Executed application: DBDel Dec 21 13:43:59 DEBUG[15840] app_dial.c: Macro exited with status 0 Dec 21 13:43:59 DEBUG[15840] chan_zap.c: Requested indication -1 on channel Zap/2-1 Dec 21 13:43:59 DEBUG[3398] channel.c: Avoiding initial deadlock for 'Zap/2-1'
Dec 21 13:43:59 DEBUG[15840] chan_zap.c: Took Zap/2-1 off hook Dec 21 13:43:59 DEBUG[15840] chan_zap.c: Enabled echo cancellation on channel 2 Dec 21 13:43:59 WARNING[15840] chan_zap.c: Unable to request echo training on channel 2

Dec 21 13:44:02 DEBUG[15840] channel.c: Didn't get a frame from channel: SIP/203-09632e30

Dec 21 13:44:02 DEBUG[15840] channel.c: Bridge stops bridging channels Zap/2-1 and SIP/203-09632e30 Dec 21 13:44:02 DEBUG[15840] chan_sip.c: update_call_counter(203) - decrement call limit counter Dec 21 13:44:02 DEBUG[15840] app_dial.c: Exiting with DIALSTATUS=ANSWER.
Dec 21 13:44:02 VERBOSE[15840] logger.c:   == Spawn extension (macro-dial, s, 42) exited non-zero on 'Zap/2-1' in macro 'dial'
Dec 21 13:44:02 VERBOSE[15840] logger.c:   == Spawn extension (macro-dial, s, 42) exited non-zero on 'Zap/2-1'
Dec 21 13:44:02 VERBOSE[15840] logger.c:     -- Executing Macro("Zap/2-1", "hangupcall") in new stack
Dec 21 13:44:02 VERBOSE[15840] logger.c:     -- Executing ResetCDR("Zap/2-1", "w") in new stack
Dec 21 13:44:02 DEBUG[15840] cdr_addon_mysql.c: cdr_mysql: inserting a CDR record.
Dec 21 13:44:02 DEBUG[15840] 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-12-21 13:43:48','Leongatha:','','600','ext-group', 'Zap/2-1','SIP/203-09632e30','ResetCDR','w',14,3,'ANSWERED',3,'','1198205023.1657')
Dec 21 13:44:02 DEBUG[15840] app_macro.c: Executed application: ResetCDR
Dec 21 13:44:02 VERBOSE[15840] logger.c:     -- Executing NoCDR("Zap/2-1", "") in new stack
Dec 21 13:44:02 NOTICE[15840] cdr.c: CDR on channel 'Zap/2-1' not posted Dec 21 13:44:02 NOTICE[15840] cdr.c: CDR on channel 'Zap/2-1' lacks end Dec 21 13:44:02 DEBUG[15840] app_macro.c: Executed application: NoCDR Dec 21 13:44:02 DEBUG[15840] pbx.c: Expression result is '1'
Dec 21 13:44:02 VERBOSE[15840] logger.c:     -- Executing GotoIf("Zap/2-1", "1?skiprg") in new stack
Dec 21 13:44:02 VERBOSE[15840] logger.c:     -- Goto (macro-hangupcall,s,6)
Dec 21 13:44:02 DEBUG[15840] app_macro.c: Executed application: GotoIf Dec 21 13:44:02 DEBUG[15840] pbx.c: Expression result is '0'
Dec 21 13:44:02 VERBOSE[15840] logger.c:     -- Executing GotoIf("Zap/2-1", "0?skipblkvm") in new stack
Dec 21 13:44:02 DEBUG[15840] pbx.c: Not taking any branch Dec 21 13:44:02 DEBUG[15840] app_macro.c: Executed application: GotoIf
Dec 21 13:44:02 VERBOSE[15840] logger.c:     -- Executing NoOp("Zap/2-1", "Cleaning Up Block VM Flag: BLKVM/600/Zap/2-1") in new stack
Dec 21 13:44:02 DEBUG[15840] app_macro.c: Executed application: Noop
Dec 21 13:44:02 VERBOSE[15840] logger.c:     -- Executing DBdel("Zap/2-1", "BLKVM/600/Zap/2-1") in new stack
Dec 21 13:44:02 VERBOSE[15840] logger.c:     -- DBdel: family=BLKVM, key=600/Zap/2-1
Dec 21 13:44:02 DEBUG[15840] db.c: Unable to find key '600/Zap/2-1' in family 'BLKVM'
Dec 21 13:44:02 VERBOSE[15840] logger.c:     -- DBdel: Error deleting key from database.
Dec 21 13:44:02 DEBUG[15840] app_macro.c: Executed application: DBDel Dec 21 13:44:02 DEBUG[15840] pbx.c: Expression result is '1'
Dec 21 13:44:02 VERBOSE[15840] logger.c:     -- Executing GotoIf("Zap/2-1", "1?theend") in new stack
Dec 21 13:44:02 VERBOSE[15840] logger.c:     -- Goto (macro-hangupcall,s,11)
Dec 21 13:44:02 DEBUG[15840] app_macro.c: Executed application: GotoIf
Dec 21 13:44:02 VERBOSE[15840] logger.c:     -- Executing Hangup("Zap/2-1", "") in new stack
Dec 21 13:44:02 VERBOSE[15840] logger.c:   == Spawn extension (macro-hangupcall, s, 11) exited non-zero on 'Zap/2-1' in macro 'hangupcall'
Dec 21 13:44:02 VERBOSE[15840] logger.c:   == Spawn extension (macro-hangupcall, s, 11) exited non-zero on 'Zap/2-1'
Dec 21 13:44:02 DEBUG[15840] chan_zap.c: Hangup: channel: 2 index = 0, normal = 13, callwait = -1, thirdcall = -1 Dec 21 13:44:02 DEBUG[15840] chan_zap.c: disabled echo cancellation on channel 2 Dec 21 13:44:02 DEBUG[15840] chan_zap.c: Set option TDD MODE, value: OFF(0) on Zap/2-1 Dec 21 13:44:02 DEBUG[15840] chan_zap.c: Updated conferencing on 2, with 0 conference users
Dec 21 13:44:02 VERBOSE[15840] logger.c:     -- Hungup 'Zap/2-1'