Jan 11 10:31:18 VERBOSE[16638]: Asterisk Event Logger restarted Jan 11 10:31:44 DEBUG[16638]: Setting NAT on RTP to 0 Jan 11 10:31:44 DEBUG[16638]: Stopping retransmission on '4cfd466a-d96079ec-d6d3a6c1@192.168.3.108' of Response 1: Found Jan 11 10:31:45 DEBUG[16638]: Setting NAT on RTP to 0 Jan 11 10:31:45 DEBUG[16638]: Check for res for 108 Jan 11 10:31:45 DEBUG[16638]: Call from user '108' is 1 out of 0 Jan 11 10:31:45 DEBUG[16638]: build_route: Contact hop: Jan 11 10:31:45 VERBOSE[16638]: -- Executing Macro("SIP/108-9026", "exten-vm|111|111") in new stack Jan 11 10:31:45 VERBOSE[16638]: -- Executing Macro("SIP/108-9026", "user-callerid") in new stack Jan 11 10:31:45 VERBOSE[16638]: -- Executing DBget("SIP/108-9026", "AMPUSER=DEVICE/108/user") in new stack Jan 11 10:31:45 VERBOSE[16638]: -- DBget: varname=AMPUSER, family=DEVICE, key=108/user Jan 11 10:31:45 VERBOSE[16638]: -- DBget: set variable AMPUSER to 108 Jan 11 10:31:45 VERBOSE[16638]: -- Executing DBget("SIP/108-9026", "AMPUSERCIDNAME=AMPUSER/108/cidname") in new stack Jan 11 10:31:45 VERBOSE[16638]: -- DBget: varname=AMPUSERCIDNAME, family=AMPUSER, key=108/cidname Jan 11 10:31:45 VERBOSE[16638]: -- DBget: set variable AMPUSERCIDNAME to Twila Jan 11 10:31:45 DEBUG[16638]: Expression is '0' Jan 11 10:31:45 VERBOSE[16638]: -- Executing GotoIf("SIP/108-9026", "0?5") in new stack Jan 11 10:31:45 DEBUG[16638]: Not taking any branch Jan 11 10:31:45 VERBOSE[16638]: -- Executing SetCallerID("SIP/108-9026", ""Twila" <108>") in new stack Jan 11 10:31:45 VERBOSE[16638]: -- Executing NoOp("SIP/108-9026", "Using CallerID "Twila" <108>") in new stack Jan 11 10:31:45 VERBOSE[16638]: -- Executing SetVar("SIP/108-9026", "FROMCONTEXT=exten-vm") in new stack Jan 11 10:31:45 VERBOSE[16638]: -- Executing Macro("SIP/108-9026", "record-enable|111|IN") in new stack Jan 11 10:31:45 VERBOSE[16638]: -- Executing GotoIf("SIP/108-9026", "0 > 0?2:4") in new stack Jan 11 10:31:45 VERBOSE[16638]: -- Goto (macro-record-enable,s,4) Jan 11 10:31:45 VERBOSE[16638]: -- Executing AGI("SIP/108-9026", "recordingcheck|20060111-103145|1136993505.8") in new stack Jan 11 10:31:45 VERBOSE[16638]: -- Launched AGI Script /var/lib/asterisk/agi-bin/recordingcheck Jan 11 10:31:45 VERBOSE[16638]: recordingcheck|20060111-103145|1136993505.8: Inbound recording enabled. Jan 11 10:31:45 VERBOSE[16638]: recordingcheck|20060111-103145|1136993505.8: CALLFILENAME=20060111-103145-1136993505.8 Jan 11 10:31:45 VERBOSE[16638]: -- AGI Script recordingcheck completed, returning 0 Jan 11 10:31:45 VERBOSE[16638]: -- Executing Monitor("SIP/108-9026", "wav49|20060111-103145-1136993505.8| mb") in new stack Jan 11 10:31:45 VERBOSE[16638]: -- Executing Macro("SIP/108-9026", "dial|15|tr|111") in new stack Jan 11 10:31:45 DEBUG[16638]: Expression is '0' Jan 11 10:31:45 VERBOSE[16638]: -- Executing GotoIf("SIP/108-9026", "0?4:2") in new stack Jan 11 10:31:45 VERBOSE[16638]: -- Goto (macro-dial,s,2) Jan 11 10:31:45 DEBUG[16638]: Expression is '0' Jan 11 10:31:45 VERBOSE[16638]: -- Executing GotoIf("SIP/108-9026", "0?4:3") in new stack Jan 11 10:31:45 VERBOSE[16638]: -- Goto (macro-dial,s,3) Jan 11 10:31:45 VERBOSE[16638]: -- Executing SetCIDName("SIP/108-9026", "Twila") in new stack Jan 11 10:31:45 VERBOSE[16638]: -- Executing AGI("SIP/108-9026", "dialparties.agi") in new stack Jan 11 10:31:45 VERBOSE[16638]: -- Launched AGI Script /var/lib/asterisk/agi-bin/dialparties.agi Jan 11 10:31:45 VERBOSE[16638]: -- dialparties.agi: request = dialparties.agi Jan 11 10:31:45 VERBOSE[16638]: -- dialparties.agi: priority = 4 Jan 11 10:31:45 VERBOSE[16638]: -- dialparties.agi: extension = s Jan 11 10:31:45 VERBOSE[16638]: -- dialparties.agi: language = en Jan 11 10:31:45 VERBOSE[16638]: -- dialparties.agi: accountcode = Jan 11 10:31:45 VERBOSE[16638]: -- dialparties.agi: uniqueid = 1136993505.8 Jan 11 10:31:45 VERBOSE[16638]: -- dialparties.agi: channel = SIP/108-9026 Jan 11 10:31:45 VERBOSE[16638]: -- dialparties.agi: callerid = Twila <108> Jan 11 10:31:45 VERBOSE[16638]: -- dialparties.agi: context = macro-dial Jan 11 10:31:45 VERBOSE[16638]: -- dialparties.agi: type = SIP Jan 11 10:31:45 VERBOSE[16638]: -- dialparties.agi: rdnis = unknown Jan 11 10:31:45 VERBOSE[16638]: -- dialparties.agi: enhanced = 0.0 Jan 11 10:31:45 VERBOSE[16638]: -- dialparties.agi: dnid = 111 Jan 11 10:31:45 VERBOSE[16638]: dialparties.agi: Caller ID name is 'Twila' number is '108' Jan 11 10:31:45 VERBOSE[16638]: dialparties.agi: Methodology of ring is 'none' Jan 11 10:31:45 VERBOSE[16638]: -- dialparties.agi: Added extension 111 to extension map Jan 11 10:31:45 DEBUG[16638]: Unable to find key '111' in family 'CF' Jan 11 10:31:45 VERBOSE[16638]: -- dialparties.agi: Extension 111 cf is disabled Jan 11 10:31:45 DEBUG[16638]: Unable to find key '111' in family 'DND' Jan 11 10:31:45 VERBOSE[16638]: -- dialparties.agi: Extension 111 do not disturb is disabled Jan 11 10:31:45 DEBUG[16638]: Unable to find key '111' in family 'CW' Jan 11 10:31:45 DEBUG[16638]: Unable to find key '111' in family 'CFB' Jan 11 10:31:45 VERBOSE[16638]: -- dialparties.agi: Checking CW and CFB status for extension 111 Jan 11 10:31:45 DEBUG[16638]: Manager received command 'Login' Jan 11 10:31:45 VERBOSE[16638]: == Parsing '/etc/asterisk/manager.conf': Jan 11 10:31:45 VERBOSE[16638]: == Parsing '/etc/asterisk/manager.conf': Found Jan 11 10:31:45 VERBOSE[16638]: == Parsing '/etc/asterisk/manager_custom.conf': Jan 11 10:31:45 VERBOSE[16638]: == Parsing '/etc/asterisk/manager_custom.conf': Not found (No such file or directory) Jan 11 10:31:45 DEBUG[16638]: 0.0.0.0/0.0.0.0/0.0.0.0 appended to acl for peer Jan 11 10:31:45 DEBUG[16638]: 127.0.0.1/255.255.255.0/255.255.255.0 appended to acl for peer Jan 11 10:31:45 DEBUG[16638]: ##### Testing 127.0.0.1 with 0.0.0.0 Jan 11 10:31:45 DEBUG[16638]: ##### Testing 127.0.0.1 with 127.0.0.0 Jan 11 10:31:45 VERBOSE[16638]: == Manager 'admin' logged on from 127.0.0.1 Jan 11 10:31:45 DEBUG[16638]: Manager received command 'ExtensionState' Jan 11 10:31:45 DEBUG[16638]: Manager received command 'Logoff' Jan 11 10:31:45 VERBOSE[16638]: == Manager 'admin' logged off from 127.0.0.1 Jan 11 10:31:45 VERBOSE[16638]: dialparties.agi: Extension 111 is available...skipping checks Jan 11 10:31:45 VERBOSE[16638]: -- dialparties.agi: DbSet CALLTRACE/111 to 108 Jan 11 10:31:45 VERBOSE[16638]: -- AGI Script dialparties.agi completed, returning 0 Jan 11 10:31:45 VERBOSE[16638]: -- Executing Dial("SIP/108-9026", "SIP/111|15|tr") in new stack Jan 11 10:31:45 DEBUG[16638]: SIMPLE DIAL (NO URL) Jan 11 10:31:45 DEBUG[16638]: Setting NAT on RTP to 0 Jan 11 10:31:45 DEBUG[16638]: Outgoing Call for 111 Jan 11 10:31:45 DEBUG[16638]: Call from user '111' is 1 out of 0 Jan 11 10:31:45 VERBOSE[16638]: -- Called 111 Jan 11 10:31:45 DEBUG[16638]: (Provisional) Stopping retransmission (but retaining packet) on '5b5a03d55169f3027cf43a6f2cbc2f16@192.168.3.185' Request 102: Found Jan 11 10:31:45 DEBUG[16638]: (Provisional) Stopping retransmission (but retaining packet) on '5b5a03d55169f3027cf43a6f2cbc2f16@192.168.3.185' Request 102: Found Jan 11 10:31:45 VERBOSE[16638]: -- SIP/111-2253 is ringing Jan 11 10:31:46 DEBUG[16638]: Acked pending invite 102 Jan 11 10:31:46 DEBUG[16638]: Stopping retransmission on '5b5a03d55169f3027cf43a6f2cbc2f16@192.168.3.185' of Request 102: Found Jan 11 10:31:46 DEBUG[16638]: build_route: Contact hop: Jan 11 10:31:46 VERBOSE[16638]: -- SIP/111-2253 answered SIP/108-9026 Jan 11 10:31:46 DEBUG[16638]: Stopping retransmission on '4cfd466a-d96079ec-d6d3a6c1@192.168.3.108' of Response 2: Found Jan 11 10:31:46 DEBUG[16638]: Ooh, format changed from unknown to ulaw Jan 11 10:31:47 DEBUG[16638]: Ooh, format changed from unknown to ulaw Jan 11 10:31:59 NOTICE[16638]: Peer '111' is now UNREACHABLE! Jan 11 10:31:59 DEBUG[16638]: Stopping retransmission on '4b1c8d3029f65fbd7375cd694810c79f@192.168.3.185' of Request 102: Found Jan 11 10:32:59 DEBUG[16638]: Stopping retransmission on '4b42cabc60367d803d543f553b01ffb9@192.168.3.185' of Request 102: Found Jan 11 10:33:07 DEBUG[16638]: Manager received command 'Command' Jan 11 10:33:07 DEBUG[16638]: Manager received command 'Command' Jan 11 10:33:19 DEBUG[16638]: Stopping retransmission on '741467904aa7b3f50152f4f95d636297@192.168.3.185' of Request 102: Found Jan 11 10:33:19 NOTICE[16638]: Peer '111' is now REACHABLE! Jan 11 10:33:24 DEBUG[16638]: Setting NAT on RTP to 0 Jan 11 10:33:25 DEBUG[16638]: Stopping retransmission on '52a2b94d74d8450c7c1f260e3cb98b1a@192.168.3.185' of Request 102: Found Jan 11 10:33:31 DEBUG[16638]: Auto destroying call '42009183-60bd8c7d-17a18450@192.168.3.111'