Apr 10 18:22:48 DEBUG[2621] chan_sip.c: Stopping retransmission on '69d080573363c19d192d14c0168becac@127.0.0.1' of Request 105: Match Found Apr 10 18:22:48 DEBUG[2621] chan_sip.c: Registration successful Apr 10 18:22:48 DEBUG[2621] chan_sip.c: Cancelling timeout 594 Apr 10 18:22:48 DEBUG[2621] chan_sip.c: Stopping retransmission on '378ac79c57fd76346ef6a72b248124ea@127.0.0.1' of Request 105: Match Found Apr 10 18:22:48 DEBUG[2621] chan_sip.c: Registration successful Apr 10 18:22:48 DEBUG[2621] chan_sip.c: Cancelling timeout 596 Apr 10 18:22:48 DEBUG[2621] chan_sip.c: Stopping retransmission on '135b0049042380f12d23eb9f6cf5f2fe@127.0.0.1' of Request 105: Match Found Apr 10 18:22:48 DEBUG[2621] chan_sip.c: Registration successful Apr 10 18:22:48 DEBUG[2621] chan_sip.c: Cancelling timeout 598 Apr 10 18:22:56 DEBUG[2621] chan_sip.c: Auto destroying call '043d35c03ed841766bb2d1df5df7207c@192.168.1.5' Apr 10 18:23:19 DEBUG[2621] chan_sip.c: Auto destroying call '0d08a2b55fcf905f4edfab85436d6477@127.0.0.1' Apr 10 18:23:20 DEBUG[2621] chan_sip.c: Auto destroying call '5083a8f5605f9215771f7e647eee500e@127.0.0.1' Apr 10 18:23:20 DEBUG[2621] chan_sip.c: Auto destroying call '23d5a8cd69a3172c15a9bc9e6c218a13@127.0.0.1' Apr 10 18:23:20 DEBUG[2621] chan_sip.c: Auto destroying call '69d080573363c19d192d14c0168becac@127.0.0.1' Apr 10 18:23:20 DEBUG[2621] chan_sip.c: Auto destroying call '378ac79c57fd76346ef6a72b248124ea@127.0.0.1' Apr 10 18:23:20 DEBUG[2621] chan_sip.c: Auto destroying call '135b0049042380f12d23eb9f6cf5f2fe@127.0.0.1' Apr 10 18:23:22 DEBUG[2621] acl.c: ##### Testing 195.214.41.82 with 192.168.1.0 Apr 10 18:23:22 DEBUG[2621] chan_sip.c: Target address 195.214.41.82 is not local, substituting externip Apr 10 18:23:22 DEBUG[2621] chan_sip.c: Setting NAT on RTP to 524288 Apr 10 18:23:22 DEBUG[2621] chan_sip.c: Checking SIP call limits for device 557728832 Apr 10 18:23:22 DEBUG[2621] chan_sip.c: build_route: Record-Route hop: Apr 10 18:23:22 VERBOSE[4289] logger.c: -- Executing NoOp("SIP/557728832-0823cc50", "Received incoming SIP connection from unknown peer to 558959701") in$ Apr 10 18:23:22 DEBUG[4289] pbx.c: Expression result is '0' Apr 10 18:23:22 DEBUG[4289] pbx.c: Function result is '558959701' Apr 10 18:23:22 VERBOSE[4289] logger.c: -- Executing Set("SIP/557728832-0823cc50", "DID=558959701") in new stack Apr 10 18:23:22 VERBOSE[4289] logger.c: -- Executing Goto("SIP/557728832-0823cc50", "s|1") in new stack Apr 10 18:23:22 VERBOSE[4289] logger.c: -- Goto (from-sip-external,s,1) Apr 10 18:23:22 VERBOSE[4289] logger.c: -- Executing Ringing("SIP/557728832-0823cc50", "") in new stack Apr 10 18:23:22 DEBUG[4289] pbx.c: Expression result is '1' Apr 10 18:23:22 VERBOSE[4289] logger.c: -- Executing GotoIf("SIP/557728832-0823cc50", "1?from-trunk|558959701|1") in new stack Apr 10 18:23:22 VERBOSE[4289] logger.c: -- Goto (from-trunk,558959701,1) Apr 10 18:23:22 VERBOSE[4289] logger.c: -- Executing NoOp("SIP/557728832-0823cc50", "Catch-All DID Match - Found 558959701 - You probably want a DID for $ Apr 10 18:23:22 VERBOSE[4289] logger.c: -- Executing Goto("SIP/557728832-0823cc50", "ext-did|s|1") in new stack Apr 10 18:23:22 VERBOSE[4289] logger.c: -- Goto (ext-did,s,1) Apr 10 18:23:22 VERBOSE[4289] logger.c: -- Executing Set("SIP/557728832-0823cc50", "FROM_DID=s") in new stack Apr 10 18:23:22 VERBOSE[4289] logger.c: -- Executing Set("SIP/557728832-0823cc50", "FAX_RX=disabled") in new stack Apr 10 18:23:22 VERBOSE[4289] logger.c: -- Executing Goto("SIP/557728832-0823cc50", "ivr-2|s|1") in new stack Apr 10 18:23:22 VERBOSE[4289] logger.c: -- Goto (ivr-2,s,1) Apr 10 18:23:22 VERBOSE[4289] logger.c: -- Executing Set("SIP/557728832-0823cc50", "LOOPCOUNT=0") in new stack Apr 10 18:23:22 VERBOSE[4289] logger.c: -- Executing Set("SIP/557728832-0823cc50", "__DIR-CONTEXT=") in new stack Apr 10 18:23:22 VERBOSE[4289] logger.c: -- Executing Set("SIP/557728832-0823cc50", "_IVR_CONTEXT_ivr-2=") in new stack Apr 10 18:23:22 VERBOSE[4289] logger.c: -- Executing Set("SIP/557728832-0823cc50", "_IVR_CONTEXT=ivr-2") in new stack Apr 10 18:23:22 DEBUG[4289] pbx.c: Function result is 'NO ANSWER' Apr 10 18:23:22 DEBUG[4289] pbx.c: Expression result is '0' Apr 10 18:23:22 VERBOSE[4289] logger.c: -- Executing GotoIf("SIP/557728832-0823cc50", "0?begin") in new stack Apr 10 18:23:22 DEBUG[4289] pbx.c: Not taking any branch Apr 10 18:23:22 VERBOSE[4289] logger.c: -- Executing Answer("SIP/557728832-0823cc50", "") in new stack Apr 10 18:23:22 VERBOSE[4289] logger.c: -- Executing Wait("SIP/557728832-0823cc50", "1") in new stack Apr 10 18:23:23 VERBOSE[4289] logger.c: -- Executing Set("SIP/557728832-0823cc50", "TIMEOUT(digit)=3") in new stack Apr 10 18:23:23 VERBOSE[4289] logger.c: -- Digit timeout set to 3 Apr 10 18:23:23 VERBOSE[4289] logger.c: -- Executing Set("SIP/557728832-0823cc50", "TIMEOUT(response)=5") in new stack Apr 10 18:23:23 VERBOSE[4289] logger.c: -- Response timeout set to 5 Apr 10 18:23:23 VERBOSE[4289] logger.c: -- Executing BackGround("SIP/557728832-0823cc50", "custom/MsgBienvenida") in new stack Apr 10 18:23:23 DEBUG[4289] channel.c: Scheduling timer at 160 sample intervals Apr 10 18:23:23 VERBOSE[4289] logger.c: -- Playing 'custom/MsgBienvenida' (language 'es') Apr 10 18:23:32 DEBUG[4289] channel.c: Scheduling timer at 138 sample intervals Apr 10 18:23:32 DEBUG[4289] channel.c: Scheduling timer at 0 sample intervals Apr 10 18:23:32 DEBUG[4289] channel.c: Scheduling timer at 0 sample intervals Apr 10 18:23:37 VERBOSE[4289] logger.c: -- Timeout on SIP/557728832-0823cc50 Apr 10 18:23:37 VERBOSE[4289] logger.c: == CDR updated on SIP/557728832-0823cc50 Apr 10 18:23:37 VERBOSE[4289] logger.c: -- Executing DBdel("SIP/557728832-0823cc50", "") in new stack Apr 10 18:23:37 DEBUG[4289] app_db.c: Ignoring, no parameters Apr 10 18:23:37 VERBOSE[4289] logger.c: -- Executing Set("SIP/557728832-0823cc50", "__NODEST=") in new stack Apr 10 18:23:37 VERBOSE[4289] logger.c: -- Executing Goto("SIP/557728832-0823cc50", "ext-group|600|1") in new stack Apr 10 18:23:37 VERBOSE[4289] logger.c: -- Goto (ext-group,600,1) Apr 10 18:23:37 VERBOSE[4289] logger.c: -- Executing Macro("SIP/557728832-0823cc50", "user-callerid|") in new stack Apr 10 18:23:37 DEBUG[4289] pbx.c: Function result is '' Apr 10 18:23:37 DEBUG[4289] pbx.c: Function result is '34913821724' Apr 10 18:23:37 VERBOSE[4289] logger.c: -- Executing NoOp("SIP/557728832-0823cc50", "user-callerid: 34913821724") in new stack Apr 10 18:23:37 DEBUG[4289] pbx.c: Expression result is '0' Apr 10 18:23:37 VERBOSE[4289] logger.c: -- Executing GotoIf("SIP/557728832-0823cc50", "0?report") in new stack Apr 10 18:23:37 DEBUG[4289] pbx.c: Not taking any branch Apr 10 18:23:37 DEBUG[4289] pbx.c: Expression result is '0' Apr 10 18:23:37 VERBOSE[4289] logger.c: -- Executing GotoIf("SIP/557728832-0823cc50", "0?start") in new stack Apr 10 18:23:37 DEBUG[4289] pbx.c: Not taking any branch Apr 10 18:23:37 DEBUG[4289] pbx.c: Function result is '34913821724' Apr 10 18:23:37 VERBOSE[4289] logger.c: -- Executing Set("SIP/557728832-0823cc50", "REALCALLERIDNUM=34913821724") in new stack Apr 10 18:23:37 VERBOSE[4289] logger.c: -- Executing NoOp("SIP/557728832-0823cc50", "REALCALLERIDNUM is 34913821724") in new stack Apr 10 18:23:37 DEBUG[4289] db.c: Unable to find key '34913821724/user' in family 'DEVICE' Apr 10 18:23:37 DEBUG[4289] func_db.c: DB: DEVICE/34913821724/user not found in database. Apr 10 18:23:37 DEBUG[4289] pbx.c: Function result is '' Apr 10 18:23:37 VERBOSE[4289] logger.c: -- Executing Set("SIP/557728832-0823cc50", "AMPUSER=") in new stack Apr 10 18:23:37 DEBUG[4289] db.c: Unable to find key '/cidname' in family 'AMPUSER' Apr 10 18:23:37 DEBUG[4289] func_db.c: DB: AMPUSER//cidname not found in database. Apr 10 18:23:37 DEBUG[4289] pbx.c: Function result is '' Apr 10 18:23:37 VERBOSE[4289] logger.c: -- Executing Set("SIP/557728832-0823cc50", "AMPUSERCIDNAME=") in new stack Apr 10 18:23:37 DEBUG[4289] pbx.c: Expression result is '1' Apr 10 18:23:37 VERBOSE[4289] logger.c: -- Executing GotoIf("SIP/557728832-0823cc50", "1?report") in new stack Apr 10 18:23:37 VERBOSE[4289] logger.c: -- Goto (macro-user-callerid,s,11) Apr 10 18:23:37 VERBOSE[4289] logger.c: -- Executing NoOp("SIP/557728832-0823cc50", "TTL: ARG1: ") in new stack Apr 10 18:23:37 DEBUG[4289] pbx.c: Expression result is '0' Apr 10 18:23:37 VERBOSE[4289] logger.c: -- Executing GotoIf("SIP/557728832-0823cc50", "0?continue") in new stack Apr 10 18:23:37 DEBUG[4289] pbx.c: Not taking any branch Apr 10 18:23:37 DEBUG[4289] pbx.c: Expression result is '1' Apr 10 18:23:37 DEBUG[4289] pbx.c: Expression result is '-1' Apr 10 18:23:37 DEBUG[4289] pbx.c: Function result is '64' Apr 10 18:23:37 VERBOSE[4289] logger.c: -- Executing Set("SIP/557728832-0823cc50", "_TTL=64") in new stack Apr 10 18:23:37 DEBUG[4289] pbx.c: Expression result is '1' Apr 10 18:23:37 VERBOSE[4289] logger.c: -- Executing GotoIf("SIP/557728832-0823cc50", "1?continue") in new stack Apr 10 18:23:37 VERBOSE[4289] logger.c: -- Goto (macro-user-callerid,s,21) Apr 10 18:23:37 DEBUG[4289] pbx.c: Function result is '"" <34913821724>' Apr 10 18:23:37 VERBOSE[4289] logger.c: -- Executing NoOp("SIP/557728832-0823cc50", "Using CallerID "" <34913821724>") in new stack Apr 10 18:23:37 DEBUG[4289] pbx.c: Expression result is '1' Apr 10 18:23:37 VERBOSE[4289] logger.c: -- Executing GotoIf("SIP/557728832-0823cc50", "1?skipdb") in new stack Apr 10 18:23:37 VERBOSE[4289] logger.c: -- Goto (ext-group,600,4) Apr 10 18:23:37 VERBOSE[4289] logger.c: -- Executing Set("SIP/557728832-0823cc50", "__NODEST=") in new stack Apr 10 18:23:37 VERBOSE[4289] logger.c: -- Executing Set("SIP/557728832-0823cc50", "__BLKVM_OVERRIDE=BLKVM/600/SIP/557728832-0823cc50") in new stack Apr 10 18:23:37 VERBOSE[4289] logger.c: -- Executing Set("SIP/557728832-0823cc50", "__BLKVM_BASE=600") in new stack Apr 10 18:23:37 VERBOSE[4289] logger.c: -- Executing Set("SIP/557728832-0823cc50", "DB(BLKVM/600/SIP/557728832-0823cc50)=TRUE") in new stack Apr 10 18:23:37 VERBOSE[4289] logger.c: -- Executing Set("SIP/557728832-0823cc50", "RRNODEST=") in new stack Apr 10 18:23:37 VERBOSE[4289] logger.c: -- Executing Set("SIP/557728832-0823cc50", "__NODEST=600") in new stack Apr 10 18:23:37 DEBUG[4289] pbx.c: Expression result is '1' Apr 10 18:23:37 VERBOSE[4289] logger.c: -- Executing GotoIf("SIP/557728832-0823cc50", "1?REPCID") in new stack Apr 10 18:23:37 VERBOSE[4289] logger.c: -- Goto (ext-group,600,14) Apr 10 18:23:37 DEBUG[4289] pbx.c: Function result is '' Apr 10 18:23:37 VERBOSE[4289] logger.c: -- Executing NoOp("SIP/557728832-0823cc50", "CALLERID(name) is ") in new stack Apr 10 18:23:37 VERBOSE[4289] logger.c: -- Executing Set("SIP/557728832-0823cc50", "RecordMethod=Group") in new stack Apr 10 18:23:37 VERBOSE[4289] logger.c: -- Executing Macro("SIP/557728832-0823cc50", "record-enable|200-201-202|Group") in new stack Apr 10 18:23:37 DEBUG[4289] pbx.c: Function result is '0' Apr 10 18:23:37 DEBUG[4289] pbx.c: Expression result is '0' Apr 10 18:23:37 VERBOSE[4289] logger.c: -- Executing GotoIf("SIP/557728832-0823cc50", "0?2:4") in new stack Apr 10 18:23:37 VERBOSE[4289] logger.c: -- Goto (macro-record-enable,s,4) Apr 10 18:23:37 VERBOSE[4289] logger.c: -- Executing DeadAGI("SIP/557728832-0823cc50", "recordingcheck|20070410-182337|1176222202.14") in new stack Apr 10 18:23:37 VERBOSE[4289] logger.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/recordingcheck Apr 10 18:23:37 VERBOSE[4289] logger.c: -- AGI Script recordingcheck completed, returning 0 Apr 10 18:23:37 VERBOSE[4289] logger.c: -- Executing NoOp("SIP/557728832-0823cc50", "No recording needed") in new stack Apr 10 18:23:37 VERBOSE[4289] logger.c: -- Executing Set("SIP/557728832-0823cc50", "RingGroupMethod=hunt") in new stack Apr 10 18:23:37 VERBOSE[4289] logger.c: -- Executing Macro("SIP/557728832-0823cc50", "dial|20|tr|200-201-202") in new stack Apr 10 18:23:37 VERBOSE[4289] logger.c: -- Executing DeadAGI("SIP/557728832-0823cc50", "dialparties.agi") in new stack Apr 10 18:23:37 VERBOSE[4289] logger.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/dialparties.agi Apr 10 18:23:37 VERBOSE[4289] logger.c: dialparties.agi: Starting New Dialparties.agi Apr 10 18:23:37 VERBOSE[4289] logger.c: dialparties.agi: priority is 1 Apr 10 18:23:37 VERBOSE[4289] logger.c: dialparties.agi: Caller ID name is 'unknown' number is '34913821724' Apr 10 18:23:37 VERBOSE[4289] logger.c: dialparties.agi: Methodology of ring is 'hunt' Apr 10 18:23:37 VERBOSE[4289] logger.c: > dialparties.agi: USE_CONFIRMATION: 'FALSE' Apr 10 18:23:37 VERBOSE[4289] logger.c: > dialparties.agi: RINGGROUP_INDEX: '' Apr 10 18:23:37 VERBOSE[4289] logger.c: -- dialparties.agi: Added extension 200 to extension map Apr 10 18:23:37 VERBOSE[4289] logger.c: -- dialparties.agi: Added extension 201 to extension map Apr 10 18:23:37 VERBOSE[4289] logger.c: -- dialparties.agi: Added extension 202 to extension map Apr 10 18:23:37 DEBUG[4289] db.c: Unable to find key '200' in family 'CF' Apr 10 18:23:37 VERBOSE[4289] logger.c: -- dialparties.agi: Extension 200 cf is disabled Apr 10 18:23:37 DEBUG[4289] db.c: Unable to find key '201' in family 'CF' Apr 10 18:23:37 VERBOSE[4289] logger.c: -- dialparties.agi: Extension 201 cf is disabled Apr 10 18:23:37 DEBUG[4289] db.c: Unable to find key '202' in family 'CF' Apr 10 18:23:37 VERBOSE[4289] logger.c: -- dialparties.agi: Extension 202 cf is disabled Apr 10 18:23:37 DEBUG[4289] db.c: Unable to find key '200' in family 'DND' Apr 10 18:23:37 VERBOSE[4289] logger.c: -- dialparties.agi: Extension 200 do not disturb is disabled Apr 10 18:23:37 DEBUG[4289] db.c: Unable to find key '201' in family 'DND' Apr 10 18:23:37 VERBOSE[4289] logger.c: -- dialparties.agi: Extension 201 do not disturb is disabled Apr 10 18:23:37 DEBUG[4289] db.c: Unable to find key '202' in family 'DND' Apr 10 18:23:37 VERBOSE[4289] logger.c: -- dialparties.agi: Extension 202 do not disturb is disabled Apr 10 18:23:37 DEBUG[4289] db.c: Unable to find key '200' in family 'CW' Apr 10 18:23:37 DEBUG[4289] db.c: Unable to find key '200' in family 'CFB' Apr 10 18:23:37 DEBUG[4289] db.c: Unable to find key '200' in family 'CFU' Apr 10 18:23:37 VERBOSE[4289] logger.c: > dialparties.agi: extnum: 200 Apr 10 18:23:37 VERBOSE[4289] logger.c: > dialparties.agi: exthascw: 0 Apr 10 18:23:37 VERBOSE[4289] logger.c: > dialparties.agi: exthascfb: 0 Apr 10 18:23:37 VERBOSE[4289] logger.c: > dialparties.agi: extcfb: Apr 10 18:23:37 VERBOSE[4289] logger.c: > dialparties.agi: exthascfu: 0 Apr 10 18:23:37 VERBOSE[4289] logger.c: > dialparties.agi: extcfu: Apr 10 18:23:37 DEBUG[4294] manager.c: Manager received command 'login' Apr 10 18:23:37 VERBOSE[4294] logger.c: == Parsing '/etc/asterisk/manager.conf': Apr 10 18:23:37 VERBOSE[4294] logger.c: == Parsing '/etc/asterisk/manage$ Apr 10 18:23:37 VERBOSE[4294] logger.c: == Parsing '/etc/asterisk/manager_custom.conf': Apr 10 18:23:37 VERBOSE[4294] logger.c: == Parsing '/etc/asterisk$ Apr 10 18:23:37 WARNING[4294] config.c: Unknown directive 'permit=192.168.1.0/255.255.255.0' at line 18 of /etc/asterisk/manager_custom.conf Apr 10 18:23:37 DEBUG[4294] acl.c: 0.0.0.0/0.0.0.0/0.0.0.0 appended to acl for peer Apr 10 18:23:37 DEBUG[4294] acl.c: 127.0.0.1/255.255.255.0/255.255.255.0 appended to acl for peer Apr 10 18:23:37 DEBUG[4294] acl.c: ##### Testing 127.0.0.1 with 0.0.0.0 Apr 10 18:23:37 DEBUG[4294] acl.c: ##### Testing 127.0.0.1 with 127.0.0.0 Apr 10 18:23:37 VERBOSE[4294] logger.c: == Manager 'admin' logged on from 127.0.0.1 Apr 10 18:23:37 DEBUG[4294] manager.c: Manager received command 'ExtensionState' Apr 10 18:23:37 DEBUG[4294] manager.c: Manager received command 'Logoff' Apr 10 18:23:37 VERBOSE[4289] logger.c: > dialparties.agi: ExtensionState: 0 Apr 10 18:23:37 VERBOSE[4289] logger.c: dialparties.agi: Extension 200 has ExtensionState: 0 Apr 10 18:23:37 VERBOSE[4289] logger.c: -- dialparties.agi: Checking CW and CFB status for extension 200 Apr 10 18:23:37 DEBUG[4289] db.c: Unable to find key '201' in family 'CW' Apr 10 18:23:37 DEBUG[4289] db.c: Unable to find key '201' in family 'CFB' Apr 10 18:23:37 DEBUG[4289] db.c: Unable to find key '201' in family 'CFU' Apr 10 18:23:37 VERBOSE[4289] logger.c: > dialparties.agi: extnum: 201 Apr 10 18:23:37 VERBOSE[4289] logger.c: > dialparties.agi: exthascw: 0 Apr 10 18:23:37 VERBOSE[4289] logger.c: > dialparties.agi: exthascfb: 0 Apr 10 18:23:37 VERBOSE[4289] logger.c: > dialparties.agi: extcfb: Apr 10 18:23:37 VERBOSE[4289] logger.c: > dialparties.agi: exthascfu: 0 Apr 10 18:23:37 VERBOSE[4289] logger.c: > dialparties.agi: extcfu: Apr 10 18:23:37 DEBUG[4295] manager.c: Manager received command 'login' Apr 10 18:23:37 VERBOSE[4295] logger.c: == Parsing '/etc/asterisk/manager.conf': Apr 10 18:23:37 VERBOSE[4295] logger.c: == Parsing '/etc/asterisk/manage$ Apr 10 18:23:37 VERBOSE[4295] logger.c: == Parsing '/etc/asterisk/manager_custom.conf': Apr 10 18:23:37 VERBOSE[4295] logger.c: == Parsing '/etc/asterisk$ Apr 10 18:23:37 WARNING[4295] config.c: Unknown directive 'permit=192.168.1.0/255.255.255.0' at line 18 of /etc/asterisk/manager_custom.conf Apr 10 18:23:37 DEBUG[4295] acl.c: 0.0.0.0/0.0.0.0/0.0.0.0 appended to acl for peer Apr 10 18:23:37 DEBUG[4295] acl.c: 127.0.0.1/255.255.255.0/255.255.255.0 appended to acl for peer Apr 10 18:23:37 DEBUG[4295] acl.c: ##### Testing 127.0.0.1 with 0.0.0.0 Apr 10 18:23:37 DEBUG[4295] acl.c: ##### Testing 127.0.0.1 with 127.0.0.0 Apr 10 18:23:37 VERBOSE[4295] logger.c: == Manager 'admin' logged on from 127.0.0.1 Apr 10 18:23:37 VERBOSE[4294] logger.c: == Manager 'admin' logged off from 127.0.0.1 Apr 10 18:23:37 DEBUG[4295] manager.c: Manager received command 'ExtensionState' Apr 10 18:23:37 DEBUG[4295] manager.c: Manager received command 'Logoff' Apr 10 18:23:37 VERBOSE[4295] logger.c: == Manager 'admin' logged off from 127.0.0.1 Apr 10 18:23:37 VERBOSE[4289] logger.c: > dialparties.agi: ExtensionState: 0 Apr 10 18:23:37 VERBOSE[4289] logger.c: dialparties.agi: Extension 201 has ExtensionState: 0 Apr 10 18:23:37 VERBOSE[4289] logger.c: -- dialparties.agi: Checking CW and CFB status for extension 201 Apr 10 18:23:37 DEBUG[4289] db.c: Unable to find key '202' in family 'CW' Apr 10 18:23:37 DEBUG[4289] db.c: Unable to find key '202' in family 'CFB' Apr 10 18:23:37 DEBUG[4289] db.c: Unable to find key '202' in family 'CFU' Apr 10 18:23:37 VERBOSE[4289] logger.c: > dialparties.agi: extnum: 202 Apr 10 18:23:37 VERBOSE[4289] logger.c: > dialparties.agi: exthascw: 0 Apr 10 18:23:37 VERBOSE[4289] logger.c: > dialparties.agi: exthascfb: 0 Apr 10 18:23:37 VERBOSE[4289] logger.c: > dialparties.agi: extcfb: Apr 10 18:23:37 VERBOSE[4289] logger.c: > dialparties.agi: exthascfu: 0 Apr 10 18:23:37 VERBOSE[4289] logger.c: > dialparties.agi: extcfu: Apr 10 18:23:37 DEBUG[4296] manager.c: Manager received command 'login' Apr 10 18:23:37 VERBOSE[4296] logger.c: == Parsing '/etc/asterisk/manager.conf': Apr 10 18:23:37 VERBOSE[4296] logger.c: == Parsing '/etc/asterisk/manage$ Apr 10 18:23:37 VERBOSE[4296] logger.c: == Parsing '/etc/asterisk/manager_custom.conf': Apr 10 18:23:37 VERBOSE[4296] logger.c: == Parsing '/etc/asterisk$ Apr 10 18:23:37 WARNING[4296] config.c: Unknown directive 'permit=192.168.1.0/255.255.255.0' at line 18 of /etc/asterisk/manager_custom.conf Apr 10 18:23:37 DEBUG[4296] acl.c: 0.0.0.0/0.0.0.0/0.0.0.0 appended to acl for peer Apr 10 18:23:37 DEBUG[4296] acl.c: 127.0.0.1/255.255.255.0/255.255.255.0 appended to acl for peer Apr 10 18:23:37 DEBUG[4296] acl.c: ##### Testing 127.0.0.1 with 0.0.0.0 Apr 10 18:23:37 DEBUG[4296] acl.c: ##### Testing 127.0.0.1 with 127.0.0.0 Apr 10 18:23:37 VERBOSE[4296] logger.c: == Manager 'admin' logged on from 127.0.0.1 Apr 10 18:23:37 DEBUG[4296] manager.c: Manager received command 'ExtensionState' Apr 10 18:23:37 DEBUG[4296] manager.c: Manager received command 'Logoff' Apr 10 18:23:37 VERBOSE[4289] logger.c: > dialparties.agi: ExtensionState: 0 Apr 10 18:23:37 VERBOSE[4289] logger.c: dialparties.agi: Extension 202 has ExtensionState: 0 Apr 10 18:23:37 VERBOSE[4289] logger.c: -- dialparties.agi: Checking CW and CFB status for extension 202 Apr 10 18:23:37 VERBOSE[4289] logger.c: > dialparties.agi: NODEST: 600 adding M(auto-blkvm) to dialopts: trM(auto-blkvm) Apr 10 18:23:37 VERBOSE[4289] logger.c: -- AGI Script dialparties.agi completed, returning 0 Apr 10 18:23:37 VERBOSE[4289] logger.c: -- Executing NoOp("SIP/557728832-0823cc50", "Returned from dialparties with hunt groups to dial ") in new stack Apr 10 18:23:37 VERBOSE[4289] logger.c: -- Executing Set("SIP/557728832-0823cc50", "HuntLoop=0") in new stack Apr 10 18:23:37 DEBUG[4289] pbx.c: Expression result is '1' Apr 10 18:23:37 VERBOSE[4289] logger.c: -- Executing GotoIf("SIP/557728832-0823cc50", "1?30 ") in new stack Apr 10 18:23:37 VERBOSE[4289] logger.c: -- Goto (macro-dial,s,30) Apr 10 18:23:37 VERBOSE[4289] logger.c: -- Executing Set("SIP/557728832-0823cc50", "HuntMember=HuntMember0") in new stack Apr 10 18:23:37 DEBUG[4289] pbx.c: Expression result is '1' Apr 10 18:23:37 DEBUG[4289] pbx.c: Expression result is '1' Apr 10 18:23:37 DEBUG[4289] pbx.c: Expression result is '1' Apr 10 18:23:37 VERBOSE[4289] logger.c: -- Executing GotoIf("SIP/557728832-0823cc50", "1?32:35 ") in new stack Apr 10 18:23:37 VERBOSE[4289] logger.c: -- Goto (macro-dial,s,32) Apr 10 18:23:37 DEBUG[4289] pbx.c: Expression result is '1' Apr 10 18:23:37 DEBUG[4289] pbx.c: Function result is '200' Apr 10 18:23:37 VERBOSE[4289] logger.c: -- Executing Set("SIP/557728832-0823cc50", "CT_EXTEN=200") in new stack Apr 10 18:23:37 VERBOSE[4289] logger.c: -- Executing Set("SIP/557728832-0823cc50", "DB(CALLTRACE/200)=34913821724") in new stack Apr 10 18:23:37 VERBOSE[4289] logger.c: -- Executing Goto("SIP/557728832-0823cc50", "s|42") in new stack Apr 10 18:23:37 VERBOSE[4289] logger.c: -- Goto (macro-dial,s,42) Apr 10 18:23:37 VERBOSE[4289] logger.c: -- Executing Dial("SIP/557728832-0823cc50", "SIP/200|20|trM(auto-blkvm) ") in new stack Apr 10 18:23:37 DEBUG[4289] chan_sip.c: Setting NAT on RTP to 0 Apr 10 18:23:37 DEBUG[4289] acl.c: ##### Testing 192.168.1.23 with 192.168.1.0 Apr 10 18:23:37 DEBUG[4289] chan_sip.c: Outgoing Call for 200 Apr 10 18:23:37 VERBOSE[4289] logger.c: -- Called 200 Apr 10 18:23:37 DEBUG[4289] channel.c: Driver for channel 'SIP/557728832-0823cc50' does not support indication 3, emulating it Apr 10 18:23:37 DEBUG[4289] channel.c: Scheduling timer at 160 sample intervals Apr 10 18:23:37 DEBUG[4289] channel.c: Generator got voice, switching to phase locked mode Apr 10 18:23:37 DEBUG[4289] channel.c: Scheduling timer at 0 sample intervals Apr 10 18:23:37 VERBOSE[4296] logger.c: == Manager 'admin' logged off from 127.0.0.1 Apr 10 18:23:37 DEBUG[2621] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '7388b4d14f59a6ae4753add96c4e36a8@192.168.1.5' Reques$ Apr 10 18:23:37 DEBUG[2621] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '7388b4d14f59a6ae4753add96c4e36a8@192.168.1.5' Reques$ Apr 10 18:23:37 VERBOSE[4289] logger.c: -- SIP/200-08242190 is ringing Apr 10 18:23:42 WARNING[2621] chan_sip.c: Maximum retries exceeded on transmission A283C6CA-E6B611DB-AC6DC0AD-AB2E51AA@195.214.40.132 for seqno 101 (Critical$ Apr 10 18:23:42 WARNING[2621] chan_sip.c: Hanging up call A283C6CA-E6B611DB-AC6DC0AD-AB2E51AA@195.214.40.132 - no reply to our critical packet. Apr 10 18:23:42 DEBUG[4289] channel.c: Scheduling timer at 0 sample intervals Apr 10 18:23:42 DEBUG[4289] chan_sip.c: update_call_counter(200) - decrement call limit counter Apr 10 18:23:42 DEBUG[4289] chan_sip.c: Acked pending invite 102 Apr 10 18:23:42 DEBUG[4289] chan_sip.c: Stopping retransmission on '7388b4d14f59a6ae4753add96c4e36a8@192.168.1.5' of Request 102: Match Found Apr 10 18:23:42 DEBUG[4289] app_dial.c: Exiting with DIALSTATUS=CANCEL. Apr 10 18:23:42 VERBOSE[4289] logger.c: == Spawn extension (macro-dial, s, 42) exited non-zero on 'SIP/557728832-0823cc50' in macro 'dial' Apr 10 18:23:42 VERBOSE[4289] logger.c: == Spawn extension (macro-dial, s, 42) exited non-zero on 'SIP/557728832-0823cc50' Apr 10 18:23:42 VERBOSE[4289] logger.c: -- Executing Macro("SIP/557728832-0823cc50", "hangupcall") in new stack Apr 10 18:23:42 VERBOSE[4289] logger.c: -- Executing ResetCDR("SIP/557728832-0823cc50", "w") in new stack Apr 10 18:23:42 DEBUG[4289] cdr_addon_mysql.c: cdr_mysql: inserting a CDR record. Apr 10 18:23:42 DEBUG[4289] cdr_addon_mysql.c: cdr_mysql: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,$ Apr 10 18:23:42 VERBOSE[4289] logger.c: -- Executing NoCDR("SIP/557728832-0823cc50", "") in new stack Apr 10 18:23:42 NOTICE[4289] cdr.c: CDR on channel 'SIP/557728832-0823cc50' not posted Apr 10 18:23:42 NOTICE[4289] cdr.c: CDR on channel 'SIP/557728832-0823cc50' lacks end Apr 10 18:23:42 DEBUG[4289] pbx.c: Expression result is '1' Apr 10 18:23:42 VERBOSE[4289] logger.c: -- Executing GotoIf("SIP/557728832-0823cc50", "1?skiprg") in new stack Apr 10 18:23:42 VERBOSE[4289] logger.c: -- Goto (macro-hangupcall,s,6) Apr 10 18:23:42 DEBUG[4289] pbx.c: Expression result is '0' Apr 10 18:23:42 VERBOSE[4289] logger.c: -- Executing GotoIf("SIP/557728832-0823cc50", "0?theend") in new stack Apr 10 18:23:42 DEBUG[4289] pbx.c: Not taking any branch Apr 10 18:23:42 VERBOSE[4289] logger.c: -- Executing NoOp("SIP/557728832-0823cc50", "Cleaning Up Block VM Flag: BLKVM/600/SIP/557728832-0823cc50") in new$ Apr 10 18:23:42 VERBOSE[4289] logger.c: -- Executing DBdel("SIP/557728832-0823cc50", "BLKVM/600/SIP/557728832-0823cc50") in new stack Apr 10 18:23:42 VERBOSE[4289] logger.c: -- DBdel: family=BLKVM, key=600/SIP/557728832-0823cc50 Apr 10 18:23:42 DEBUG[2621] chan_sip.c: Stopping retransmission on '7388b4d14f59a6ae4753add96c4e36a8@192.168.1.5' of Request 102: Match Found Apr 10 18:23:42 DEBUG[2621] chan_sip.c: Stopping retransmission on '7388b4d14f59a6ae4753add96c4e36a8@192.168.1.5' of Request 102: Match Not Found Apr 10 18:23:42 VERBOSE[4289] logger.c: -- Executing Wait("SIP/557728832-0823cc50", "5") in new stack Apr 10 18:23:42 VERBOSE[4289] logger.c: == Spawn extension (macro-hangupcall, s, 9) exited non-zero on 'SIP/557728832-0823cc50' in macro 'hangupcall' Apr 10 18:23:42 VERBOSE[4289] logger.c: == Spawn extension (macro-hangupcall, s, 9) exited non-zero on 'SIP/557728832-0823cc50' Apr 10 18:23:42 DEBUG[4289] chan_sip.c: update_call_counter(557728832) - decrement call limit counter