May 29 17:02:08 DEBUG[2701] chan_zap.c: Requested indication 3 on channel Zap/2-1
May 29 17:02:08 DEBUG[2701] pbx.c: Expression result is '1'
May 29 17:02:08 DEBUG[2701] pbx.c: Function result is 's'
May 29 17:02:08 DEBUG[2701] pbx.c: Expression result is '1'
May 29 17:02:08 DEBUG[2701] pbx.c: Function result is '2'
May 29 17:02:08 WARNING[2701] app_macro.c: No such context 'macro-from-zaptel-2' for macro 'from-zaptel-2'
May 29 17:02:08 DEBUG[2701] db.c: Unable to find key '5038513831' in family 'blacklist'
May 29 17:02:08 DEBUG[2701] pbx.c: Expression result is '0'
May 29 17:02:08 DEBUG[2701] pbx.c: Not taking any branch
May 29 17:02:08 DEBUG[2701] pbx.c: Function result is ''
May 29 17:02:08 DEBUG[2701] pbx.c: Expression result is '0'
May 29 17:02:08 DEBUG[2701] pbx.c: Not taking any branch
May 29 17:02:08 DEBUG[2701] pbx.c: Function result is '5038513831'
May 29 17:02:08 DEBUG[2701] pbx.c: Function result is '"5038513831" <5038513831>'
May 29 17:02:08 DEBUG[2701] pbx.c: Function result is '5038513831'
May 29 17:02:08 DEBUG[2701] pbx.c: Function result is '5038513831'
May 29 17:02:08 DEBUG[2701] pbx.c: Expression result is '0'
May 29 17:02:08 DEBUG[2701] pbx.c: Not taking any branch
May 29 17:02:08 DEBUG[2701] pbx.c: Expression result is '0'
May 29 17:02:08 DEBUG[2701] pbx.c: Not taking any branch
May 29 17:02:08 DEBUG[2701] pbx.c: Function result is '5038513831'
May 29 17:02:08 DEBUG[2701] db.c: Unable to find key '5038513831/user' in family 'DEVICE'
May 29 17:02:08 DEBUG[2701] func_db.c: DB: DEVICE/5038513831/user not found in database.
May 29 17:02:08 DEBUG[2701] pbx.c: Function result is ''
May 29 17:02:08 DEBUG[2701] db.c: Unable to find key '/cidname' in family 'AMPUSER'
May 29 17:02:08 DEBUG[2701] func_db.c: DB: AMPUSER//cidname not found in database.
May 29 17:02:08 DEBUG[2701] pbx.c: Function result is ''
May 29 17:02:08 DEBUG[2701] pbx.c: Expression result is '1'
May 29 17:02:08 DEBUG[2701] pbx.c: Expression result is '0'
May 29 17:02:08 DEBUG[2701] pbx.c: Not taking any branch
May 29 17:02:08 DEBUG[2701] pbx.c: Expression result is '1'
May 29 17:02:08 DEBUG[2701] pbx.c: Expression result is '-1'
May 29 17:02:08 DEBUG[2701] pbx.c: Function result is '64'
May 29 17:02:08 DEBUG[2701] pbx.c: Expression result is '1'
May 29 17:02:08 DEBUG[2701] pbx.c: Function result is '"5038513831" <5038513831>'
May 29 17:02:08 DEBUG[2701] pbx.c: Expression result is '1'
May 29 17:02:08 DEBUG[2701] pbx.c: Expression result is '1'
May 29 17:02:08 DEBUG[2701] pbx.c: Function result is '5038513831'
May 29 17:02:08 DEBUG[2701] pbx.c: Function result is '201-5038510262#'
May 29 17:02:08 DEBUG[2701] pbx.c: Function result is '0'
May 29 17:02:08 DEBUG[2701] pbx.c: Expression result is '0'
May 29 17:02:08 DEBUG[2701] db.c: Unable to find key '5038510262#/recording' in family 'AMPUSER'
May 29 17:02:08 VERBOSE[2701] logger.c: recordingcheck|20070529-170208|1180483327.767: No DB Entry AMPUSER/5038510262#/recording - Not recording
May 29 17:02:09 DEBUG[2701] pbx.c: Function result is 'ENABLED'
May 29 17:02:09 DEBUG[2701] pbx.c: Expression result is '1'
May 29 17:02:09 DEBUG[2701] pbx.c: Function result is '20'
May 29 17:02:09 DEBUG[2701] pbx.c: Function result is '4'
May 29 17:02:09 DEBUG[2701] pbx.c: Expression result is '24'
May 29 17:02:09 DEBUG[2701] pbx.c: Function result is '201-5038510262#'
May 29 17:02:09 VERBOSE[2701] logger.c: dialparties.agi: Starting New Dialparties.agi
May 29 17:02:09 DEBUG[2705] manager.c: Manager received command 'login'
May 29 17:02:09 DEBUG[2705] acl.c: 0.0.0.0/0.0.0.0/0.0.0.0 appended to acl for peer
May 29 17:02:09 DEBUG[2705] acl.c: 127.0.0.1/255.255.255.0/255.255.255.0 appended to acl for peer
May 29 17:02:09 DEBUG[2705] acl.c: ##### Testing 127.0.0.1 with 0.0.0.0
May 29 17:02:09 DEBUG[2705] acl.c: ##### Testing 127.0.0.1 with 127.0.0.0
May 29 17:02:09 VERBOSE[2701] logger.c: dialparties.agi: priority is 1
May 29 17:02:09 VERBOSE[2701] logger.c: dialparties.agi: Caller ID name is '5038513831' number is '5038513831'
May 29 17:02:09 VERBOSE[2701] logger.c: dialparties.agi: Methodology of ring is 'ringallv2-prim'
May 29 17:02:09 DEBUG[2701] db.c: Unable to find key '201' in family 'CF'
May 29 17:02:09 DEBUG[2701] db.c: Unable to find key '5038510262#' in family 'CF'
May 29 17:02:09 DEBUG[2701] db.c: Unable to find key '201' in family 'DND'
May 29 17:02:09 DEBUG[2701] db.c: Unable to find key '201' in family 'CFB'
May 29 17:02:09 DEBUG[2701] db.c: Unable to find key '201' in family 'CFU'
May 29 17:02:09 DEBUG[2705] manager.c: Manager received command 'ExtensionState'
May 29 17:02:09 VERBOSE[2701] logger.c: dialparties.agi: Extension 201 has ExtensionState: 0
May 29 17:02:09 DEBUG[2701] db.c: Unable to find key '5038510262#' in family 'CW'
May 29 17:02:09 DEBUG[2701] db.c: Unable to find key '5038510262#' in family 'CFB'
May 29 17:02:09 DEBUG[2701] db.c: Unable to find key '5038510262#' in family 'CFU'
May 29 17:02:09 DEBUG[2705] manager.c: Manager received command 'Logoff'
May 29 17:02:09 DEBUG[2706] pbx.c: Function result is '5038513831'
May 29 17:02:09 DEBUG[2706] pbx.c: Function result is '5038513831'
May 29 17:02:09 DEBUG[2706] pbx.c: Expression result is '1'
May 29 17:02:09 DEBUG[2706] pbx.c: Expression result is '1'
May 29 17:02:09 DEBUG[2706] pbx.c: Function result is '"5038513831" <5038513831>'
May 29 17:02:09 DEBUG[2706] db.c: Unable to find key '201' in family 'CFU'
May 29 17:02:09 DEBUG[2706] func_db.c: DB: CFU/201 not found in database.
May 29 17:02:09 DEBUG[2706] pbx.c: Function result is ''
May 29 17:02:09 DEBUG[2706] db.c: Unable to find key '201' in family 'CFB'
May 29 17:02:09 DEBUG[2706] func_db.c: DB: CFB/201 not found in database.
May 29 17:02:09 DEBUG[2706] pbx.c: Function result is ''
May 29 17:02:09 DEBUG[2706] pbx.c: Function result is '0'
May 29 17:02:09 DEBUG[2706] pbx.c: Expression result is '0'
May 29 17:02:09 DEBUG[2707] db.c: Unable to find key 'DND/201/Zap/2-1' in family 'FM'
May 29 17:02:09 DEBUG[2707] func_db.c: DB: FM/DND/201/Zap/2-1 not found in database.
May 29 17:02:09 DEBUG[2707] pbx.c: Function result is ''
May 29 17:02:09 DEBUG[2707] pbx.c: Expression result is '0'
May 29 17:02:09 DEBUG[2707] pbx.c: Not taking any branch
May 29 17:02:09 VERBOSE[2706] logger.c: recordingcheck|20070529-170209|1180483329.769: Inbound recording not enabled
May 29 17:02:09 VERBOSE[2706] logger.c: dialparties.agi: Starting New Dialparties.agi
May 29 17:02:09 DEBUG[2712] manager.c: Manager received command 'login'
May 29 17:02:09 DEBUG[2712] acl.c: 0.0.0.0/0.0.0.0/0.0.0.0 appended to acl for peer
May 29 17:02:09 DEBUG[2712] acl.c: 127.0.0.1/255.255.255.0/255.255.255.0 appended to acl for peer
May 29 17:02:09 DEBUG[2712] acl.c: ##### Testing 127.0.0.1 with 0.0.0.0
May 29 17:02:09 DEBUG[2712] acl.c: ##### Testing 127.0.0.1 with 127.0.0.0
May 29 17:02:09 VERBOSE[2706] logger.c: dialparties.agi: priority is 1
May 29 17:02:09 VERBOSE[2706] logger.c: dialparties.agi: Caller ID name is '5038513831' number is '5038513831'
May 29 17:02:09 VERBOSE[2706] logger.c: dialparties.agi: Methodology of ring is 'none'
May 29 17:02:09 DEBUG[2706] db.c: Unable to find key '201' in family 'CF'
May 29 17:02:09 DEBUG[2706] db.c: Unable to find key '201' in family 'DND'
May 29 17:02:09 DEBUG[2706] db.c: Unable to find key '201' in family 'CFB'
May 29 17:02:09 DEBUG[2706] db.c: Unable to find key '201' in family 'CFU'
May 29 17:02:09 DEBUG[2712] manager.c: Manager received command 'Logoff'
May 29 17:02:09 DEBUG[2706] chan_sip.c: Setting NAT on RTP to 524288
May 29 17:02:09 DEBUG[2706] acl.c: ##### Testing 192.168.2.92 with 192.168.2.0
May 29 17:02:09 DEBUG[2706] chan_sip.c: Outgoing Call for 201
May 29 17:02:09 DEBUG[2731] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '6bd6c4cd11c25c8d61f633bd2845f265@192.168.2.12' Request 102: Found
May 29 17:02:09 DEBUG[2731] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '6bd6c4cd11c25c8d61f633bd2845f265@192.168.2.12' Request 102: Found
May 29 17:02:09 DEBUG[2701] chan_zap.c: Requested indication 3 on channel Zap/2-1
May 29 17:02:10 DEBUG[2707] db.c: Unable to find key 'DND/201/Zap/2-1' in family 'FM'
May 29 17:02:10 DEBUG[2707] func_db.c: DB: FM/DND/201/Zap/2-1 not found in database.
May 29 17:02:10 DEBUG[2707] pbx.c: Function result is ''
May 29 17:02:10 DEBUG[2707] pbx.c: Expression result is '0'
May 29 17:02:10 DEBUG[2707] pbx.c: Not taking any branch
May 29 17:02:11 DEBUG[2707] db.c: Unable to find key 'DND/201/Zap/2-1' in family 'FM'
May 29 17:02:11 DEBUG[2707] func_db.c: DB: FM/DND/201/Zap/2-1 not found in database.
May 29 17:02:11 DEBUG[2707] pbx.c: Function result is ''
May 29 17:02:11 DEBUG[2707] pbx.c: Expression result is '0'
May 29 17:02:11 DEBUG[2707] pbx.c: Not taking any branch
May 29 17:02:11 DEBUG[2701] chan_zap.c: Exception on 19, channel 2
May 29 17:02:11 DEBUG[2701] chan_zap.c: Got event Ring Begin(18) on channel 2 (index 0)
May 29 17:02:13 DEBUG[2707] db.c: Unable to find key 'DND/201/Zap/2-1' in family 'FM'
May 29 17:02:13 DEBUG[2707] func_db.c: DB: FM/DND/201/Zap/2-1 not found in database.
May 29 17:02:13 DEBUG[2707] pbx.c: Function result is ''
May 29 17:02:13 DEBUG[2707] pbx.c: Expression result is '0'
May 29 17:02:13 DEBUG[2707] pbx.c: Not taking any branch
May 29 17:02:13 DEBUG[2707] db.c: Unable to find key 'DND/201/Zap/2-1' in family 'FM'
May 29 17:02:13 VERBOSE[2707] logger.c: dialparties.agi: Starting New Dialparties.agi
May 29 17:02:13 DEBUG[2715] manager.c: Manager received command 'login'
May 29 17:02:13 DEBUG[2715] acl.c: 0.0.0.0/0.0.0.0/0.0.0.0 appended to acl for peer
May 29 17:02:13 DEBUG[2715] acl.c: 127.0.0.1/255.255.255.0/255.255.255.0 appended to acl for peer
May 29 17:02:13 DEBUG[2715] acl.c: ##### Testing 127.0.0.1 with 0.0.0.0
May 29 17:02:13 DEBUG[2715] acl.c: ##### Testing 127.0.0.1 with 127.0.0.0
May 29 17:02:13 VERBOSE[2707] logger.c: dialparties.agi: priority is 1
May 29 17:02:13 VERBOSE[2707] logger.c: dialparties.agi: Caller ID name is '5038513831' number is '5038513831'
May 29 17:02:13 VERBOSE[2707] logger.c: dialparties.agi: Methodology of ring is 'ringall'
May 29 17:02:13 DEBUG[2707] db.c: Unable to find key '5038510262#' in family 'CF'
May 29 17:02:13 DEBUG[2707] db.c: Unable to find key '5038510262#' in family 'CW'
May 29 17:02:13 DEBUG[2707] db.c: Unable to find key '5038510262#' in family 'CFB'
May 29 17:02:13 DEBUG[2707] db.c: Unable to find key '5038510262#' in family 'CFU'
May 29 17:02:13 DEBUG[2715] manager.c: Manager received command 'Logoff'
May 29 17:02:13 DEBUG[2716] pbx.c: Function result is '20'
May 29 17:02:13 DEBUG[2701] chan_zap.c: Exception on 19, channel 2
May 29 17:02:13 DEBUG[2701] chan_zap.c: Got event Ring/Answered(2) on channel 2 (index 0)
May 29 17:02:13 DEBUG[2701] chan_zap.c: Setting IDLE polarity due to ring. Old polarity was 0
May 29 17:02:13 VERBOSE[2716] logger.c: dialparties.agi: Starting New Dialparties.agi
May 29 17:02:13 DEBUG[2724] manager.c: Manager received command 'login'
May 29 17:02:13 DEBUG[2724] acl.c: 0.0.0.0/0.0.0.0/0.0.0.0 appended to acl for peer
May 29 17:02:13 DEBUG[2724] acl.c: 127.0.0.1/255.255.255.0/255.255.255.0 appended to acl for peer
May 29 17:02:13 DEBUG[2724] acl.c: ##### Testing 127.0.0.1 with 0.0.0.0
May 29 17:02:13 DEBUG[2724] acl.c: ##### Testing 127.0.0.1 with 127.0.0.0
May 29 17:02:13 VERBOSE[2716] logger.c: dialparties.agi: priority is 1
May 29 17:02:13 VERBOSE[2716] logger.c: dialparties.agi: Caller ID name is '5038513831' number is '5038513831'
May 29 17:02:13 VERBOSE[2716] logger.c: dialparties.agi: Methodology of ring is 'none'
May 29 17:02:13 DEBUG[2716] db.c: Unable to find key '5038510262#' in family 'CF'
May 29 17:02:13 DEBUG[2716] db.c: Unable to find key '5038510262#' in family 'CW'
May 29 17:02:13 DEBUG[2716] db.c: Unable to find key '5038510262#' in family 'CFB'
May 29 17:02:13 DEBUG[2716] db.c: Unable to find key '5038510262#' in family 'CFU'
May 29 17:02:13 DEBUG[2724] manager.c: Manager received command 'Logoff'
May 29 17:02:13 DEBUG[2736] pbx.c: Expression result is '1'
May 29 17:02:13 DEBUG[2736] pbx.c: Expression result is '0'
May 29 17:02:13 DEBUG[2736] pbx.c: Not taking any branch
May 29 17:02:13 DEBUG[2736] pbx.c: Function result is '5038513831'
May 29 17:02:13 DEBUG[2736] pbx.c: Function result is '5038513831'
May 29 17:02:13 DEBUG[2736] pbx.c: Expression result is '1'
May 29 17:02:13 DEBUG[2736] pbx.c: Expression result is '1'
May 29 17:02:13 DEBUG[2736] pbx.c: Function result is '"5038513831" <5038513831>'
May 29 17:02:13 DEBUG[2736] pbx.c: Function result is '5038513831'
May 29 17:02:13 DEBUG[2736] pbx.c: Function result is '0'
May 29 17:02:13 DEBUG[2736] pbx.c: Expression result is '0'
May 29 17:02:14 DEBUG[2736] db.c: Unable to find key '5038513831/recording' in family 'AMPUSER'
May 29 17:02:14 VERBOSE[2736] logger.c: recordingcheck|20070529-170213|1180483333.776: No AMPUSER db entry for 5038513831. Not recording
May 29 17:02:14 DEBUG[2731] chan_sip.c: Acked pending invite 102
May 29 17:02:14 DEBUG[2731] chan_sip.c: Stopping retransmission on '6bd6c4cd11c25c8d61f633bd2845f265@192.168.2.12' of Request 102: Match Found
May 29 17:02:14 DEBUG[2731] chan_sip.c: build_route: Contact hop: "$USER"
May 29 17:02:14 DEBUG[2706] app_dial.c: Macro exited with status 0
May 29 17:02:14 DEBUG[2701] chan_zap.c: Requested indication -1 on channel Zap/2-1
May 29 17:02:14 DEBUG[2701] db.c: Unable to find key '201/Zap/2-1' in family 'BLKVM'
May 29 17:02:14 DEBUG[2701] app_dial.c: Macro exited with status 0
May 29 17:02:14 DEBUG[2701] chan_zap.c: Took Zap/2-1 off hook
May 29 17:02:14 DEBUG[2701] chan_zap.c: Enabled echo cancellation on channel 2
May 29 17:02:14 DEBUG[2701] chan_zap.c: Engaged echo training on channel 2
May 29 17:02:14 DEBUG[2707] app_dial.c: Exiting with DIALSTATUS=CANCEL.
May 29 17:02:14 DEBUG[2716] app_dial.c: Exiting with DIALSTATUS=CANCEL.
May 29 17:02:14 DEBUG[2707] cdr_addon_mysql.c: cdr_mysql: inserting a CDR record.
May 29 17:02:14 DEBUG[2707] 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) VALUES ('2007-05-29 17:02:09','\"5038513831\" <5038513831>','5038513831','FMGL-5038510262#','from-internal', 'Local/FMGL-5038510262#@from-internal-5a79,2','Local/RG-201-5038510262#@from-internal-d70d,1','ResetCDR','w',5,0,'NO ANSWER',3,'')
May 29 17:02:14 NOTICE[2707] cdr.c: CDR on channel 'Local/FMGL-5038510262#@from-internal-5a79,2' not posted
May 29 17:02:14 NOTICE[2707] cdr.c: CDR on channel 'Local/FMGL-5038510262#@from-internal-5a79,2' lacks end
May 29 17:02:14 DEBUG[2707] pbx.c: Expression result is '1'
May 29 17:02:14 DEBUG[2707] pbx.c: Expression result is '1'
May 29 17:02:14 DEBUG[2707] pbx.c: Expression result is '1'
May 29 17:02:14 DEBUG[2716] cdr_addon_mysql.c: cdr_mysql: inserting a CDR record.
May 29 17:02:14 DEBUG[2716] 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) VALUES ('2007-05-29 17:02:13','\"5038513831\" <5038513831>','5038513831','RG-201-5038510262#','from-internal', 'Local/RG-201-5038510262#@from-internal-d70d,2','Local/5038510262@from-internal-82f2,1','ResetCDR','w',1,0,'NO ANSWER',3,'')
May 29 17:02:14 NOTICE[2716] cdr.c: CDR on channel 'Local/RG-201-5038510262#@from-internal-d70d,2' not posted
May 29 17:02:14 NOTICE[2716] cdr.c: CDR on channel 'Local/RG-201-5038510262#@from-internal-d70d,2' lacks end
May 29 17:02:14 DEBUG[2716] pbx.c: Expression result is '1'
May 29 17:02:14 DEBUG[2716] pbx.c: Expression result is '1'
May 29 17:02:14 DEBUG[2716] pbx.c: Expression result is '1'
May 29 17:02:14 DEBUG[2736] pbx.c: Expression result is '0'
May 29 17:02:14 DEBUG[2736] pbx.c: Not taking any branch
May 29 17:02:14 DEBUG[2736] pbx.c: Expression result is '0'
May 29 17:02:14 DEBUG[2736] pbx.c: Not taking any branch
May 29 17:02:14 DEBUG[2736] pbx.c: Function result is '5038513831'
May 29 17:02:14 DEBUG[2736] pbx.c: Expression result is '0'
May 29 17:02:14 DEBUG[2736] pbx.c: Not taking any branch
May 29 17:02:14 DEBUG[2736] pbx.c: Expression result is '0'
May 29 17:02:14 DEBUG[2736] pbx.c: Not taking any branch
May 29 17:02:14 DEBUG[2736] pbx.c: Expression result is '0'
May 29 17:02:14 DEBUG[2736] pbx.c: Not taking any branch
May 29 17:02:14 DEBUG[2736] db.c: Unable to find key '5038513831/device' in family 'AMPUSER'
May 29 17:02:14 DEBUG[2736] func_db.c: DB: AMPUSER/5038513831/device not found in database.
May 29 17:02:14 DEBUG[2736] pbx.c: Function result is ''
May 29 17:02:14 DEBUG[2736] pbx.c: Expression result is '1'
May 29 17:02:14 DEBUG[2736] db.c: Unable to find key '5038513831/emergency_cid' in family 'DEVICE'
May 29 17:02:14 DEBUG[2736] func_db.c: DB: DEVICE/5038513831/emergency_cid not found in database.
May 29 17:02:14 DEBUG[2736] pbx.c: Function result is ''
May 29 17:02:14 DEBUG[2736] pbx.c: Expression result is '1'
May 29 17:02:14 DEBUG[2736] pbx.c: Expression result is '0'
May 29 17:02:14 DEBUG[2736] pbx.c: Not taking any branch
May 29 17:02:14 DEBUG[2736] pbx.c: Expression result is '0'
May 29 17:02:14 DEBUG[2736] pbx.c: Not taking any branch
May 29 17:02:14 DEBUG[2736] pbx.c: Function result is ''
May 29 17:02:14 DEBUG[2736] pbx.c: Expression result is '1'
May 29 17:02:14 DEBUG[2736] pbx.c: Function result is '"" <5038513831>'
May 29 17:02:14 DEBUG[2736] pbx.c: Expression result is '0'
May 29 17:02:14 DEBUG[2736] pbx.c: Not taking any branch
May 29 17:02:14 DEBUG[2736] pbx.c: Function result is '1'
May 29 17:02:14 DEBUG[2736] pbx.c: Expression result is '0'
May 29 17:02:14 DEBUG[2736] pbx.c: Not taking any branch
May 29 17:02:14 DEBUG[2736] pbx.c: Function result is 'SIP/telasip-gw'
May 29 17:02:14 DEBUG[2736] pbx.c: Expression result is '0'
May 29 17:02:14 DEBUG[2736] pbx.c: Expression result is '1'
May 29 17:02:14 DEBUG[2736] pbx.c: Expression result is '1'
May 29 17:02:14 DEBUG[2736] pbx.c: Expression result is '0'
May 29 17:02:14 DEBUG[2736] pbx.c: Not taking any branch
May 29 17:02:14 DEBUG[2736] chan_sip.c: Setting NAT on RTP to 0
May 29 17:02:14 DEBUG[2736] acl.c: ##### Testing 216.93.169.208 with 192.168.2.0
May 29 17:02:14 DEBUG[2736] chan_sip.c: Target address 216.93.169.208 is not local, substituting externip
May 29 17:02:14 DEBUG[2736] chan_sip.c: Outgoing Call for 5038510262
May 29 17:02:14 DEBUG[2736] chan_sip.c: update_call_counter(5038510262) - decrement call limit counter
May 29 17:02:14 DEBUG[2736] chan_sip.c: Acked pending invite 102
May 29 17:02:14 DEBUG[2736] chan_sip.c: Stopping retransmission on '4cc2b9907806a8707f329c6319a06884@sea.telasip.com' of Request 102: Match Found
May 29 17:02:14 DEBUG[2736] app_dial.c: Exiting with DIALSTATUS=CANCEL.
May 29 17:02:14 DEBUG[2736] cdr_addon_mysql.c: cdr_mysql: inserting a CDR record.
May 29 17:02:14 DEBUG[2736] 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) VALUES ('2007-05-29 17:02:13','5038513831','5038513831','5038510262','from-internal', 'Local/5038510262@from-internal-82f2,2','SIP/telasip-gw-087c0e18','ResetCDR','w',1,0,'NO ANSWER',3,'')
May 29 17:02:14 NOTICE[2736] cdr.c: CDR on channel 'Local/5038510262@from-internal-82f2,2' not posted
May 29 17:02:14 NOTICE[2736] cdr.c: CDR on channel 'Local/5038510262@from-internal-82f2,2' lacks end
May 29 17:02:14 DEBUG[2736] pbx.c: Expression result is '1'
May 29 17:02:14 DEBUG[2736] pbx.c: Expression result is '1'
May 29 17:02:14 DEBUG[2736] pbx.c: Expression result is '1'
May 29 17:02:14 DEBUG[2731] chan_sip.c: Stopping retransmission on '4cc2b9907806a8707f329c6319a06884@sea.telasip.com' of Request 102: Match Not Found
May 29 17:02:24 DEBUG[2731] chan_sip.c: Auto destroying call '22e4eeba732d0afa69087394578e897b@127.0.0.1'
May 29 17:02:32 DEBUG[2701] chan_zap.c: Exception on 19, channel 2
May 29 17:02:32 DEBUG[2701] chan_zap.c: Got event On hook(1) on channel 2 (index 0)
May 29 17:02:32 DEBUG[2701] chan_zap.c: disabled echo cancellation on channel 2
May 29 17:02:32 DEBUG[2701] channel.c: Didn't get a frame from channel: Zap/2-1
May 29 17:02:32 DEBUG[2701] channel.c: Bridge stops bridging channels Zap/2-1 and Local/FMPR-201@from-internal-61ca,1
May 29 17:02:32 DEBUG[2701] app_dial.c: Exiting with DIALSTATUS=ANSWER.
May 29 17:02:32 DEBUG[2706] channel.c: Didn't get a frame from channel: Local/FMPR-201@from-internal-61ca,2
May 29 17:02:32 DEBUG[2706] channel.c: Bridge stops bridging channels Local/FMPR-201@from-internal-61ca,2 and SIP/201-087bae00
May 29 17:02:32 DEBUG[2706] chan_sip.c: update_call_counter(201) - decrement call limit counter
May 29 17:02:32 DEBUG[2706] app_dial.c: Exiting with DIALSTATUS=ANSWER.
May 29 17:02:32 DEBUG[2731] chan_sip.c: Stopping retransmission on '6bd6c4cd11c25c8d61f633bd2845f265@192.168.2.12' of Request 103: Match Found
May 29 17:02:32 DEBUG[2701] cdr_addon_mysql.c: cdr_mysql: inserting a CDR record.
May 29 17:02:32 DEBUG[2701] 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) VALUES ('2007-05-29 17:02:08','\"5038513831\" <5038513831>','5038513831','201','ext-findmefollow', 'Zap/2-1','Local/FMPR-201@from-internal-61ca,1','ResetCDR','w',24,18,'ANSWERED',3,'')
May 29 17:02:32 NOTICE[2701] cdr.c: CDR on channel 'Zap/2-1' not posted
May 29 17:02:32 NOTICE[2701] cdr.c: CDR on channel 'Zap/2-1' lacks end
May 29 17:02:32 DEBUG[2701] pbx.c: Expression result is '0'
May 29 17:02:32 DEBUG[2701] pbx.c: Not taking any branch
May 29 17:02:32 DEBUG[2706] cdr_addon_mysql.c: cdr_mysql: inserting a CDR record.
May 29 17:02:32 DEBUG[2706] 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) VALUES ('2007-05-29 17:02:09','\"5038513831\" <5038513831>','5038513831','FMPR-201','from-internal', 'Local/FMPR-201@from-internal-61ca,2','SIP/201-087bae00','ResetCDR','w',23,18,'ANSWERED',3,'')
May 29 17:02:32 NOTICE[2706] cdr.c: CDR on channel 'Local/FMPR-201@from-internal-61ca,2' not posted
May 29 17:02:32 NOTICE[2706] cdr.c: CDR on channel 'Local/FMPR-201@from-internal-61ca,2' lacks end
May 29 17:02:32 DEBUG[2706] pbx.c: Expression result is '1'
May 29 17:02:32 DEBUG[2706] pbx.c: Expression result is '1'
May 29 17:02:32 DEBUG[2706] pbx.c: Expression result is '1'
May 29 17:02:32 DEBUG[2701] pbx.c: Expression result is '0'
May 29 17:02:32 DEBUG[2701] pbx.c: Not taking any branch
May 29 17:02:32 DEBUG[2701] db.c: Unable to find key '201/Zap/2-1' in family 'BLKVM'
May 29 17:02:32 DEBUG[2701] pbx.c: Expression result is '0'
May 29 17:02:32 DEBUG[2701] pbx.c: Not taking any branch
May 29 17:02:32 DEBUG[2701] db.c: Unable to find key 'DND/201/Zap/2-1' in family 'FM'
May 29 17:02:32 DEBUG[2701] chan_zap.c: Hangup: channel: 2 index = 0, normal = 19, callwait = -1, thirdcall = -1
May 29 17:02:32 DEBUG[2701] chan_zap.c: disabled echo cancellation on channel 2
May 29 17:02:32 DEBUG[2701] chan_zap.c: Set option TDD MODE, value: OFF(0) on Zap/2-1
May 29 17:02:32 DEBUG[2701] chan_zap.c: Updated conferencing on 2, with 0 conference users
May 29 17:02:37 DEBUG[2731] acl.c: ##### Testing 64.2.142.26 with 192.168.2.0
May 29 17:02:37 DEBUG[2731] chan_sip.c: Target address 64.2.142.26 is not local, substituting externip
May 29 17:02:37 DEBUG[2731] chan_sip.c: Scheduled a registration timeout for inbound1.vitelity.net id #302832
May 29 17:02:37 DEBUG[2731] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '22e4eeba732d0afa69087394578e897b@127.0.0.1' Request 4021: Found
May 29 17:02:37 DEBUG[2731] chan_sip.c: Stopping retransmission on '22e4eeba732d0afa69087394578e897b@127.0.0.1' of Request 4021: Match Found
May 29 17:02:37 DEBUG[2731] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '22e4eeba732d0afa69087394578e897b@127.0.0.1' Request 4022: Found
May 29 17:02:37 DEBUG[2731] chan_sip.c: Stopping retransmission on '22e4eeba732d0afa69087394578e897b@127.0.0.1' of Request 4022: Match Found
May 29 17:02:37 DEBUG[2731] chan_sip.c: Registration successful
May 29 17:02:37 DEBUG[2731] chan_sip.c: Cancelling timeout 302832
May 29 17:02:42 DEBUG[2759] chan_zap.c: Requested indication 3 on channel Zap/2-1
May 29 17:02:42 DEBUG[2759] pbx.c: Expression result is '1'
May 29 17:02:42 DEBUG[2759] pbx.c: Function result is 's'
May 29 17:02:42 DEBUG[2759] pbx.c: Expression result is '1'
May 29 17:02:42 DEBUG[2759] pbx.c: Function result is '2'
May 29 17:02:42 WARNING[2759] app_macro.c: No such context 'macro-from-zaptel-2' for macro 'from-zaptel-2'
May 29 17:02:42 DEBUG[2759] db.c: Unable to find key '5038513831' in family 'blacklist'
May 29 17:02:42 DEBUG[2759] pbx.c: Expression result is '0'
May 29 17:02:42 DEBUG[2759] pbx.c: Not taking any branch
May 29 17:02:42 DEBUG[2759] pbx.c: Function result is ''
May 29 17:02:42 DEBUG[2759] pbx.c: Expression result is '0'
May 29 17:02:42 DEBUG[2759] pbx.c: Not taking any branch
May 29 17:02:42 DEBUG[2759] pbx.c: Function result is '5038513831'
May 29 17:02:42 DEBUG[2759] pbx.c: Function result is '"5038513831" <5038513831>'
May 29 17:02:42 DEBUG[2759] pbx.c: Function result is '5038513831'
May 29 17:02:42 DEBUG[2759] pbx.c: Function result is '5038513831'
May 29 17:02:42 DEBUG[2759] pbx.c: Expression result is '0'
May 29 17:02:42 DEBUG[2759] pbx.c: Not taking any branch
May 29 17:02:42 DEBUG[2759] pbx.c: Expression result is '0'
May 29 17:02:42 DEBUG[2759] pbx.c: Not taking any branch
May 29 17:02:42 DEBUG[2759] pbx.c: Function result is '5038513831'
May 29 17:02:42 DEBUG[2759] db.c: Unable to find key '5038513831/user' in family 'DEVICE'
May 29 17:02:42 DEBUG[2759] func_db.c: DB: DEVICE/5038513831/user not found in database.
May 29 17:02:42 DEBUG[2759] pbx.c: Function result is ''
May 29 17:02:42 DEBUG[2759] db.c: Unable to find key '/cidname' in family 'AMPUSER'
May 29 17:02:42 DEBUG[2759] func_db.c: DB: AMPUSER//cidname not found in database.
May 29 17:02:42 DEBUG[2759] pbx.c: Function result is ''
May 29 17:02:42 DEBUG[2759] pbx.c: Expression result is '1'
May 29 17:02:42 DEBUG[2759] pbx.c: Expression result is '0'
May 29 17:02:42 DEBUG[2759] pbx.c: Not taking any branch
May 29 17:02:42 DEBUG[2759] pbx.c: Expression result is '1'
May 29 17:02:42 DEBUG[2759] pbx.c: Expression result is '-1'
May 29 17:02:42 DEBUG[2759] pbx.c: Function result is '64'
May 29 17:02:42 DEBUG[2759] pbx.c: Expression result is '1'
May 29 17:02:42 DEBUG[2759] pbx.c: Function result is '"5038513831" <5038513831>'
May 29 17:02:42 DEBUG[2759] pbx.c: Expression result is '1'
May 29 17:02:42 DEBUG[2759] pbx.c: Expression result is '1'
May 29 17:02:42 DEBUG[2759] pbx.c: Function result is '5038513831'
May 29 17:02:42 DEBUG[2759] pbx.c: Function result is '201-5038510262#'
May 29 17:02:42 DEBUG[2759] pbx.c: Function result is '0'
May 29 17:02:42 DEBUG[2759] pbx.c: Expression result is '0'
May 29 17:02:42 DEBUG[2759] db.c: Unable to find key '5038510262#/recording' in family 'AMPUSER'
May 29 17:02:42 VERBOSE[2759] logger.c: recordingcheck|20070529-170242|1180483361.778: No DB Entry AMPUSER/5038510262#/recording - Not recording
May 29 17:02:42 DEBUG[2759] pbx.c: Function result is 'ENABLED'
May 29 17:02:42 DEBUG[2759] pbx.c: Expression result is '1'
May 29 17:02:42 DEBUG[2759] pbx.c: Function result is '20'
May 29 17:02:42 DEBUG[2759] pbx.c: Function result is '4'
May 29 17:02:42 DEBUG[2759] pbx.c: Expression result is '24'
May 29 17:02:42 DEBUG[2759] pbx.c: Function result is '201-5038510262#'
May 29 17:02:42 DEBUG[2731] acl.c: ##### Testing 216.93.169.208 with 192.168.2.0
May 29 17:02:42 DEBUG[2731] chan_sip.c: Target address 216.93.169.208 is not local, substituting externip
May 29 17:02:42 DEBUG[2731] chan_sip.c: Stopping retransmission on '5e75410803314d3f7e7975904367c47a@71.237.146.239' of Request 102: Match Found
May 29 17:02:42 VERBOSE[2759] logger.c: dialparties.agi: Starting New Dialparties.agi
May 29 17:02:42 DEBUG[2765] manager.c: Manager received command 'login'
May 29 17:02:42 DEBUG[2765] acl.c: 0.0.0.0/0.0.0.0/0.0.0.0 appended to acl for peer
May 29 17:02:42 DEBUG[2765] acl.c: 127.0.0.1/255.255.255.0/255.255.255.0 appended to acl for peer
May 29 17:02:42 DEBUG[2765] acl.c: ##### Testing 127.0.0.1 with 0.0.0.0
May 29 17:02:42 DEBUG[2765] acl.c: ##### Testing 127.0.0.1 with 127.0.0.0
May 29 17:02:42 VERBOSE[2759] logger.c: dialparties.agi: priority is 1
May 29 17:02:42 VERBOSE[2759] logger.c: dialparties.agi: Caller ID name is '5038513831' number is '5038513831'
May 29 17:02:42 VERBOSE[2759] logger.c: dialparties.agi: Methodology of ring is 'ringallv2-prim'
May 29 17:02:42 DEBUG[2759] db.c: Unable to find key '201' in family 'CF'
May 29 17:02:42 DEBUG[2759] db.c: Unable to find key '5038510262#' in family 'CF'
May 29 17:02:42 DEBUG[2759] db.c: Unable to find key '201' in family 'DND'
May 29 17:02:42 DEBUG[2759] db.c: Unable to find key '201' in family 'CFB'
May 29 17:02:42 DEBUG[2759] db.c: Unable to find key '201' in family 'CFU'
May 29 17:02:42 DEBUG[2765] manager.c: Manager received command 'ExtensionState'
May 29 17:02:42 VERBOSE[2759] logger.c: dialparties.agi: Extension 201 has ExtensionState: 0
May 29 17:02:42 DEBUG[2759] db.c: Unable to find key '5038510262#' in family 'CW'
May 29 17:02:42 DEBUG[2759] db.c: Unable to find key '5038510262#' in family 'CFB'
May 29 17:02:42 DEBUG[2759] db.c: Unable to find key '5038510262#' in family 'CFU'
May 29 17:02:42 DEBUG[2765] manager.c: Manager received command 'Logoff'
May 29 17:02:42 DEBUG[2766] pbx.c: Function result is '5038513831'
May 29 17:02:42 DEBUG[2766] pbx.c: Function result is '5038513831'
May 29 17:02:42 DEBUG[2766] pbx.c: Expression result is '1'
May 29 17:02:42 DEBUG[2766] pbx.c: Expression result is '1'
May 29 17:02:42 DEBUG[2766] pbx.c: Function result is '"5038513831" <5038513831>'
May 29 17:02:42 DEBUG[2766] db.c: Unable to find key '201' in family 'CFU'
May 29 17:02:42 DEBUG[2766] func_db.c: DB: CFU/201 not found in database.
May 29 17:02:42 DEBUG[2766] pbx.c: Function result is ''
May 29 17:02:42 DEBUG[2766] db.c: Unable to find key '201' in family 'CFB'
May 29 17:02:42 DEBUG[2766] func_db.c: DB: CFB/201 not found in database.
May 29 17:02:42 DEBUG[2766] pbx.c: Function result is ''
May 29 17:02:42 DEBUG[2766] pbx.c: Function result is '0'
May 29 17:02:42 DEBUG[2766] pbx.c: Expression result is '0'
May 29 17:02:42 DEBUG[2767] db.c: Unable to find key 'DND/201/Zap/2-1' in family 'FM'
May 29 17:02:42 DEBUG[2767] func_db.c: DB: FM/DND/201/Zap/2-1 not found in database.
May 29 17:02:42 DEBUG[2767] pbx.c: Function result is ''
May 29 17:02:42 DEBUG[2767] pbx.c: Expression result is '0'
May 29 17:02:42 DEBUG[2767] pbx.c: Not taking any branch
May 29 17:02:43 VERBOSE[2766] logger.c: recordingcheck|20070529-170242|1180483362.780: Inbound recording not enabled
May 29 17:02:43 VERBOSE[2766] logger.c: dialparties.agi: Starting New Dialparties.agi
May 29 17:02:43 DEBUG[2772] manager.c: Manager received command 'login'
May 29 17:02:43 DEBUG[2772] acl.c: 0.0.0.0/0.0.0.0/0.0.0.0 appended to acl for peer
May 29 17:02:43 DEBUG[2772] acl.c: 127.0.0.1/255.255.255.0/255.255.255.0 appended to acl for peer
May 29 17:02:43 DEBUG[2772] acl.c: ##### Testing 127.0.0.1 with 0.0.0.0
May 29 17:02:43 DEBUG[2772] acl.c: ##### Testing 127.0.0.1 with 127.0.0.0
May 29 17:02:43 VERBOSE[2766] logger.c: dialparties.agi: priority is 1
May 29 17:02:43 VERBOSE[2766] logger.c: dialparties.agi: Caller ID name is '5038513831' number is '5038513831'
May 29 17:02:43 VERBOSE[2766] logger.c: dialparties.agi: Methodology of ring is 'none'
May 29 17:02:43 DEBUG[2766] db.c: Unable to find key '201' in family 'CF'
May 29 17:02:43 DEBUG[2766] db.c: Unable to find key '201' in family 'DND'
May 29 17:02:43 DEBUG[2766] db.c: Unable to find key '201' in family 'CFB'
May 29 17:02:43 DEBUG[2766] db.c: Unable to find key '201' in family 'CFU'
May 29 17:02:43 DEBUG[2772] manager.c: Manager received command 'Logoff'
May 29 17:02:43 DEBUG[2766] chan_sip.c: Setting NAT on RTP to 524288
May 29 17:02:43 DEBUG[2766] acl.c: ##### Testing 192.168.2.92 with 192.168.2.0
May 29 17:02:43 DEBUG[2766] chan_sip.c: Outgoing Call for 201
May 29 17:02:43 DEBUG[2731] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '5e55ccd36189274d78d8949d4d932a88@192.168.2.12' Request 102: Found
May 29 17:02:43 DEBUG[2731] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '5e55ccd36189274d78d8949d4d932a88@192.168.2.12' Request 102: Found
May 29 17:02:43 DEBUG[2759] chan_zap.c: Requested indication 3 on channel Zap/2-1
May 29 17:02:43 DEBUG[2767] db.c: Unable to find key 'DND/201/Zap/2-1' in family 'FM'
May 29 17:02:43 DEBUG[2767] func_db.c: DB: FM/DND/201/Zap/2-1 not found in database.
May 29 17:02:43 DEBUG[2767] pbx.c: Function result is ''
May 29 17:02:43 DEBUG[2767] pbx.c: Expression result is '0'
May 29 17:02:43 DEBUG[2767] pbx.c: Not taking any branch
May 29 17:02:44 DEBUG[2767] db.c: Unable to find key 'DND/201/Zap/2-1' in family 'FM'
May 29 17:02:44 DEBUG[2767] func_db.c: DB: FM/DND/201/Zap/2-1 not found in database.
May 29 17:02:44 DEBUG[2767] pbx.c: Function result is ''
May 29 17:02:44 DEBUG[2767] pbx.c: Expression result is '0'
May 29 17:02:44 DEBUG[2767] pbx.c: Not taking any branch
May 29 17:02:45 DEBUG[2759] chan_zap.c: Exception on 19, channel 2
May 29 17:02:45 DEBUG[2759] chan_zap.c: Got event Ring Begin(18) on channel 2 (index 0)
May 29 17:02:46 DEBUG[2731] chan_sip.c: Auto destroying call '4cc2b9907806a8707f329c6319a06884@sea.telasip.com'
May 29 17:02:46 DEBUG[2767] db.c: Unable to find key 'DND/201/Zap/2-1' in family 'FM'
May 29 17:02:46 DEBUG[2767] func_db.c: DB: FM/DND/201/Zap/2-1 not found in database.
May 29 17:02:46 DEBUG[2767] pbx.c: Function result is ''
May 29 17:02:46 DEBUG[2767] pbx.c: Expression result is '0'
May 29 17:02:46 DEBUG[2767] pbx.c: Not taking any branch
May 29 17:02:46 DEBUG[2767] db.c: Unable to find key 'DND/201/Zap/2-1' in family 'FM'
May 29 17:02:47 VERBOSE[2767] logger.c: dialparties.agi: Starting New Dialparties.agi
May 29 17:02:47 DEBUG[2781] manager.c: Manager received command 'login'
May 29 17:02:47 DEBUG[2781] acl.c: 0.0.0.0/0.0.0.0/0.0.0.0 appended to acl for peer
May 29 17:02:47 DEBUG[2781] acl.c: 127.0.0.1/255.255.255.0/255.255.255.0 appended to acl for peer
May 29 17:02:47 DEBUG[2781] acl.c: ##### Testing 127.0.0.1 with 0.0.0.0
May 29 17:02:47 DEBUG[2781] acl.c: ##### Testing 127.0.0.1 with 127.0.0.0
May 29 17:02:47 VERBOSE[2767] logger.c: dialparties.agi: priority is 1
May 29 17:02:47 VERBOSE[2767] logger.c: dialparties.agi: Caller ID name is '5038513831' number is '5038513831'
May 29 17:02:47 VERBOSE[2767] logger.c: dialparties.agi: Methodology of ring is 'ringall'
May 29 17:02:47 DEBUG[2767] db.c: Unable to find key '5038510262#' in family 'CF'
May 29 17:02:47 DEBUG[2767] db.c: Unable to find key '5038510262#' in family 'CW'
May 29 17:02:47 DEBUG[2767] db.c: Unable to find key '5038510262#' in family 'CFB'
May 29 17:02:47 DEBUG[2767] db.c: Unable to find key '5038510262#' in family 'CFU'
May 29 17:02:47 DEBUG[2781] manager.c: Manager received command 'Logoff'
May 29 17:02:47 DEBUG[2782] pbx.c: Function result is '20'
May 29 17:02:47 DEBUG[2759] chan_zap.c: Exception on 19, channel 2
May 29 17:02:47 DEBUG[2759] chan_zap.c: Got event Ring/Answered(2) on channel 2 (index 0)
May 29 17:02:47 DEBUG[2759] chan_zap.c: Setting IDLE polarity due to ring. Old polarity was 0
May 29 17:02:47 VERBOSE[2782] logger.c: dialparties.agi: Starting New Dialparties.agi
May 29 17:02:47 DEBUG[2785] manager.c: Manager received command 'login'
May 29 17:02:47 DEBUG[2785] acl.c: 0.0.0.0/0.0.0.0/0.0.0.0 appended to acl for peer
May 29 17:02:47 DEBUG[2785] acl.c: 127.0.0.1/255.255.255.0/255.255.255.0 appended to acl for peer
May 29 17:02:47 DEBUG[2785] acl.c: ##### Testing 127.0.0.1 with 0.0.0.0
May 29 17:02:47 DEBUG[2785] acl.c: ##### Testing 127.0.0.1 with 127.0.0.0
May 29 17:02:47 VERBOSE[2782] logger.c: dialparties.agi: priority is 1
May 29 17:02:47 VERBOSE[2782] logger.c: dialparties.agi: Caller ID name is '5038513831' number is '5038513831'
May 29 17:02:47 VERBOSE[2782] logger.c: dialparties.agi: Methodology of ring is 'none'
May 29 17:02:47 DEBUG[2782] db.c: Unable to find key '5038510262#' in family 'CF'
May 29 17:02:47 DEBUG[2782] db.c: Unable to find key '5038510262#' in family 'CW'
May 29 17:02:47 DEBUG[2782] db.c: Unable to find key '5038510262#' in family 'CFB'
May 29 17:02:47 DEBUG[2782] db.c: Unable to find key '5038510262#' in family 'CFU'
May 29 17:02:47 DEBUG[2785] manager.c: Manager received command 'Logoff'
May 29 17:02:47 DEBUG[2786] pbx.c: Expression result is '1'
May 29 17:02:47 DEBUG[2786] pbx.c: Expression result is '0'
May 29 17:02:47 DEBUG[2786] pbx.c: Not taking any branch
May 29 17:02:47 DEBUG[2786] pbx.c: Function result is '5038513831'
May 29 17:02:47 DEBUG[2786] pbx.c: Function result is '5038513831'
May 29 17:02:47 DEBUG[2786] pbx.c: Expression result is '1'
May 29 17:02:47 DEBUG[2786] pbx.c: Expression result is '1'
May 29 17:02:47 DEBUG[2786] pbx.c: Function result is '"5038513831" <5038513831>'
May 29 17:02:47 DEBUG[2786] pbx.c: Function result is '5038513831'
May 29 17:02:47 DEBUG[2786] pbx.c: Function result is '0'
May 29 17:02:47 DEBUG[2786] pbx.c: Expression result is '0'
May 29 17:02:47 DEBUG[2786] db.c: Unable to find key '5038513831/recording' in family 'AMPUSER'
May 29 17:02:47 VERBOSE[2786] logger.c: recordingcheck|20070529-170247|1180483367.787: No AMPUSER db entry for 5038513831. Not recording
May 29 17:02:47 DEBUG[2786] pbx.c: Expression result is '0'
May 29 17:02:47 DEBUG[2786] pbx.c: Not taking any branch
May 29 17:02:47 DEBUG[2786] pbx.c: Expression result is '0'
May 29 17:02:47 DEBUG[2786] pbx.c: Not taking any branch
May 29 17:02:47 DEBUG[2786] pbx.c: Function result is '5038513831'
May 29 17:02:47 DEBUG[2786] pbx.c: Expression result is '0'
May 29 17:02:47 DEBUG[2786] pbx.c: Not taking any branch
May 29 17:02:47 DEBUG[2786] pbx.c: Expression result is '0'
May 29 17:02:47 DEBUG[2786] pbx.c: Not taking any branch
May 29 17:02:47 DEBUG[2786] pbx.c: Expression result is '0'
May 29 17:02:47 DEBUG[2786] pbx.c: Not taking any branch
May 29 17:02:47 DEBUG[2786] db.c: Unable to find key '5038513831/device' in family 'AMPUSER'
May 29 17:02:47 DEBUG[2786] func_db.c: DB: AMPUSER/5038513831/device not found in database.
May 29 17:02:47 DEBUG[2786] pbx.c: Function result is ''
May 29 17:02:47 DEBUG[2786] pbx.c: Expression result is '1'
May 29 17:02:47 DEBUG[2786] db.c: Unable to find key '5038513831/emergency_cid' in family 'DEVICE'
May 29 17:02:47 DEBUG[2786] func_db.c: DB: DEVICE/5038513831/emergency_cid not found in database.
May 29 17:02:47 DEBUG[2786] pbx.c: Function result is ''
May 29 17:02:47 DEBUG[2786] pbx.c: Expression result is '1'
May 29 17:02:47 DEBUG[2786] pbx.c: Expression result is '0'
May 29 17:02:47 DEBUG[2786] pbx.c: Not taking any branch
May 29 17:02:47 DEBUG[2786] pbx.c: Expression result is '0'
May 29 17:02:47 DEBUG[2786] pbx.c: Not taking any branch
May 29 17:02:47 DEBUG[2786] pbx.c: Function result is ''
May 29 17:02:47 DEBUG[2786] pbx.c: Expression result is '1'
May 29 17:02:47 DEBUG[2786] pbx.c: Function result is '"" <5038513831>'
May 29 17:02:47 DEBUG[2786] pbx.c: Expression result is '0'
May 29 17:02:47 DEBUG[2786] pbx.c: Not taking any branch
May 29 17:02:47 DEBUG[2786] pbx.c: Function result is '1'
May 29 17:02:47 DEBUG[2786] pbx.c: Expression result is '0'
May 29 17:02:47 DEBUG[2786] pbx.c: Not taking any branch
May 29 17:02:48 DEBUG[2786] pbx.c: Function result is 'SIP/telasip-gw'
May 29 17:02:48 DEBUG[2786] pbx.c: Expression result is '0'
May 29 17:02:48 DEBUG[2786] pbx.c: Expression result is '1'
May 29 17:02:48 DEBUG[2786] pbx.c: Expression result is '1'
May 29 17:02:48 DEBUG[2786] pbx.c: Expression result is '0'
May 29 17:02:48 DEBUG[2786] pbx.c: Not taking any branch
May 29 17:02:48 DEBUG[2786] chan_sip.c: Setting NAT on RTP to 0
May 29 17:02:48 DEBUG[2786] acl.c: ##### Testing 216.93.169.208 with 192.168.2.0
May 29 17:02:48 DEBUG[2786] chan_sip.c: Target address 216.93.169.208 is not local, substituting externip
May 29 17:02:48 DEBUG[2786] chan_sip.c: Outgoing Call for 5038510262
May 29 17:02:48 DEBUG[2731] chan_sip.c: Acked pending invite 102
May 29 17:02:48 DEBUG[2731] chan_sip.c: Stopping retransmission on '30b817c11bd69ab34bccab443a5c0bff@sea.telasip.com' of Request 102: Match Found
May 29 17:02:48 DEBUG[2786] chan_sip.c: update_call_counter(5038510262) - decrement call limit counter
May 29 17:02:48 DEBUG[2786] app_dial.c: Exiting with DIALSTATUS=CONGESTION.
May 29 17:02:48 DEBUG[2786] pbx.c: Expression result is '1'
May 29 17:02:48 DEBUG[2786] pbx.c: Expression result is '1'
May 29 17:02:48 DEBUG[2786] pbx.c: Expression result is '0'
May 29 17:02:48 DEBUG[2786] pbx.c: Not taking any branch
May 29 17:02:48 DEBUG[2786] pbx.c: Function result is ''
May 29 17:02:48 DEBUG[2786] pbx.c: Function result is '5038513831'
May 29 17:02:48 DEBUG[2786] pbx.c: Expression result is '1'
May 29 17:02:48 DEBUG[2786] pbx.c: Expression result is '1'
May 29 17:02:48 DEBUG[2786] pbx.c: Function result is '"" <5038513831>'
May 29 17:02:48 DEBUG[2786] pbx.c: Function result is '5038513831'
May 29 17:02:48 DEBUG[2786] pbx.c: Function result is '0'
May 29 17:02:48 DEBUG[2786] pbx.c: Expression result is '0'
May 29 17:02:48 DEBUG[2786] db.c: Unable to find key '5038513831/recording' in family 'AMPUSER'
May 29 17:02:48 VERBOSE[2786] logger.c: recordingcheck|20070529-170248|1180483367.787: No AMPUSER db entry for 5038513831. Not recording
May 29 17:02:48 DEBUG[2786] pbx.c: Expression result is '0'
May 29 17:02:48 DEBUG[2786] pbx.c: Not taking any branch
May 29 17:02:48 DEBUG[2786] pbx.c: Expression result is '1'
May 29 17:02:48 DEBUG[2786] pbx.c: Expression result is '0'
May 29 17:02:48 DEBUG[2786] pbx.c: Not taking any branch
May 29 17:02:48 DEBUG[2786] pbx.c: Expression result is '0'
May 29 17:02:48 DEBUG[2786] pbx.c: Not taking any branch
May 29 17:02:48 DEBUG[2786] pbx.c: Expression result is '0'
May 29 17:02:48 DEBUG[2786] pbx.c: Not taking any branch
May 29 17:02:48 DEBUG[2786] db.c: Unable to find key '5038513831/device' in family 'AMPUSER'
May 29 17:02:48 DEBUG[2786] func_db.c: DB: AMPUSER/5038513831/device not found in database.
May 29 17:02:48 DEBUG[2786] pbx.c: Function result is ''
May 29 17:02:48 DEBUG[2786] pbx.c: Expression result is '1'
May 29 17:02:48 DEBUG[2786] db.c: Unable to find key '5038513831/emergency_cid' in family 'DEVICE'
May 29 17:02:48 DEBUG[2786] func_db.c: DB: DEVICE/5038513831/emergency_cid not found in database.
May 29 17:02:48 DEBUG[2786] pbx.c: Function result is ''
May 29 17:02:48 DEBUG[2786] pbx.c: Expression result is '1'
May 29 17:02:48 DEBUG[2786] pbx.c: Expression result is '0'
May 29 17:02:48 DEBUG[2786] pbx.c: Not taking any branch
May 29 17:02:48 DEBUG[2786] pbx.c: Expression result is '0'
May 29 17:02:48 DEBUG[2786] pbx.c: Not taking any branch
May 29 17:02:48 DEBUG[2786] pbx.c: Function result is ''
May 29 17:02:48 DEBUG[2786] pbx.c: Expression result is '1'
May 29 17:02:48 DEBUG[2786] pbx.c: Function result is '"" <5038513831>'
May 29 17:02:48 DEBUG[2786] pbx.c: Expression result is '0'
May 29 17:02:48 DEBUG[2786] pbx.c: Not taking any branch
May 29 17:02:48 DEBUG[2786] pbx.c: Function result is '1'
May 29 17:02:48 DEBUG[2786] pbx.c: Expression result is '0'
May 29 17:02:48 DEBUG[2786] pbx.c: Not taking any branch
May 29 17:02:48 DEBUG[2786] pbx.c: Function result is 'SIP/Vitelity-outbound'
May 29 17:02:48 DEBUG[2786] pbx.c: Expression result is '0'
May 29 17:02:48 DEBUG[2786] pbx.c: Expression result is '1'
May 29 17:02:48 DEBUG[2786] pbx.c: Expression result is '1'
May 29 17:02:48 DEBUG[2786] pbx.c: Expression result is '0'
May 29 17:02:48 DEBUG[2786] pbx.c: Not taking any branch
May 29 17:02:48 DEBUG[2786] chan_sip.c: Setting NAT on RTP to 0
May 29 17:02:48 DEBUG[2786] acl.c: ##### Testing 64.2.142.29 with 192.168.2.0
May 29 17:02:48 DEBUG[2786] chan_sip.c: Target address 64.2.142.29 is not local, substituting externip
May 29 17:02:48 DEBUG[2786] chan_sip.c: Outgoing Call for 5038510262
May 29 17:02:48 DEBUG[2731] chan_sip.c: Acked pending invite 102
May 29 17:02:48 DEBUG[2731] chan_sip.c: Stopping retransmission on '60f282c27a92eb477074b8be4e1d2506@71.237.146.239' of Request 102: Match Found
May 29 17:02:49 DEBUG[2731] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '60f282c27a92eb477074b8be4e1d2506@71.237.146.239' Request 103: Found
May 29 17:02:50 DEBUG[2731] chan_sip.c: Acked pending invite 102
May 29 17:02:50 DEBUG[2731] chan_sip.c: Stopping retransmission on '5e55ccd36189274d78d8949d4d932a88@192.168.2.12' of Request 102: Match Found
May 29 17:02:50 DEBUG[2731] chan_sip.c: build_route: Contact hop: "$USER"
May 29 17:02:50 DEBUG[2766] app_dial.c: Macro exited with status 0
May 29 17:02:50 DEBUG[2759] chan_zap.c: Requested indication -1 on channel Zap/2-1
May 29 17:02:50 DEBUG[2759] db.c: Unable to find key '201/Zap/2-1' in family 'BLKVM'
May 29 17:02:50 DEBUG[2759] app_dial.c: Macro exited with status 0
May 29 17:02:50 DEBUG[2759] chan_zap.c: Took Zap/2-1 off hook
May 29 17:02:50 DEBUG[2759] chan_zap.c: Enabled echo cancellation on channel 2
May 29 17:02:50 DEBUG[2759] chan_zap.c: Engaged echo training on channel 2
May 29 17:02:50 DEBUG[2767] app_dial.c: Exiting with DIALSTATUS=CANCEL.
May 29 17:02:50 DEBUG[2782] app_dial.c: Exiting with DIALSTATUS=CANCEL.
May 29 17:02:50 DEBUG[2786] chan_sip.c: update_call_counter(5038510262) - decrement call limit counter
May 29 17:02:50 DEBUG[2786] chan_sip.c: Acked pending invite 103
May 29 17:02:50 DEBUG[2786] chan_sip.c: Stopping retransmission on '60f282c27a92eb477074b8be4e1d2506@71.237.146.239' of Request 103: Match Found
May 29 17:02:50 DEBUG[2786] app_dial.c: Exiting with DIALSTATUS=CANCEL.
May 29 17:02:50 DEBUG[2767] cdr_addon_mysql.c: cdr_mysql: inserting a CDR record.
May 29 17:02:50 DEBUG[2767] 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) VALUES ('2007-05-29 17:02:42','\"5038513831\" <5038513831>','5038513831','FMGL-5038510262#','from-internal', 'Local/FMGL-5038510262#@from-internal-da81,2','Local/RG-201-5038510262#@from-internal-a135,1','ResetCDR','w',8,0,'NO ANSWER',3,'')
May 29 17:02:50 NOTICE[2767] cdr.c: CDR on channel 'Local/FMGL-5038510262#@from-internal-da81,2' not posted
May 29 17:02:50 NOTICE[2767] cdr.c: CDR on channel 'Local/FMGL-5038510262#@from-internal-da81,2' lacks end
May 29 17:02:50 DEBUG[2767] pbx.c: Expression result is '1'
May 29 17:02:50 DEBUG[2767] pbx.c: Expression result is '1'
May 29 17:02:50 DEBUG[2767] pbx.c: Expression result is '1'
May 29 17:02:50 DEBUG[2782] cdr_addon_mysql.c: cdr_mysql: inserting a CDR record.
May 29 17:02:50 DEBUG[2782] 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) VALUES ('2007-05-29 17:02:47','\"5038513831\" <5038513831>','5038513831','RG-201-5038510262#','from-internal', 'Local/RG-201-5038510262#@from-internal-a135,2','Local/5038510262@from-internal-987e,1','ResetCDR','w',3,0,'NO ANSWER',3,'')
May 29 17:02:50 NOTICE[2782] cdr.c: CDR on channel 'Local/RG-201-5038510262#@from-internal-a135,2' not posted
May 29 17:02:50 NOTICE[2782] cdr.c: CDR on channel 'Local/RG-201-5038510262#@from-internal-a135,2' lacks end
May 29 17:02:50 DEBUG[2782] pbx.c: Expression result is '1'
May 29 17:02:50 DEBUG[2782] pbx.c: Expression result is '1'
May 29 17:02:50 DEBUG[2782] pbx.c: Expression result is '1'
May 29 17:02:50 DEBUG[2786] cdr_addon_mysql.c: cdr_mysql: inserting a CDR record.
May 29 17:02:50 DEBUG[2786] 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) VALUES ('2007-05-29 17:02:47','5038513831','5038513831','5038510262','from-internal', 'Local/5038510262@from-internal-987e,2','SIP/Vitelity-outbound-087c0e18','ResetCDR','w',3,0,'FAILED',3,'')
May 29 17:02:50 NOTICE[2786] cdr.c: CDR on channel 'Local/5038510262@from-internal-987e,2' not posted
May 29 17:02:50 NOTICE[2786] cdr.c: CDR on channel 'Local/5038510262@from-internal-987e,2' lacks end
May 29 17:02:50 DEBUG[2786] pbx.c: Expression result is '1'
May 29 17:02:50 DEBUG[2786] pbx.c: Expression result is '1'
May 29 17:02:50 DEBUG[2786] pbx.c: Expression result is '1'
May 29 17:02:50 DEBUG[2766] channel.c: Planning to masquerade channel SIP/201-087bae00 into the structure of Local/FMPR-201@from-internal-98f1,1
May 29 17:02:50 DEBUG[2766] channel.c: Done planning to masquerade channel SIP/201-087bae00 into the structure of Local/FMPR-201@from-internal-98f1,1
May 29 17:02:50 DEBUG[2766] chan_local.c: Not posting to queue since already masked on 'Local/FMPR-201@from-internal-98f1,2'
May 29 17:02:50 DEBUG[2759] channel.c: Got clone lock for masquerade on 'SIP/201-087bae00' at 0x87cfd34
May 29 17:02:50 DEBUG[2759] channel.c: Putting channel SIP/201-087bae00 in 64/64 formats
May 29 17:02:50 DEBUG[2759] channel.c: Released clone lock on 'Local/FMPR-201@from-internal-98f1,1'
May 29 17:02:50 DEBUG[2759] channel.c: Done Masquerading SIP/201-087bae00 (6)
May 29 17:02:50 DEBUG[2766] channel.c: Didn't get a frame from channel: Local/FMPR-201@from-internal-98f1,2
May 29 17:02:50 DEBUG[2766] channel.c: Bridge stops bridging channels Local/FMPR-201@from-internal-98f1,2 and Local/FMPR-201@from-internal-98f1,1
May 29 17:02:50 DEBUG[2766] app_dial.c: Exiting with DIALSTATUS=ANSWER.
May 29 17:02:50 DEBUG[2766] cdr_addon_mysql.c: cdr_mysql: inserting a CDR record.
May 29 17:02:50 DEBUG[2766] 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) VALUES ('2007-05-29 17:02:42','\"5038513831\" <5038513831>','5038513831','FMPR-201','from-internal', 'Local/FMPR-201@from-internal-98f1,2','SIP/201-087bae00','ResetCDR','w',8,0,'ANSWERED',3,'')
May 29 17:02:50 NOTICE[2766] cdr.c: CDR on channel 'Local/FMPR-201@from-internal-98f1,2' not posted
May 29 17:02:50 NOTICE[2766] cdr.c: CDR on channel 'Local/FMPR-201@from-internal-98f1,2' lacks end
May 29 17:02:50 DEBUG[2766] pbx.c: Expression result is '1'
May 29 17:02:50 DEBUG[2766] pbx.c: Expression result is '1'
May 29 17:02:50 DEBUG[2766] pbx.c: Expression result is '1'
May 29 17:02:50 DEBUG[2731] chan_sip.c: Stopping retransmission on '60f282c27a92eb477074b8be4e1d2506@71.237.146.239' of Request 103: Match Not Found
May 29 17:02:50 DEBUG[2731] chan_sip.c: Stopping retransmission on '60f282c27a92eb477074b8be4e1d2506@71.237.146.239' of Request 103: Match Found
May 29 17:02:51 DEBUG[1488] manager.c: Manager received command 'Command'
May 29 17:02:51 DEBUG[1488] manager.c: Manager received command 'Command'
May 29 17:02:51 DEBUG[1488] manager.c: Manager received command 'Command'
May 29 17:02:54 DEBUG[2731] acl.c: ##### Testing 192.168.2.59 with 192.168.2.0
May 29 17:02:54 DEBUG[2731] chan_sip.c: Stopping retransmission on '536c95bc7a2c1ed258a15fda5bd2ad19@192.168.2.12' of Request 102: Match Found
May 29 17:03:00 DEBUG[2731] acl.c: ##### Testing 192.168.2.92 with 192.168.2.0
May 29 17:03:00 DEBUG[2731] chan_sip.c: Stopping retransmission on '7d7bb51332995dd769abcc9876cb4e33@192.168.2.12' of Request 102: Match Found
May 29 17:03:09 DEBUG[2731] chan_sip.c: Auto destroying call '22e4eeba732d0afa69087394578e897b@127.0.0.1'
May 29 17:03:22 DEBUG[2731] chan_sip.c: Auto destroying call '60f282c27a92eb477074b8be4e1d2506@71.237.146.239'
May 29 17:03:22 DEBUG[2731] acl.c: ##### Testing 64.2.142.26 with 192.168.2.0
May 29 17:03:22 DEBUG[2731] chan_sip.c: Target address 64.2.142.26 is not local, substituting externip
May 29 17:03:22 DEBUG[2731] chan_sip.c: Scheduled a registration timeout for inbound1.vitelity.net id #302854
May 29 17:03:22 DEBUG[2731] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '22e4eeba732d0afa69087394578e897b@127.0.0.1' Request 4023: Found
May 29 17:03:22 DEBUG[2731] chan_sip.c: Stopping retransmission on '22e4eeba732d0afa69087394578e897b@127.0.0.1' of Request 4023: Match Found
May 29 17:03:23 DEBUG[2731] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '22e4eeba732d0afa69087394578e897b@127.0.0.1' Request 4024: Found
May 29 17:03:23 DEBUG[2731] chan_sip.c: Stopping retransmission on '22e4eeba732d0afa69087394578e897b@127.0.0.1' of Request 4024: Match Found
May 29 17:03:23 DEBUG[2731] chan_sip.c: Registration successful
May 29 17:03:23 DEBUG[2731] chan_sip.c: Cancelling timeout 302854
May 29 17:03:26 DEBUG[2810] manager.c: Manager received command 'login'
May 29 17:03:26 DEBUG[2810] acl.c: 0.0.0.0/0.0.0.0/0.0.0.0 appended to acl for peer
May 29 17:03:26 DEBUG[2810] acl.c: 127.0.0.1/255.255.255.0/255.255.255.0 appended to acl for peer
May 29 17:03:26 DEBUG[2810] acl.c: ##### Testing 127.0.0.1 with 0.0.0.0
May 29 17:03:26 DEBUG[2810] acl.c: ##### Testing 127.0.0.1 with 127.0.0.0
May 29 17:03:32 DEBUG[2814] manager.c: Manager received command 'login'
May 29 17:03:32 DEBUG[2814] acl.c: 0.0.0.0/0.0.0.0/0.0.0.0 appended to acl for peer
May 29 17:03:32 DEBUG[2814] acl.c: 127.0.0.1/255.255.255.0/255.255.255.0 appended to acl for peer
May 29 17:03:32 DEBUG[2814] acl.c: ##### Testing 127.0.0.1 with 0.0.0.0
May 29 17:03:32 DEBUG[2814] acl.c: ##### Testing 127.0.0.1 with 127.0.0.0
May 29 17:03:42 DEBUG[2731] acl.c: ##### Testing 216.93.169.208 with 192.168.2.0
May 29 17:03:42 DEBUG[2731] chan_sip.c: Target address 216.93.169.208 is not local, substituting externip
May 29 17:03:42 DEBUG[2731] chan_sip.c: Stopping retransmission on '50ded23a648b3f1f5a2ddfc2781672ca@71.237.146.239' of Request 102: Match Found
May 29 17:03:44 DEBUG[2816] manager.c: Manager received command 'login'
May 29 17:03:44 DEBUG[2816] acl.c: 0.0.0.0/0.0.0.0/0.0.0.0 appended to acl for peer
May 29 17:03:44 DEBUG[2816] acl.c: 127.0.0.1/255.255.255.0/255.255.255.0 appended to acl for peer
May 29 17:03:44 DEBUG[2816] acl.c: ##### Testing 127.0.0.1 with 0.0.0.0
May 29 17:03:44 DEBUG[2816] acl.c: ##### Testing 127.0.0.1 with 127.0.0.0
May 29 17:03:44 DEBUG[2816] acl.c: ##### Testing 127.0.0.1 with 127.0.0.0