Delay occurs at Nov 3 14:47:48
Nov 3 14:47:37 DEBUG[10521] chan_sip.c: Setting NAT on RTP to 524288
Nov 3 14:47:37 DEBUG[10521] chan_sip.c: Stopping retransmission on '02d1b3160fd10b67051628ac11193f74@172.17.170.151' of Request 102: Match Found
Nov 3 14:47:37 DEBUG[10521] chan_sip.c: Stopping retransmission on 'MjZkMDk3Yjc0MmVjMzU3Y2VkNTE0YjQ3ZDE4Y2U3ZmQ.' of Response 1: Match Found
Nov 3 14:47:37 DEBUG[10521] chan_sip.c: Setting NAT on RTP to 524288
Nov 3 14:47:37 DEBUG[10521] chan_sip.c: Checking SIP call limits for device 101
Nov 3 14:47:37 DEBUG[10521] chan_sip.c: build_route: Contact hop: <sip:101@172.17.170.203:50085>
Nov 3 14:47:37 DEBUG[10509] channel.c: Avoiding initial deadlock for 'SIP/101-09a78608'
Nov 3 14:47:37 VERBOSE[10846] logger.c: -- Executing Goto("SIP/101-09a78608", "from-pstn|s|1") in new stack
Nov 3 14:47:37 VERBOSE[10846] logger.c: -- Goto (from-pstn,s,1)
Nov 3 14:47:37 VERBOSE[10846] logger.c: -- Executing Set("SIP/101-09a78608", "FROM_DID=s") in new stack
Nov 3 14:47:37 VERBOSE[10846] logger.c: -- Executing Goto("SIP/101-09a78608", "ivr-2|s|1") in new stack
Nov 3 14:47:37 VERBOSE[10846] logger.c: -- Goto (ivr-2,s,1)
Nov 3 14:47:37 VERBOSE[10846] logger.c: -- Executing Set("SIP/101-09a78608", "LOOPCOUNT=0") in new stack
Nov 3 14:47:37 VERBOSE[10846] logger.c: -- Executing Set("SIP/101-09a78608", "__DIR-CONTEXT=") in new stack
Nov 3 14:47:37 VERBOSE[10846] logger.c: -- Executing Answer("SIP/101-09a78608", "") in new stack
Nov 3 14:47:37 VERBOSE[10846] logger.c: -- Executing Wait("SIP/101-09a78608", "1") in new stack
Nov 3 14:47:38 DEBUG[10521] chan_sip.c: Stopping retransmission on 'MjZkMDk3Yjc0MmVjMzU3Y2VkNTE0YjQ3ZDE4Y2U3ZmQ.' of Response 2: Match Found
Nov 3 14:47:38 VERBOSE[10846] logger.c: -- Executing Set("SIP/101-09a78608", "TIMEOUT(digit)=3") in new stack
Nov 3 14:47:38 VERBOSE[10846] logger.c: -- Digit timeout set to 3
Nov 3 14:47:38 VERBOSE[10846] logger.c: -- Executing Set("SIP/101-09a78608", "TIMEOUT(response)=1") in new stack
Nov 3 14:47:38 VERBOSE[10846] logger.c: -- Response timeout set to 1
Nov 3 14:47:38 VERBOSE[10846] logger.c: -- Executing BackGround("SIP/101-09a78608", "custom/my-mainmenu") in new stack
Nov 3 14:47:38 DEBUG[10846] channel.c: Scheduling timer at 160 sample intervals
Nov 3 14:47:38 VERBOSE[10846] logger.c: -- Playing 'custom/my-mainmenu' (language 'en')
Nov 3 14:47:48 DEBUG[10846] channel.c: Scheduling timer at 0 sample intervals
Nov 3 14:47:48 DEBUG[10846] pbx.c: Oooh, got something to jump out with ('1')!
Nov 3 14:47:52 VERBOSE[10846] logger.c: == CDR updated on SIP/101-09a78608
Nov 3 14:47:52 VERBOSE[10846] logger.c: -- Executing Goto("SIP/101-09a78608", "custom-ext-queues2|20|1") in new stack
Nov 3 14:47:52 VERBOSE[10846] logger.c: -- Goto (custom-ext-queues2,20,1)
Nov 3 14:47:52 VERBOSE[10846] logger.c: -- Executing Playback("SIP/101-09a78608", "custom/please-wait") in new stack
Nov 3 14:47:52 DEBUG[10846] channel.c: Scheduling timer at 160 sample intervals
Nov 3 14:47:52 VERBOSE[10846] logger.c: -- Playing 'custom/please-wait' (language 'en')
Nov 3 14:47:54 DEBUG[10846] channel.c: Scheduling timer at 60 sample intervals
Nov 3 14:47:54 DEBUG[10846] channel.c: Scheduling timer at 0 sample intervals
Nov 3 14:47:54 DEBUG[10846] channel.c: Scheduling timer at 0 sample intervals
Nov 3 14:47:54 DEBUG[10846] pbx.c: Function result is 'NO'
Nov 3 14:47:54 VERBOSE[10846] logger.c: -- Executing Set("SIP/101-09a78608", "OFFICECLOSED=NO") in new stack
Nov 3 14:47:54 DEBUG[10846] pbx.c: Expression result is '0'
Nov 3 14:47:54 VERBOSE[10846] logger.c: -- Executing GotoIf("SIP/101-09a78608", "0?10") in new stack
Nov 3 14:47:54 DEBUG[10846] pbx.c: Not taking any branch
Nov 3 14:47:54 VERBOSE[10846] logger.c: -- Executing Goto("SIP/101-09a78608", "ext-queues|20|1") in new stack
Nov 3 14:47:54 VERBOSE[10846] logger.c: -- Goto (ext-queues,20,1)
Nov 3 14:47:54 VERBOSE[10846] logger.c: -- Executing Answer("SIP/101-09a78608", "") in new stack
Nov 3 14:47:54 DEBUG[10846] pbx.c: Expression result is '0'
Nov 3 14:47:54 VERBOSE[10846] logger.c: -- Executing GotoIf("SIP/101-09a78608", "0?USERCID:SETCID") in new stack
Nov 3 14:47:54 VERBOSE[10846] logger.c: -- Goto (ext-queues,20,4)
Nov 3 14:47:54 VERBOSE[10846] logger.c: -- Executing Set("SIP/101-09a78608", "CALLERID(name)=101") in new stack
Nov 3 14:47:54 VERBOSE[10846] logger.c: -- Executing Set("SIP/101-09a78608", "MONITOR_FILENAME=/var/spool/asterisk/monitor/q20-20061103-144754-1162525657.27") in new stack
Nov 3 14:47:54 VERBOSE[10846] logger.c: -- Executing Queue("SIP/101-09a78608", "20|t||custom/announce-enquiries") in new stack
Nov 3 14:47:54 VERBOSE[10846] logger.c: -- Started music on hold, class 'default', on SIP/101-09a78608
Nov 3 14:47:54 DEBUG[10846] channel.c: Scheduling timer at 160 sample intervals
Nov 3 14:47:54 VERBOSE[10846] logger.c: -- Called Local/100@from-internal/n
Nov 3 14:47:54 VERBOSE[10850] logger.c: -- Executing Macro("Local/100@from-internal-b3b7,2", "exten-vm|100|100") in new stack
Nov 3 14:47:54 VERBOSE[10850] logger.c: -- Executing Macro("Local/100@from-internal-b3b7,2", "user-callerid") in new stack
Nov 3 14:47:54 DEBUG[10850] pbx.c: Expression result is '1'
Nov 3 14:47:54 VERBOSE[10850] logger.c: -- Executing GotoIf("Local/100@from-internal-b3b7,2", "1?report") in new stack
Nov 3 14:47:54 VERBOSE[10850] logger.c: -- Goto (macro-user-callerid,s,9)
Nov 3 14:47:54 DEBUG[10850] pbx.c: Function result is '"101" <101>'
Nov 3 14:47:54 VERBOSE[10850] logger.c: -- Executing NoOp("Local/100@from-internal-b3b7,2", "Using CallerID "101" <101>") in new stack
Nov 3 14:47:54 VERBOSE[10850] logger.c: -- Executing Set("Local/100@from-internal-b3b7,2", "FROMCONTEXT=exten-vm") in new stack
Nov 3 14:47:54 VERBOSE[10850] logger.c: -- Executing Set("Local/100@from-internal-b3b7,2", "VMBOX=100") in new stack
Nov 3 14:47:54 VERBOSE[10850] logger.c: -- Executing Set("Local/100@from-internal-b3b7,2", "EXTTOCALL=100") in new stack
Nov 3 14:47:54 DEBUG[10850] db.c: Unable to find key '100' in family 'CFU'
Nov 3 14:47:54 DEBUG[10850] func_db.c: DB: CFU/100 not found in database.
Nov 3 14:47:54 DEBUG[10850] pbx.c: Function result is ''
Nov 3 14:47:54 VERBOSE[10850] logger.c: -- Executing Set("Local/100@from-internal-b3b7,2", "CFUEXT=") in new stack
Nov 3 14:47:54 DEBUG[10850] pbx.c: Expression result is '1'
Nov 3 14:47:54 DEBUG[10850] pbx.c: Expression result is '0'
Nov 3 14:47:54 DEBUG[10850] pbx.c: Expression result is '1'
Nov 3 14:47:54 DEBUG[10850] pbx.c: Function result is '15'
Nov 3 14:47:54 VERBOSE[10850] logger.c: -- Executing Set("Local/100@from-internal-b3b7,2", "RT=15") in new stack
Nov 3 14:47:54 VERBOSE[10850] logger.c: -- Executing Macro("Local/100@from-internal-b3b7,2", "record-enable|100|IN") in new stack
Nov 3 14:47:54 DEBUG[10850] pbx.c: Function result is '0'
Nov 3 14:47:54 VERBOSE[10850] logger.c: -- Executing GotoIf("Local/100@from-internal-b3b7,2", "0 > 0?2:4") in new stack
Nov 3 14:47:54 VERBOSE[10850] logger.c: -- Goto (macro-record-enable,s,4)
Nov 3 14:47:54 VERBOSE[10850] logger.c: -- Executing AGI("Local/100@from-internal-b3b7,2", "recordingcheck|20061103-144754|1162525674.29") in new stack
Nov 3 14:47:54 VERBOSE[10850] logger.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/recordingcheck
Nov 3 14:47:54 DEBUG[10846] channel.c: Generator got voice, switching to phase locked mode
Nov 3 14:47:54 DEBUG[10846] channel.c: Scheduling timer at 0 sample intervals
Nov 3 14:47:54 VERBOSE[10850] logger.c: recordingcheck|20061103-144754|1162525674.29: Inbound recording not enabled
Nov 3 14:47:54 VERBOSE[10850] logger.c: -- AGI Script recordingcheck completed, returning 0
Nov 3 14:47:54 VERBOSE[10850] logger.c: -- Executing NoOp("Local/100@from-internal-b3b7,2", "No recording needed") in new stack
Nov 3 14:47:54 DEBUG[10850] pbx.c: Expression result is '1'
Nov 3 14:47:54 VERBOSE[10850] logger.c: -- Executing GotoIf("Local/100@from-internal-b3b7,2", "1?dolocaldial|1") in new stack
Nov 3 14:47:54 VERBOSE[10850] logger.c: -- Goto (macro-exten-vm,dolocaldial,1)
Nov 3 14:47:54 VERBOSE[10850] logger.c: -- Executing Macro("Local/100@from-internal-b3b7,2", "dial||tr|100") in new stack
Nov 3 14:47:54 VERBOSE[10850] logger.c: -- Executing AGI("Local/100@from-internal-b3b7,2", "dialparties.agi") in new stack
Nov 3 14:47:54 VERBOSE[10850] logger.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/dialparties.agi
Nov 3 14:47:54 VERBOSE[10850] logger.c: dialparties.agi: Starting New Dialparties.agi
Nov 3 14:47:54 VERBOSE[10850] logger.c: -- dialparties.agi: priority is 1
Nov 3 14:47:54 VERBOSE[10850] logger.c: dialparties.agi: Caller ID name is '101' number is '101'
Nov 3 14:47:54 VERBOSE[10850] logger.c: dialparties.agi: Methodology of ring is 'none'
Nov 3 14:47:54 VERBOSE[10850] logger.c: -- dialparties.agi: Added extension 100 to extension map
Nov 3 14:47:54 DEBUG[10850] db.c: Unable to find key '100' in family 'CF'
Nov 3 14:47:54 VERBOSE[10850] logger.c: -- dialparties.agi: Extension 100 cf is disabled
Nov 3 14:47:54 DEBUG[10850] db.c: Unable to find key '100' in family 'DND'
Nov 3 14:47:54 VERBOSE[10850] logger.c: -- dialparties.agi: Extension 100 do not disturb is disabled
Nov 3 14:47:54 DEBUG[10850] db.c: Unable to find key '100' in family 'CFB'
Nov 3 14:47:54 DEBUG[10850] db.c: Unable to find key '100' in family 'CFU'
Nov 3 14:47:54 VERBOSE[10850] logger.c: > dialparties.agi: extnum: 100
Nov 3 14:47:54 VERBOSE[10850] logger.c: > dialparties.agi: exthascw: 1
Nov 3 14:47:54 VERBOSE[10850] logger.c: > dialparties.agi: exthascfb: 0
Nov 3 14:47:54 VERBOSE[10850] logger.c: > dialparties.agi: extcfb:
Nov 3 14:47:55 VERBOSE[10850] logger.c: > dialparties.agi: exthascfu: 0
Nov 3 14:47:55 VERBOSE[10850] logger.c: > dialparties.agi: extcfu:
Nov 3 14:47:55 VERBOSE[10850] logger.c: -- dialparties.agi: DbSet CALLTRACE/100 to 101
Nov 3 14:47:55 VERBOSE[10850] logger.c: -- AGI Script dialparties.agi completed, returning 0
Nov 3 14:47:55 VERBOSE[10850] logger.c: -- Executing Dial("Local/100@from-internal-b3b7,2", "SIP/100||tr") in new stack
Nov 3 14:47:55 DEBUG[10850] chan_sip.c: Setting NAT on RTP to 524288
Nov 3 14:47:55 DEBUG[10850] chan_sip.c: Outgoing Call for 100
Nov 3 14:47:55 VERBOSE[10850] logger.c: -- Called 100
Nov 3 14:47:55 VERBOSE[10846] logger.c: -- Local/100@from-internal-b3b7,1 is ringing
Nov 3 14:47:55 DEBUG[10521] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '1b7d732b54f954657ee476f90ee2b963@172.17.170.151' Request 102: Found
Nov 3 14:47:55 DEBUG[10521] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '1b7d732b54f954657ee476f90ee2b963@172.17.170.151' Request 102: Found
Nov 3 14:47:55 VERBOSE[10850] logger.c: -- SIP/100-09aa5e38 is ringing
Nov 3 14:47:55 VERBOSE[10846] logger.c: -- Stopped music on hold on SIP/101-09a78608
Nov 3 14:47:55 DEBUG[10846] channel.c: Scheduling timer at 0 sample intervals
Nov 3 14:47:55 DEBUG[10850] chan_sip.c: update_call_counter(100) - decrement call limit counter
Nov 3 14:47:55 DEBUG[10850] chan_sip.c: Acked pending invite 102
Nov 3 14:47:55 DEBUG[10850] chan_sip.c: Stopping retransmission on '1b7d732b54f954657ee476f90ee2b963@172.17.170.151' of Request 102: Match Found
Nov 3 14:47:55 VERBOSE[10846] logger.c: == Spawn extension (ext-queues, 20, 6) exited non-zero on 'SIP/101-09a78608'
Nov 3 14:47:55 DEBUG[10850] app_dial.c: Exiting with DIALSTATUS=CANCEL.
Nov 3 14:47:55 VERBOSE[10850] logger.c: == Spawn extension (macro-dial, s, 10) exited non-zero on 'Local/100@from-internal-b3b7,2' in macro 'dial'
Nov 3 14:47:55 VERBOSE[10850] logger.c: == Spawn extension (macro-dial, s, 10) exited non-zero on 'Local/100@from-internal-b3b7,2' in macro 'exten-vm'
Nov 3 14:47:55 VERBOSE[10850] logger.c: == Spawn extension (macro-dial, s, 10) exited non-zero on 'Local/100@from-internal-b3b7,2'
Nov 3 14:47:55 DEBUG[10846] cdr_addon_mysql.c: cdr_mysql: inserting a CDR record.
Nov 3 14:47:55 DEBUG[10846] 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 ('2006-11-03 14:47:37','\"101\" <101>','101','20','ext-queues', 'SIP/101-09a78608','','Queue','20|t||custom/announce-enquiries',18,18,'ANSWERED',3,'')
Nov 3 14:47:55 DEBUG[10846] pbx.c: Function result is '"101" <101>'
Nov 3 14:47:55 DEBUG[10846] pbx.c: Function result is '101'
Nov 3 14:47:55 DEBUG[10846] pbx.c: Function result is '20'
Nov 3 14:47:55 DEBUG[10846] pbx.c: Function result is 'ext-queues'
Nov 3 14:47:55 DEBUG[10846] pbx.c: Function result is 'SIP/101-09a78608'
Nov 3 14:47:55 DEBUG[10846] pbx.c: Function result is '(null)'
Nov 3 14:47:55 DEBUG[10846] pbx.c: Function result is 'Queue'
Nov 3 14:47:55 DEBUG[10846] pbx.c: Function result is '20|t||custom/announce-enquiries'
Nov 3 14:47:55 DEBUG[10846] pbx.c: Function result is '2006-11-03 14:47:37'
Nov 3 14:47:55 DEBUG[10846] pbx.c: Function result is '2006-11-03 14:47:37'
Nov 3 14:47:55 DEBUG[10846] pbx.c: Function result is '2006-11-03 14:47:55'
Nov 3 14:47:55 DEBUG[10846] pbx.c: Function result is '18'
Nov 3 14:47:55 DEBUG[10846] pbx.c: Function result is '18'
Nov 3 14:47:55 DEBUG[10846] pbx.c: Function result is 'ANSWERED'
Nov 3 14:47:55 DEBUG[10846] pbx.c: Function result is 'DOCUMENTATION'
Nov 3 14:47:55 DEBUG[10846] pbx.c: Function result is '(null)'
Nov 3 14:47:55 DEBUG[10846] pbx.c: Function result is '1162525657.27'
Nov 3 14:47:55 DEBUG[10846] pbx.c: Function result is '(null)'
Nov 3 14:47:55 DEBUG[10846] chan_sip.c: update_call_counter(101) - decrement call limit counter
Nov 3 14:47:55 DEBUG[10850] cdr_addon_mysql.c: cdr_mysql: inserting a CDR record.
Nov 3 14:47:55 DEBUG[10850] 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 ('2006-11-03 14:47:54','\"101\" <101>','101','100','from-internal', 'Local/100@from-internal-b3b7,2','SIP/100-09aa5e38','Dial','SIP/100||tr',1,0,'NO ANSWER',3,'')
Nov 3 14:47:55 DEBUG[10850] pbx.c: Function result is '"101" <101>'
Nov 3 14:47:55 DEBUG[10850] pbx.c: Function result is '101'
Nov 3 14:47:55 DEBUG[10850] pbx.c: Function result is '100'
Nov 3 14:47:55 DEBUG[10850] pbx.c: Function result is 'from-internal'
Nov 3 14:47:55 DEBUG[10850] pbx.c: Function result is 'Local/100@from-internal-b3b7,2'
Nov 3 14:47:55 DEBUG[10850] pbx.c: Function result is 'SIP/100-09aa5e38'
Nov 3 14:47:55 DEBUG[10850] pbx.c: Function result is 'Dial'
Nov 3 14:47:55 DEBUG[10850] pbx.c: Function result is 'SIP/100||tr'
Nov 3 14:47:55 DEBUG[10850] pbx.c: Function result is '2006-11-03 14:47:54'
Nov 3 14:47:55 DEBUG[10850] pbx.c: Function result is '(null)'
Nov 3 14:47:55 DEBUG[10850] pbx.c: Function result is '2006-11-03 14:47:55'
Nov 3 14:47:55 DEBUG[10850] pbx.c: Function result is '1'
Nov 3 14:47:55 DEBUG[10850] pbx.c: Function result is '0'
Nov 3 14:47:55 DEBUG[10850] pbx.c: Function result is 'NO ANSWER'
Nov 3 14:47:55 DEBUG[10850] pbx.c: Function result is 'DOCUMENTATION'
Nov 3 14:47:55 DEBUG[10850] pbx.c: Function result is '(null)'
Nov 3 14:47:55 DEBUG[10850] pbx.c: Function result is '1162525674.29'
Nov 3 14:47:55 DEBUG[10850] pbx.c: Function result is '(null)'
Nov 3 14:47:55 DEBUG[10521] chan_sip.c: Stopping retransmission on '1b7d732b54f954657ee476f90ee2b963@172.17.170.151' of Request 102: Match Found
Nov 3 14:47:55 DEBUG[10521] chan_sip.c: Stopping retransmission on '1b7d732b54f954657ee476f90ee2b963@172.17.170.151' of Request 102: Match Not Found