Nov 23 11:17:32 DEBUG[2210]: Allocating new SIP call for CALL_ID125_00D0E90182FC_T1499234192@192.168.1.132
Nov 23 11:17:32 DEBUG[2210]: Setting NAT on RTP to 0
Nov 23 11:17:32 DEBUG[2210]: Stopping retransmission on 'CALL_ID125_00D0E90182FC_T1499234192@192.168.1.132' of Response 1555618554: Found
Nov 23 11:17:32 DEBUG[2210]: Setting NAT on RTP to 0
Nov 23 11:17:32 DEBUG[2210]: Check for res for 1337
Nov 23 11:17:32 DEBUG[2210]: Call from user '1337' is 1 out of 0
Nov 23 11:17:32 DEBUG[2210]: build_route: Contact hop: <sip:1337@192.168.1.132:5060>
Nov 23 11:17:32 DEBUG[2210]: Launching 'Macro'
Nov 23 11:17:32 VERBOSE[2210]: -- Executing Macro("SIP/1337-71b6", "exten-vm|1331@default|1331") in new stack
Nov 23 11:17:32 DEBUG[2210]: Launching 'SetVar'
Nov 23 11:17:32 VERBOSE[2210]: -- Executing SetVar("SIP/1337-71b6", "FROMCONTEXT=exten-vm") in new stack
Nov 23 11:17:32 DEBUG[2210]: Launching 'Macro'
Nov 23 11:17:32 VERBOSE[2210]: -- Executing Macro("SIP/1337-71b6", "record-enable|1331|IN") in new stack
Nov 23 11:17:32 DEBUG[2210]: Launching 'GotoIf'
Nov 23 11:17:32 VERBOSE[2210]: -- Executing GotoIf("SIP/1337-71b6", "0 > 0?2:4") in new stack
Nov 23 11:17:32 VERBOSE[2210]: -- Goto (macro-record-enable,s,4)
Nov 23 11:17:32 DEBUG[2210]: Expression is '0'
Nov 23 11:17:32 DEBUG[2210]: Launching 'GotoIf'
Nov 23 11:17:32 VERBOSE[2210]: -- Executing GotoIf("SIP/1337-71b6", "0?5:8") in new stack
Nov 23 11:17:32 VERBOSE[2210]: -- Goto (macro-record-enable,s,8)
Nov 23 11:17:32 DEBUG[2210]: Expression is '0'
Nov 23 11:17:32 DEBUG[2210]: Launching 'GotoIf'
Nov 23 11:17:32 VERBOSE[2210]: -- Executing GotoIf("SIP/1337-71b6", "0?9:12") in new stack
Nov 23 11:17:32 VERBOSE[2210]: -- Goto (macro-record-enable,s,12)
Nov 23 11:17:32 DEBUG[2210]: Launching 'DBget'
Nov 23 11:17:32 VERBOSE[2210]: -- Executing DBget("SIP/1337-71b6", "RecEnable=RECORD-IN/1331") in new stack
Nov 23 11:17:32 VERBOSE[2210]: -- DBget: varname=RecEnable, family=RECORD-IN, key=1331
Nov 23 11:17:32 DEBUG[2210]: Unable to find key '1331' in family 'RECORD-IN'
Nov 23 11:17:32 VERBOSE[2210]: -- DBget: Value not found in database.
Nov 23 11:17:32 DEBUG[2210]: Launching 'SetVar'
Nov 23 11:17:32 VERBOSE[2210]: -- Executing SetVar("SIP/1337-71b6", "CALLFILENAME=20051123-111732-1132762652.46") in new stack
Nov 23 11:17:32 DEBUG[2210]: Expression is '0'
Nov 23 11:17:32 DEBUG[2210]: Launching 'GotoIf'
Nov 23 11:17:32 VERBOSE[2210]: -- Executing GotoIf("SIP/1337-71b6", "0?15:99") in new stack
Nov 23 11:17:32 VERBOSE[2210]: -- Goto (macro-record-enable,s,99)
Nov 23 11:17:32 DEBUG[2210]: Launching 'NoOp'
Nov 23 11:17:32 VERBOSE[2210]: -- Executing NoOp("SIP/1337-71b6", "NO RECORDING NEEDED") in new stack
Nov 23 11:17:32 DEBUG[2210]: Launching 'Macro'
Nov 23 11:17:32 VERBOSE[2210]: -- Executing Macro("SIP/1337-71b6", "dial|15|tr|1331") in new stack
Nov 23 11:17:32 DEBUG[2210]: Expression is '0'
Nov 23 11:17:32 DEBUG[2210]: Launching 'GotoIf'
Nov 23 11:17:32 VERBOSE[2210]: -- Executing GotoIf("SIP/1337-71b6", "0?4:2") in new stack
Nov 23 11:17:32 VERBOSE[2210]: -- Goto (macro-dial,s,2)
Nov 23 11:17:32 WARNING[2210]: ast_yyerror(): syntax error: syntax error; Input:
!=
^
Nov 23 11:17:32 DEBUG[2210]: Expression is '0'
Nov 23 11:17:32 DEBUG[2210]: Launching 'GotoIf'
Nov 23 11:17:32 VERBOSE[2210]: -- Executing GotoIf("SIP/1337-71b6", "0?4:3") in new stack
Nov 23 11:17:32 VERBOSE[2210]: -- Goto (macro-dial,s,3)
Nov 23 11:17:32 DEBUG[2210]: Launching 'SetCIDName'
Nov 23 11:17:32 VERBOSE[2210]: -- Executing SetCIDName("SIP/1337-71b6", "Robert Davies") in new stack
Nov 23 11:17:32 DEBUG[2210]: Launching 'AGI'
Nov 23 11:17:32 VERBOSE[2210]: -- Executing AGI("SIP/1337-71b6", "dialparties.agi") in new stack
Nov 23 11:17:32 VERBOSE[2210]: -- Launched AGI Script /var/lib/asterisk/agi-bin/dialparties.agi
Nov 23 11:17:32 VERBOSE[2210]: -- AGI Script dialparties.agi completed, returning 0
Nov 23 11:17:32 DEBUG[2210]: Launching 'NoOp'
Nov 23 11:17:32 VERBOSE[2210]: -- Executing NoOp("SIP/1337-71b6", "Returned from dialparties with no extensions to call") in new stack
Nov 23 11:17:32 DEBUG[2210]: Launching 'SetVar'
Nov 23 11:17:32 VERBOSE[2210]: -- Executing SetVar("SIP/1337-71b6", "DIALSTATUS=BUSY") in new stack
Nov 23 11:17:32 DEBUG[2210]: Expression is '0'
Nov 23 11:17:32 DEBUG[2210]: Launching 'GotoIf'
Nov 23 11:17:32 VERBOSE[2210]: -- Executing GotoIf("SIP/1337-71b6", "0?s-BUSY|1") in new stack
Nov 23 11:17:32 DEBUG[2210]: Not taking any branch
Nov 23 11:17:32 DEBUG[2210]: Expression is '0'
Nov 23 11:17:32 DEBUG[2210]: Launching 'GotoIf'
Nov 23 11:17:32 VERBOSE[2210]: -- Executing GotoIf("SIP/1337-71b6", "0?s-BUSY|1") in new stack
Nov 23 11:17:32 DEBUG[2210]: Not taking any branch
Nov 23 11:17:32 DEBUG[2210]: Launching 'NoOp'
Nov 23 11:17:32 VERBOSE[2210]: -- Executing NoOp("SIP/1337-71b6", "Sending to Voicemail box 1331@default") in new stack
Nov 23 11:17:32 DEBUG[2210]: Launching 'Macro'
Nov 23 11:17:32 VERBOSE[2210]: -- Executing Macro("SIP/1337-71b6", "vm|1331@default|BUSY") in new stack
Nov 23 11:17:32 DEBUG[2210]: Launching 'Goto'
Nov 23 11:17:32 VERBOSE[2210]: -- Executing Goto("SIP/1337-71b6", "s-BUSY|1") in new stack
Nov 23 11:17:32 VERBOSE[2210]: -- Goto (macro-vm,s-BUSY,1)
Nov 23 11:17:32 DEBUG[2210]: Launching 'VoiceMail'
Nov 23 11:17:32 VERBOSE[2210]: -- Executing VoiceMail("SIP/1337-71b6", "b1331@default") in new stack
Nov 23 11:17:32 DEBUG[2210]: sip_answer(SIP/1337-71b6)
Nov 23 11:17:32 DEBUG[2210]: voicemail/default/1331/busy doesn't exist, doing what we can
Nov 23 11:17:32 DEBUG[2210]: Set channel SIP/1337-71b6 to write format gsm
Nov 23 11:17:32 DEBUG[2210]: Ooh, format changed from unknown to ulaw
Nov 23 11:17:32 DEBUG[2210]: Scheduling timer at 160 sample intervals
Nov 23 11:17:32 VERBOSE[2210]: -- Playing 'vm-theperson' (language 'en')
Nov 23 11:17:32 DEBUG[2210]: Stopping retransmission on 'CALL_ID125_00D0E90182FC_T1499234192@192.168.1.132' of Response 1555618555: Found
Nov 23 11:17:33 DEBUG[2210]: Hang up during prefile playback
Nov 23 11:17:33 DEBUG[2210]: Spawn extension (macro-vm,s-BUSY,1) exited non-zero on 'SIP/1337-71b6' in macro 'vm'
Nov 23 11:17:33 DEBUG[2210]: Spawn extension (macro-exten-vm,s,7) exited non-zero on 'SIP/1337-71b6' in macro 'exten-vm'
Nov 23 11:17:33 DEBUG[2210]: Spawn extension (from-internal,1331,1) exited non-zero on 'SIP/1337-71b6'
Nov 23 11:17:33 DEBUG[2210]: Launching 'Macro'
Nov 23 11:17:33 VERBOSE[2210]: -- Executing Macro("SIP/1337-71b6", "hangupcall") in new stack
Nov 23 11:17:33 DEBUG[2210]: Launching 'ResetCDR'
Nov 23 11:17:33 VERBOSE[2210]: -- Executing ResetCDR("SIP/1337-71b6", "w") in new stack
Nov 23 11:17:33 DEBUG[2210]: cdr_mysql: inserting a CDR record.
Nov 23 11:17:33 DEBUG[2210]: cdr_mysql: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode) VALUES ('2005-11-23 11:17:32','\"Robert Davies\" <1337>','1337','1331','from-internal', 'SIP/1337-71b6','','ResetCDR','w',1,1,'ANSWERED',3,'')
Nov 23 11:17:33 DEBUG[2210]: Launching 'NoCDR'
Nov 23 11:17:33 VERBOSE[2210]: -- Executing NoCDR("SIP/1337-71b6", "") in new stack
Nov 23 11:17:33 WARNING[2210]: CDR on channel 'SIP/1337-71b6' not posted
Nov 23 11:17:33 WARNING[2210]: CDR on channel 'SIP/1337-71b6' lacks end
Nov 23 11:17:33 DEBUG[2210]: Launching 'Wait'
Nov 23 11:17:33 VERBOSE[2210]: -- Executing Wait("SIP/1337-71b6", "5") in new stack
Nov 23 11:17:33 DEBUG[2210]: Spawn extension (macro-hangupcall,s,3) exited non-zero on 'SIP/1337-71b6' in macro 'hangupcall'
Nov 23 11:17:33 DEBUG[2210]: Spawn extension (from-internal,h,1) exited non-zero on 'SIP/1337-71b6'
Nov 23 11:17:33 DEBUG[2210]: Scheduling timer at 0 sample intervals
Nov 23 11:17:33 DEBUG[2210]: Hanging up channel 'SIP/1337-71b6'
Nov 23 11:17:33 DEBUG[2210]: sip_hangup(SIP/1337-71b6)
Nov 23 11:17:33 DEBUG[2210]: update_user_counter(1337) - decrement inUse counter
Nov 23 11:18:19 DEBUG[2210]: Manager received command 'Command'
Nov 23 11:18:19 DEBUG[2210]: Manager received command 'Command'