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: <sip:108@192.168.3.108:5060>
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: <sip:111@192.168.3.111:5060>
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'