Oct 8 15:55:51 VERBOSE[11513] logger.c: -- Attempting call on Zap/47/18193593403 for s@oplus_recrue_f:1 (Retry 1) Oct 8 15:55:51 VERBOSE[11513] logger.c: -- Requested transfer capability: 0x00 - SPEECH Oct 8 15:55:51 VERBOSE[11513] logger.c: [Span 0 D-Channel 0] > [ 00 01 92 94 08 02 0c 3b 05 04 03 80 90 a2 18 04 e9 81 83 97 1e 02 80 83 28 0c b1 31 38 31 39 33 35 39 33 34 30 33 6c 0c 21 81 38 30 30 39 39 39 39 39 39 39 70 0c a1 31 38 31 39 33 35 39 33 34 30 33 ] Oct 8 15:55:51 VERBOSE[11513] logger.c: [Span 0 D-Channel 0] > Informational frame: Oct 8 15:55:51 VERBOSE[11513] logger.c: [Span 0 D-Channel 0]> SAPI: 00 C/R: 0 EA: 0 > TEI: 000 EA: 1 Oct 8 15:55:51 VERBOSE[11513] logger.c: [Span 0 D-Channel 0]> N(S): 073 0: 0 > N(R): 074 P: 0 > 62 bytes of data Oct 8 15:55:51 VERBOSE[11513] logger.c: [Span 0 D-Channel 0]-- Restarting T203 counter Oct 8 15:55:51 VERBOSE[11513] logger.c: [Span 0 D-Channel 0]Stopping T_203 timer Oct 8 15:55:51 VERBOSE[11513] logger.c: [Span 0 D-Channel 0]Starting T_200 timer Oct 8 15:55:51 VERBOSE[11513] logger.c: [Span 0 D-Channel 0]> Protocol Discriminator: Q.931 (8) len=62 Oct 8 15:55:51 VERBOSE[11513] logger.c: [Span 0 D-Channel 0]> Call Ref: len= 2 (reference 3131/0xC3B) (Originator) Oct 8 15:55:51 VERBOSE[11513] logger.c: [Span 0 D-Channel 0]> Message type: SETUP (5) Oct 8 15:55:51 VERBOSE[11513] logger.c: > [ Oct 8 15:55:51 VERBOSE[11513] logger.c: > [04 Oct 8 15:55:51 VERBOSE[11513] logger.c: > [04 03 Oct 8 15:55:51 VERBOSE[11513] logger.c: > [04 03 80 Oct 8 15:55:51 VERBOSE[11513] logger.c: > [04 03 80 90 Oct 8 15:55:51 VERBOSE[11513] logger.c: > [04 03 80 90 a2 Oct 8 15:55:51 VERBOSE[11513] logger.c: > [04 03 80 90 a2] Oct 8 15:55:51 VERBOSE[11513] logger.c: [Span 0 D-Channel 0]> Bearer Capability (len= 5) [ Ext: 1 Q.931 Std: 0 Info transfer capability: Speech (0) Oct 8 15:55:51 VERBOSE[11513] logger.c: [Span 0 D-Channel 0]> Ext: 1 Trans mode/rate: 64kbps, circuit-mode (16) Oct 8 15:55:51 VERBOSE[11513] logger.c: [Span 0 D-Channel 0]> Ext: 1 User information layer 1: u-Law (34) Oct 8 15:55:51 VERBOSE[11513] logger.c: > [ Oct 8 15:55:51 VERBOSE[11513] logger.c: > [18 Oct 8 15:55:51 VERBOSE[11513] logger.c: > [18 04 Oct 8 15:55:51 VERBOSE[11513] logger.c: > [18 04 e9 Oct 8 15:55:51 VERBOSE[11513] logger.c: > [18 04 e9 81 Oct 8 15:55:51 VERBOSE[11513] logger.c: > [18 04 e9 81 83 Oct 8 15:55:51 VERBOSE[11513] logger.c: > [18 04 e9 81 83 97 Oct 8 15:55:51 VERBOSE[11513] logger.c: > [18 04 e9 81 83 97] Oct 8 15:55:51 VERBOSE[11513] logger.c: [Span 0 D-Channel 0]> Channel ID (len= 6) [ Ext: 1 IntID: Explicit, PRI Spare: 0, Exclusive Dchan: 0 Oct 8 15:55:51 VERBOSE[11513] logger.c: [Span 0 D-Channel 0]> ChanSel: Reserved Oct 8 15:55:51 VERBOSE[11513] logger.c: [Span 0 D-Channel 0]> Ext: 1 DS1 Identifier: 1 Oct 8 15:55:51 VERBOSE[11513] logger.c: [Span 0 D-Channel 0]> Ext: 1 Coding: 0 Number Specified Channel Type: 3 Oct 8 15:55:51 VERBOSE[11513] logger.c: [Span 0 D-Channel 0]> Ext: 1 Channel: 23 ] Oct 8 15:55:51 VERBOSE[11513] logger.c: > [ Oct 8 15:55:51 VERBOSE[11513] logger.c: > [1e Oct 8 15:55:51 VERBOSE[11513] logger.c: > [1e 02 Oct 8 15:55:51 VERBOSE[11513] logger.c: > [1e 02 80 Oct 8 15:55:51 VERBOSE[11513] logger.c: > [1e 02 80 83 Oct 8 15:55:51 VERBOSE[11513] logger.c: > [1e 02 80 83] Oct 8 15:55:51 VERBOSE[11513] logger.c: [Span 0 D-Channel 0]> Progress Indicator (len= 4) [ Ext: 1 Coding: CCITT (ITU) standard (0) 0: 0 Location: User (0) Oct 8 15:55:51 VERBOSE[11513] logger.c: [Span 0 D-Channel 0]> Ext: 1 Progress Description: Calling equipment is non-ISDN. (3) ] Oct 8 15:55:51 VERBOSE[11513] logger.c: > [ Oct 8 15:55:51 VERBOSE[11513] logger.c: > [28 Oct 8 15:55:51 VERBOSE[11513] logger.c: > [28 0c Oct 8 15:55:51 VERBOSE[11513] logger.c: > [28 0c b1 Oct 8 15:55:51 VERBOSE[11513] logger.c: > [28 0c b1 31 Oct 8 15:55:51 VERBOSE[11513] logger.c: > [28 0c b1 31 38 Oct 8 15:55:51 VERBOSE[11513] logger.c: > [28 0c b1 31 38 31 Oct 8 15:55:51 VERBOSE[11513] logger.c: > [28 0c b1 31 38 31 39 Oct 8 15:55:51 VERBOSE[11513] logger.c: > [28 0c b1 31 38 31 39 33 Oct 8 15:55:51 VERBOSE[11513] logger.c: > [28 0c b1 31 38 31 39 33 35 Oct 8 15:55:51 VERBOSE[11513] logger.c: > [28 0c b1 31 38 31 39 33 35 39 Oct 8 15:55:51 VERBOSE[11513] logger.c: > [28 0c b1 31 38 31 39 33 35 39 33 Oct 8 15:55:51 VERBOSE[11513] logger.c: > [28 0c b1 31 38 31 39 33 35 39 33 34 Oct 8 15:55:51 VERBOSE[11513] logger.c: > [28 0c b1 31 38 31 39 33 35 39 33 34 30 Oct 8 15:55:51 VERBOSE[11513] logger.c: > [28 0c b1 31 38 31 39 33 35 39 33 34 30 33 Oct 8 15:55:51 VERBOSE[11513] logger.c: > [28 0c b1 31 38 31 39 33 35 39 33 34 30 33] Oct 8 15:55:51 VERBOSE[11513] logger.c: [Span 0 D-Channel 0]> Display (len=12) Charset: 31 [ 18193593403 ] Oct 8 15:55:51 VERBOSE[11513] logger.c: > [ Oct 8 15:55:51 VERBOSE[11513] logger.c: > [6c Oct 8 15:55:51 VERBOSE[11513] logger.c: > [6c 0c Oct 8 15:55:51 VERBOSE[11513] logger.c: > [6c 0c 21 Oct 8 15:55:51 VERBOSE[11513] logger.c: > [6c 0c 21 81 Oct 8 15:55:51 VERBOSE[11513] logger.c: > [6c 0c 21 81 38 Oct 8 15:55:51 VERBOSE[11513] logger.c: > [6c 0c 21 81 38 30 Oct 8 15:55:51 VERBOSE[11513] logger.c: > [6c 0c 21 81 38 30 30 Oct 8 15:55:51 VERBOSE[11513] logger.c: > [6c 0c 21 81 38 30 30 39 Oct 8 15:55:51 VERBOSE[11513] logger.c: > [6c 0c 21 81 38 30 30 39 39 Oct 8 15:55:51 VERBOSE[11513] logger.c: > [6c 0c 21 81 38 30 30 39 39 39 Oct 8 15:55:51 VERBOSE[11513] logger.c: > [6c 0c 21 81 38 30 30 39 39 39 39 Oct 8 15:55:51 VERBOSE[11513] logger.c: > [6c 0c 21 81 38 30 30 39 39 39 39 39 Oct 8 15:55:51 VERBOSE[11513] logger.c: > [6c 0c 21 81 38 30 30 39 39 39 39 39 39 Oct 8 15:55:51 VERBOSE[11513] logger.c: > [6c 0c 21 81 38 30 30 39 39 39 39 39 39 39 Oct 8 15:55:51 VERBOSE[11513] logger.c: > [6c 0c 21 81 38 30 30 39 39 39 39 39 39 39] Oct 8 15:55:51 VERBOSE[11513] logger.c: [Span 0 D-Channel 0]> Calling Number (len=14) [ Ext: 0 TON: National Number (2) NPI: ISDN/Telephony Numbering Plan (E.164/E.163) (1) Oct 8 15:55:51 VERBOSE[11513] logger.c: [Span 0 D-Channel 0]> Presentation: Presentation permitted, user number passed network screening (1) '8009999999' ] Oct 8 15:55:51 VERBOSE[11513] logger.c: > [ Oct 8 15:55:51 VERBOSE[11513] logger.c: > [70 Oct 8 15:55:51 VERBOSE[11513] logger.c: > [70 0c Oct 8 15:55:51 VERBOSE[11513] logger.c: > [70 0c a1 Oct 8 15:55:51 VERBOSE[11513] logger.c: > [70 0c a1 31 Oct 8 15:55:51 VERBOSE[11513] logger.c: > [70 0c a1 31 38 Oct 8 15:55:51 VERBOSE[11513] logger.c: > [70 0c a1 31 38 31 Oct 8 15:55:51 VERBOSE[11513] logger.c: > [70 0c a1 31 38 31 39 Oct 8 15:55:51 VERBOSE[11513] logger.c: > [70 0c a1 31 38 31 39 33 Oct 8 15:55:51 VERBOSE[11513] logger.c: > [70 0c a1 31 38 31 39 33 35 Oct 8 15:55:51 VERBOSE[11513] logger.c: > [70 0c a1 31 38 31 39 33 35 39 Oct 8 15:55:51 VERBOSE[11513] logger.c: > [70 0c a1 31 38 31 39 33 35 39 33 Oct 8 15:55:51 VERBOSE[11513] logger.c: > [70 0c a1 31 38 31 39 33 35 39 33 34 Oct 8 15:55:51 VERBOSE[11513] logger.c: > [70 0c a1 31 38 31 39 33 35 39 33 34 30 Oct 8 15:55:51 VERBOSE[11513] logger.c: > [70 0c a1 31 38 31 39 33 35 39 33 34 30 33 Oct 8 15:55:51 VERBOSE[11513] logger.c: > [70 0c a1 31 38 31 39 33 35 39 33 34 30 33] Oct 8 15:55:51 VERBOSE[11513] logger.c: [Span 0 D-Channel 0]> Called Number (len=14) [ Ext: 1 TON: National Number (2) NPI: ISDN/Telephony Numbering Plan (E.164/E.163) (1) '18193593403' ] Oct 8 15:55:51 DEBUG[2186] channel.c: Avoiding initial deadlock for 'Zap/47-1' Oct 8 15:55:51 DEBUG[2186] channel.c: Avoiding initial deadlock for 'Zap/47-1' Oct 8 15:55:51 VERBOSE[11514] logger.c: -- Attempting call on Zap/47/4504738041 for s@oplus_recrue_f:1 (Retry 1) Oct 8 15:55:51 NOTICE[11514] channel.c: Unable to request channel Zap/47/4504738041 Oct 8 15:55:51 DEBUG[11514] cdr_addon_mysql.c: cdr_mysql: inserting a CDR record. Oct 8 15:55:51 DEBUG[11514] 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-10-08 15:55:51','','','s','default', '**Unknown**','','','',0,0,'FAILED',3,'') Oct 8 15:55:51 VERBOSE[11514] logger.c: -- Executing Set("OutgoingSpoolFailed", "CODE=-1") in new stack Oct 8 15:55:51 VERBOSE[2195] logger.c: [Span 0 D-Channel 0] < [ 00 01 01 94 ] Oct 8 15:55:51 VERBOSE[2195] logger.c: [Span 0 D-Channel 0] < Supervisory frame: Oct 8 15:55:51 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]< SAPI: 00 C/R: 0 EA: 0 < TEI: 000 EA: 1 Oct 8 15:55:51 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]< Zero: 0 S: 0 01: 1 [ RR (receive ready) ] < N(R): 074 P/F: 0 < 0 bytes of data Oct 8 15:55:51 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]-- ACKing all packets from 72 to (but not including) 74 Oct 8 15:55:51 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]-- ACKing packet 73, new txqueue is -1 (-1 means empty) Oct 8 15:55:51 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]-- Since there was nothing left, stopping T200 counter Oct 8 15:55:51 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]-- Nothing left, starting T203 counter Oct 8 15:55:51 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]-- Restarting T203 counter Oct 8 15:55:51 DEBUG[11514] pbx.c: Expression result is '1' Oct 8 15:55:51 DEBUG[11514] pbx.c: Function result is 'RBTno_service' Oct 8 15:55:51 VERBOSE[11514] logger.c: -- Executing Set("OutgoingSpoolFailed", "CODE=RBTno_service") in new stack Oct 8 15:55:51 DEBUG[11514] pbx.c: Expression result is '0' Oct 8 15:55:51 DEBUG[11514] pbx.c: Function result is 'RBTno_service' Oct 8 15:55:51 VERBOSE[11514] logger.c: -- Executing Set("OutgoingSpoolFailed", "CODE=RBTno_service") in new stack Oct 8 15:55:51 DEBUG[11514] pbx.c: Expression result is '0' Oct 8 15:55:51 DEBUG[11514] pbx.c: Function result is 'RBTno_service' Oct 8 15:55:51 VERBOSE[11514] logger.c: -- Executing Set("OutgoingSpoolFailed", "CODE=RBTno_service") in new stack Oct 8 15:55:51 DEBUG[11514] pbx.c: Expression result is '0' Oct 8 15:55:51 DEBUG[11514] pbx.c: Function result is 'RBTno_service' Oct 8 15:55:51 VERBOSE[11514] logger.c: -- Executing Set("OutgoingSpoolFailed", "CODE=RBTno_service") in new stack Oct 8 15:55:51 DEBUG[11514] pbx.c: Expression result is '0' Oct 8 15:55:51 DEBUG[11514] pbx.c: Function result is 'RBTno_service' Oct 8 15:55:51 VERBOSE[11514] logger.c: -- Executing Set("OutgoingSpoolFailed", "CODE=RBTno_service") in new stack Oct 8 15:55:51 VERBOSE[2195] logger.c: [Span 0 D-Channel 0] < [ 02 01 94 94 08 02 8c 3b 02 18 04 e9 81 83 97 ] Oct 8 15:55:51 VERBOSE[2195] logger.c: [Span 0 D-Channel 0] < Informational frame: Oct 8 15:55:51 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]< SAPI: 00 C/R: 1 EA: 0 < TEI: 000 EA: 1 Oct 8 15:55:51 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]< N(S): 074 0: 0 < N(R): 074 P: 0 < 11 bytes of data Oct 8 15:55:51 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]-- ACKing all packets from 73 to (but not including) 74 Oct 8 15:55:51 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]-- Since there was nothing left, stopping T200 counter Oct 8 15:55:51 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]-- Stopping T203 counter since we got an ACK Oct 8 15:55:51 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]-- Nothing left, starting T203 counter Oct 8 15:55:51 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]< Protocol Discriminator: Q.931 (8) len=11 Oct 8 15:55:51 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]< Call Ref: len= 2 (reference 3131/0xC3B) (Terminator) Oct 8 15:55:51 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]< Message type: CALL PROCEEDING (2) Oct 8 15:55:51 VERBOSE[2195] logger.c: < [Oct 8 15:55:51 VERBOSE[2195] logger.c: < [18Oct 8 15:55:51 VERBOSE[2195] logger.c: < [18 04Oct 8 15:55:51 VERBOSE[2195] logger.c: < [18 04 e9Oct 8 15:55:51 VERBOSE[2195] logger.c: < [18 04 e9 81Oct 8 15:55:51 VERBOSE[2195] logger.c: < [18 04 e9 81 83Oct 8 15:55:51 VERBOSE[2195] logger.c: < [18 04 e9 81 83 97Oct 8 15:55:51 VERBOSE[2195] logger.c: < [18 04 e9 81 83 97] Oct 8 15:55:51 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]< Channel ID (len= 6) [ Ext: 1 IntID: Explicit, PRI Spare: 0, Exclusive Dchan: 0 Oct 8 15:55:51 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]< ChanSel: Reserved Oct 8 15:55:51 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]< Ext: 1 DS1 Identifier: 1 Oct 8 15:55:51 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]< Ext: 1 Coding: 0 Number Specified Channel Type: 3 Oct 8 15:55:51 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]< Ext: 1 Channel: 23 ] Oct 8 15:55:51 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]Sending Receiver Ready (75) Oct 8 15:55:51 VERBOSE[2195] logger.c: [Span 0 D-Channel 0] > [ 02 01 01 96 ] Oct 8 15:55:51 VERBOSE[2195] logger.c: [Span 0 D-Channel 0] > Supervisory frame: Oct 8 15:55:51 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]> SAPI: 00 C/R: 1 EA: 0 > TEI: 000 EA: 1 Oct 8 15:55:51 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]> Zero: 0 S: 0 01: 1 [ RR (receive ready) ] > N(R): 075 P/F: 0 > 0 bytes of data Oct 8 15:55:51 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]-- Restarting T203 counter Oct 8 15:55:51 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]-- Restarting T203 counter Oct 8 15:55:51 DEBUG[2195] chan_zap.c: Queuing frame from PRI_EVENT_PROCEEDING on channel 1/23 span 1 Oct 8 15:55:51 DEBUG[11514] pbx.c: Expression result is '0' Oct 8 15:55:51 DEBUG[11514] pbx.c: Function result is 'RBTno_service' Oct 8 15:55:51 VERBOSE[11514] logger.c: -- Executing Set("OutgoingSpoolFailed", "CODE=RBTno_service") in new stack Oct 8 15:55:51 VERBOSE[11514] logger.c: -- Executing System("OutgoingSpoolFailed", "/usr/bin/cwASTstocke.pl IVRoprecrutement KYZ88692 ASTERISK47 1 "RBTno_service"") in new stack Oct 8 15:55:51 DEBUG[2416] manager.c: Manager received command 'Status' Oct 8 15:55:51 VERBOSE[11515] logger.c: -- Attempting call on Zap/47/5147695274 for s@oplus_recrue_f:1 (Retry 1) Oct 8 15:55:51 NOTICE[11515] channel.c: Unable to request channel Zap/47/5147695274 Oct 8 15:55:51 DEBUG[11515] cdr_addon_mysql.c: cdr_mysql: inserting a CDR record. Oct 8 15:55:51 DEBUG[11515] 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-10-08 15:55:51','','','s','default', '**Unknown**','','','',0,0,'FAILED',3,'') Oct 8 15:55:51 VERBOSE[11515] logger.c: -- Executing Set("OutgoingSpoolFailed", "CODE=-1") in new stack Oct 8 15:55:51 DEBUG[11515] pbx.c: Expression result is '1' Oct 8 15:55:51 DEBUG[11515] pbx.c: Function result is 'RBTno_service' Oct 8 15:55:51 VERBOSE[11515] logger.c: -- Executing Set("OutgoingSpoolFailed", "CODE=RBTno_service") in new stack Oct 8 15:55:51 DEBUG[11515] pbx.c: Expression result is '0' Oct 8 15:55:51 DEBUG[11515] pbx.c: Function result is 'RBTno_service' Oct 8 15:55:51 VERBOSE[11515] logger.c: -- Executing Set("OutgoingSpoolFailed", "CODE=RBTno_service") in new stack Oct 8 15:55:51 DEBUG[11515] pbx.c: Expression result is '0' Oct 8 15:55:51 DEBUG[11515] pbx.c: Function result is 'RBTno_service' Oct 8 15:55:51 VERBOSE[11515] logger.c: -- Executing Set("OutgoingSpoolFailed", "CODE=RBTno_service") in new stack Oct 8 15:55:51 DEBUG[11515] pbx.c: Expression result is '0' Oct 8 15:55:51 DEBUG[11515] pbx.c: Function result is 'RBTno_service' Oct 8 15:55:51 VERBOSE[11515] logger.c: -- Executing Set("OutgoingSpoolFailed", "CODE=RBTno_service") in new stack Oct 8 15:55:51 DEBUG[11515] pbx.c: Expression result is '0' Oct 8 15:55:51 DEBUG[11515] pbx.c: Function result is 'RBTno_service' Oct 8 15:55:51 VERBOSE[11515] logger.c: -- Executing Set("OutgoingSpoolFailed", "CODE=RBTno_service") in new stack Oct 8 15:55:51 DEBUG[11515] pbx.c: Expression result is '0' Oct 8 15:55:51 DEBUG[11515] pbx.c: Function result is 'RBTno_service' Oct 8 15:55:51 VERBOSE[11515] logger.c: -- Executing Set("OutgoingSpoolFailed", "CODE=RBTno_service") in new stack Oct 8 15:55:51 VERBOSE[11515] logger.c: -- Executing System("OutgoingSpoolFailed", "/usr/bin/cwASTstocke.pl IVRoprecrutement BJR63333 ASTERISK47 1 "RBTno_service"") in new stack Oct 8 15:55:51 NOTICE[11513] channel.c: Don't know what to do with control frame 15 Oct 8 15:55:52 DEBUG[2200] chan_sip.c: Auto destroying call '66de105c79a27da59e1fb7d1c8d875f6@192.168.1.33' Oct 8 15:55:52 VERBOSE[11515] logger.c: -- Executing Goto("OutgoingSpoolFailed", "oplus_recrue_f_hangup|s|1") in new stack Oct 8 15:55:52 VERBOSE[11515] logger.c: -- Goto (oplus_recrue_f_hangup,s,1) Oct 8 15:55:52 VERBOSE[11515] logger.c: -- Executing Hangup("OutgoingSpoolFailed", "") in new stack Oct 8 15:55:52 VERBOSE[11515] logger.c: == Spawn extension (oplus_recrue_f_hangup, s, 1) exited non-zero on 'OutgoingSpoolFailed' Oct 8 15:55:52 VERBOSE[11514] logger.c: -- Executing Goto("OutgoingSpoolFailed", "oplus_recrue_f_hangup|s|1") in new stack Oct 8 15:55:52 VERBOSE[11514] logger.c: -- Goto (oplus_recrue_f_hangup,s,1) Oct 8 15:55:52 VERBOSE[11514] logger.c: -- Executing Hangup("OutgoingSpoolFailed", "") in new stack Oct 8 15:55:52 VERBOSE[11514] logger.c: == Spawn extension (oplus_recrue_f_hangup, s, 1) exited non-zero on 'OutgoingSpoolFailed' Oct 8 15:55:52 DEBUG[11515] cdr_addon_mysql.c: cdr_mysql: inserting a CDR record. Oct 8 15:55:52 DEBUG[11515] 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-10-08 15:55:51','','','s','oplus_recrue_f_hangup', 'OutgoingSpoolFailed','','Hangup','',1,0,'NO ANSWER',3,'oprecrutement') Oct 8 15:55:52 NOTICE[11515] pbx_spool.c: Call failed to go through, reason 0 Oct 8 15:55:52 DEBUG[11514] cdr_addon_mysql.c: cdr_mysql: inserting a CDR record. Oct 8 15:55:52 DEBUG[11514] 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-10-08 15:55:51','','','s','oplus_recrue_f_hangup', 'OutgoingSpoolFailed','','Hangup','',1,0,'NO ANSWER',3,'oprecrutement') Oct 8 15:55:52 NOTICE[11514] pbx_spool.c: Call failed to go through, reason 0 Oct 8 15:55:52 WARNING[2193] pbx_spool.c: Unable to set utime on /var/spool/asterisk/outgoing/389735.call: Operation not permitted Oct 8 15:55:52 DEBUG[2193] pbx_spool.c: Delaying retry since we're currently running 'ض"ˆVAol/asterisk/outgoing/389735.call' Oct 8 15:55:52 DEBUG[2416] manager.c: Manager received command 'Status' Oct 8 15:55:52 VERBOSE[2195] logger.c: [Span 0 D-Channel 0] < [ 02 01 96 94 08 02 8c 3b 01 1e 02 84 88 ] Oct 8 15:55:52 VERBOSE[2195] logger.c: [Span 0 D-Channel 0] < Informational frame: Oct 8 15:55:52 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]< SAPI: 00 C/R: 1 EA: 0 < TEI: 000 EA: 1 Oct 8 15:55:52 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]< N(S): 075 0: 0 < N(R): 074 P: 0 < 9 bytes of data Oct 8 15:55:52 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]-- ACKing all packets from 73 to (but not including) 74 Oct 8 15:55:52 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]-- Since there was nothing left, stopping T200 counter Oct 8 15:55:52 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]-- Stopping T203 counter since we got an ACK Oct 8 15:55:52 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]-- Nothing left, starting T203 counter Oct 8 15:55:52 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]< Protocol Discriminator: Q.931 (8) len=9 Oct 8 15:55:52 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]< Call Ref: len= 2 (reference 3131/0xC3B) (Terminator) Oct 8 15:55:52 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]< Message type: ALERTING (1) Oct 8 15:55:52 VERBOSE[2195] logger.c: < [Oct 8 15:55:52 VERBOSE[2195] logger.c: < [1eOct 8 15:55:52 VERBOSE[2195] logger.c: < [1e 02Oct 8 15:55:52 VERBOSE[2195] logger.c: < [1e 02 84Oct 8 15:55:52 VERBOSE[2195] logger.c: < [1e 02 84 88Oct 8 15:55:52 VERBOSE[2195] logger.c: < [1e 02 84 88] Oct 8 15:55:52 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]< Progress Indicator (len= 4) [ Ext: 1 Coding: CCITT (ITU) standard (0) 0: 0 Location: Public network serving the remote user (4) Oct 8 15:55:52 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]< Ext: 1 Progress Description: Inband information or appropriate pattern now available. (8) ] Oct 8 15:55:52 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]Sending Receiver Ready (76) Oct 8 15:55:52 VERBOSE[2195] logger.c: [Span 0 D-Channel 0] > [ 02 01 01 98 ] Oct 8 15:55:52 VERBOSE[2195] logger.c: [Span 0 D-Channel 0] > Supervisory frame: Oct 8 15:55:52 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]> SAPI: 00 C/R: 1 EA: 0 > TEI: 000 EA: 1 Oct 8 15:55:52 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]> Zero: 0 S: 0 01: 1 [ RR (receive ready) ] > N(R): 076 P/F: 0 > 0 bytes of data Oct 8 15:55:52 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]-- Restarting T203 counter Oct 8 15:55:52 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]-- Restarting T203 counter Oct 8 15:55:52 DEBUG[2195] chan_zap.c: Enabled echo cancellation on channel 47 Oct 8 15:55:53 DEBUG[2200] chan_sip.c: Stopping retransmission on '4687c5fe3094204b7146fed722145687@192.168.1.100' of Request 102: Match Found Oct 8 15:55:53 DEBUG[2200] chan_sip.c: Stopping retransmission on '7d34a1e2051125b95ec358eb7a6d8a59@192.168.1.100' of Request 102: Match Found Oct 8 15:55:53 DEBUG[2200] chan_sip.c: Stopping retransmission on '4421dac735a1b7c2191909c01e740cce@192.168.1.100' of Request 102: Match Found Oct 8 15:55:53 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]T203 counter expired, sending RR and scheduling T203 again Oct 8 15:55:53 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]Sending Receiver Ready (76) Oct 8 15:55:53 VERBOSE[2195] logger.c: [Span 0 D-Channel 0] > [ 00 01 01 99 ] Oct 8 15:55:53 VERBOSE[2195] logger.c: [Span 0 D-Channel 0] > Supervisory frame: Oct 8 15:55:53 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]> SAPI: 00 C/R: 0 EA: 0 > TEI: 000 EA: 1 Oct 8 15:55:53 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]> Zero: 0 S: 0 01: 1 [ RR (receive ready) ] > N(R): 076 P/F: 1 > 0 bytes of data Oct 8 15:55:53 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]-- Restarting T203 counter Oct 8 15:55:53 VERBOSE[2195] logger.c: [Span 0 D-Channel 0] < [ 00 01 01 95 ] Oct 8 15:55:53 VERBOSE[2195] logger.c: [Span 0 D-Channel 0] < Supervisory frame: Oct 8 15:55:53 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]< SAPI: 00 C/R: 0 EA: 0 < TEI: 000 EA: 1 Oct 8 15:55:53 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]< Zero: 0 S: 0 01: 1 [ RR (receive ready) ] < N(R): 074 P/F: 1 < 0 bytes of data Oct 8 15:55:53 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]-- ACKing all packets from 73 to (but not including) 74 Oct 8 15:55:53 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]-- Since there was nothing left, stopping T200 counter Oct 8 15:55:53 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]-- Stopping T203 counter since we got an ACK Oct 8 15:55:53 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]-- Nothing left, starting T203 counter Oct 8 15:55:53 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]-- Got RR response to our frame Oct 8 15:55:53 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]-- Restarting T203 counter Oct 8 15:55:53 DEBUG[2416] manager.c: Manager received command 'Status' Oct 8 15:55:54 DEBUG[2200] chan_sip.c: Stopping retransmission on '3bf15f0d56071fb15b15ba9f4389b5b4@192.168.1.100' of Request 102: Match Found Oct 8 15:55:54 DEBUG[2416] manager.c: Manager received command 'Status' Oct 8 15:55:55 DEBUG[2200] chan_sip.c: Stopping retransmission on '7916ecd102ab73da7843e0017ef47424@192.168.1.100' of Request 102: Match Found Oct 8 15:55:55 DEBUG[2416] manager.c: Manager received command 'Status' Oct 8 15:55:56 DEBUG[2416] manager.c: Manager received command 'Status' Oct 8 15:55:57 DEBUG[2416] manager.c: Manager received command 'Status' Oct 8 15:55:57 DEBUG[2200] chan_sip.c: Auto destroying call '120f81445b7ec77d82ca481a3a011eb6@192.168.1.25' Oct 8 15:55:58 VERBOSE[2195] logger.c: [Span 0 D-Channel 1]T203 counter expired, sending RR and scheduling T203 again Oct 8 15:55:58 VERBOSE[2195] logger.c: [Span 0 D-Channel 1]Sending Receiver Ready (0) Oct 8 15:55:58 VERBOSE[2195] logger.c: [Span 0 D-Channel 1] > [ 00 01 01 01 ] Oct 8 15:55:58 VERBOSE[2195] logger.c: [Span 0 D-Channel 1] > Supervisory frame: Oct 8 15:55:58 VERBOSE[2195] logger.c: [Span 0 D-Channel 1]> SAPI: 00 C/R: 0 EA: 0 > TEI: 000 EA: 1 Oct 8 15:55:58 VERBOSE[2195] logger.c: [Span 0 D-Channel 1]> Zero: 0 S: 0 01: 1 [ RR (receive ready) ] > N(R): 000 P/F: 1 > 0 bytes of data Oct 8 15:55:58 VERBOSE[2195] logger.c: [Span 0 D-Channel 1]-- Restarting T203 counter Oct 8 15:55:58 VERBOSE[2195] logger.c: [Span 0 D-Channel 1] < [ 00 01 01 01 ] Oct 8 15:55:58 VERBOSE[2195] logger.c: [Span 0 D-Channel 1] < Supervisory frame: Oct 8 15:55:58 VERBOSE[2195] logger.c: [Span 0 D-Channel 1]< SAPI: 00 C/R: 0 EA: 0 < TEI: 000 EA: 1 Oct 8 15:55:58 VERBOSE[2195] logger.c: [Span 0 D-Channel 1]< Zero: 0 S: 0 01: 1 [ RR (receive ready) ] < N(R): 000 P/F: 1 < 0 bytes of data Oct 8 15:55:58 VERBOSE[2195] logger.c: [Span 0 D-Channel 1]-- ACKing all packets from 0 to (but not including) 0 Oct 8 15:55:58 VERBOSE[2195] logger.c: [Span 0 D-Channel 1]-- Since there was nothing left, stopping T200 counter Oct 8 15:55:58 VERBOSE[2195] logger.c: [Span 0 D-Channel 1]-- Stopping T203 counter since we got an ACK Oct 8 15:55:58 VERBOSE[2195] logger.c: [Span 0 D-Channel 1]-- Nothing left, starting T203 counter Oct 8 15:55:58 VERBOSE[2195] logger.c: [Span 0 D-Channel 1]-- Got RR response to our frame Oct 8 15:55:58 VERBOSE[2195] logger.c: [Span 0 D-Channel 1]-- Restarting T203 counter Oct 8 15:55:58 DEBUG[2416] manager.c: Manager received command 'Status' Oct 8 15:55:59 DEBUG[2200] chan_sip.c: Stopping retransmission on '7007201865a68a242eb6678a618a10fe@192.168.1.100' of Request 102: Match Found Oct 8 15:55:59 DEBUG[2200] chan_sip.c: Stopping retransmission on '25e10be356752c2e47bc2b0669d0818d@192.168.1.100' of Request 102: Match Found Oct 8 15:55:59 DEBUG[2200] chan_sip.c: Auto destroying call '54634ec5760a7c5c97a02e4cfa063b94@192.168.1.27' Oct 8 15:55:59 DEBUG[2200] chan_sip.c: Stopping retransmission on '12c1428717d268407695c12c71034b85@192.168.1.100' of Request 102: Match Found Oct 8 15:55:59 DEBUG[2200] chan_sip.c: Stopping retransmission on '0d6ecb13431082d55c298c957a9d9963@192.168.1.100' of Request 102: Match Found Oct 8 15:55:59 DEBUG[2200] chan_sip.c: Stopping retransmission on '5e0520f2340c40a30f21fb4252abb0f7@192.168.1.100' of Request 102: Match Found Oct 8 15:55:59 DEBUG[2416] manager.c: Manager received command 'Status' Oct 8 15:56:00 DEBUG[2416] manager.c: Manager received command 'Status' Oct 8 15:56:01 DEBUG[2200] chan_sip.c: Auto destroying call '59c88a6cc504a0047ff114a18f911a34@192.168.1.41' Oct 8 15:56:01 DEBUG[2200] chan_sip.c: Auto destroying call '4f8ee5b4a0d4e9203badf09c2490c344@192.168.1.29' Oct 8 15:56:01 DEBUG[2416] manager.c: Manager received command 'Status' Oct 8 15:56:02 DEBUG[2200] chan_sip.c: Auto destroying call '996dbcd222e6798f4ea43ec399c1b03e@192.168.1.37' Oct 8 15:56:02 DEBUG[2416] manager.c: Manager received command 'Status' Oct 8 15:56:02 DEBUG[2200] chan_sip.c: Auto destroying call '2759f7d97e308924848cc13d1406bba8@192.168.1.52' Oct 8 15:56:03 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]T203 counter expired, sending RR and scheduling T203 again Oct 8 15:56:03 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]Sending Receiver Ready (76) Oct 8 15:56:03 VERBOSE[2195] logger.c: [Span 0 D-Channel 0] > [ 00 01 01 99 ] Oct 8 15:56:03 VERBOSE[2195] logger.c: [Span 0 D-Channel 0] > Supervisory frame: Oct 8 15:56:03 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]> SAPI: 00 C/R: 0 EA: 0 > TEI: 000 EA: 1 Oct 8 15:56:03 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]> Zero: 0 S: 0 01: 1 [ RR (receive ready) ] > N(R): 076 P/F: 1 > 0 bytes of data Oct 8 15:56:03 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]-- Restarting T203 counter Oct 8 15:56:03 VERBOSE[2195] logger.c: [Span 0 D-Channel 0] < [ 00 01 01 95 ] Oct 8 15:56:03 VERBOSE[2195] logger.c: [Span 0 D-Channel 0] < Supervisory frame: Oct 8 15:56:03 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]< SAPI: 00 C/R: 0 EA: 0 < TEI: 000 EA: 1 Oct 8 15:56:03 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]< Zero: 0 S: 0 01: 1 [ RR (receive ready) ] < N(R): 074 P/F: 1 < 0 bytes of data Oct 8 15:56:03 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]-- ACKing all packets from 73 to (but not including) 74 Oct 8 15:56:03 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]-- Since there was nothing left, stopping T200 counter Oct 8 15:56:03 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]-- Stopping T203 counter since we got an ACK Oct 8 15:56:03 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]-- Nothing left, starting T203 counter Oct 8 15:56:03 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]-- Got RR response to our frame Oct 8 15:56:03 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]-- Restarting T203 counter Oct 8 15:56:03 WARNING[2193] pbx_spool.c: Unable to set utime on /var/spool/asterisk/outgoing/389735.call: Operation not permitted Oct 8 15:56:03 DEBUG[2193] pbx_spool.c: Delaying retry since we're currently running 'ض"ˆVAol/asterisk/outgoing/389735.call' Oct 8 15:56:03 DEBUG[2200] chan_sip.c: Auto destroying call 'ee375e9394127f53475ff968c169b32d@192.168.1.62' Oct 8 15:56:03 DEBUG[2416] manager.c: Manager received command 'Status' Oct 8 15:56:04 VERBOSE[2195] logger.c: [Span 0 D-Channel 0] < [ 02 01 98 94 08 02 8c 3b 07 1e 02 84 82 ] Oct 8 15:56:04 VERBOSE[2195] logger.c: [Span 0 D-Channel 0] < Informational frame: Oct 8 15:56:04 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]< SAPI: 00 C/R: 1 EA: 0 < TEI: 000 EA: 1 Oct 8 15:56:04 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]< N(S): 076 0: 0 < N(R): 074 P: 0 < 9 bytes of data Oct 8 15:56:04 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]-- ACKing all packets from 73 to (but not including) 74 Oct 8 15:56:04 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]-- Since there was nothing left, stopping T200 counter Oct 8 15:56:04 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]-- Stopping T203 counter since we got an ACK Oct 8 15:56:04 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]-- Nothing left, starting T203 counter Oct 8 15:56:04 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]< Protocol Discriminator: Q.931 (8) len=9 Oct 8 15:56:04 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]< Call Ref: len= 2 (reference 3131/0xC3B) (Terminator) Oct 8 15:56:04 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]< Message type: CONNECT (7) Oct 8 15:56:04 VERBOSE[2195] logger.c: < [Oct 8 15:56:04 VERBOSE[2195] logger.c: < [1eOct 8 15:56:04 VERBOSE[2195] logger.c: < [1e 02Oct 8 15:56:04 VERBOSE[2195] logger.c: < [1e 02 84Oct 8 15:56:04 VERBOSE[2195] logger.c: < [1e 02 84 82Oct 8 15:56:04 VERBOSE[2195] logger.c: < [1e 02 84 82] Oct 8 15:56:04 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]< Progress Indicator (len= 4) [ Ext: 1 Coding: CCITT (ITU) standard (0) 0: 0 Location: Public network serving the remote user (4) Oct 8 15:56:04 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]< Ext: 1 Progress Description: Called equipment is non-ISDN. (2) ] Oct 8 15:56:04 VERBOSE[2195] logger.c: [Span 0 D-Channel 0] > [ 00 01 94 9a 08 02 0c 3b 0f ] Oct 8 15:56:04 VERBOSE[2195] logger.c: [Span 0 D-Channel 0] > Informational frame: Oct 8 15:56:04 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]> SAPI: 00 C/R: 0 EA: 0 > TEI: 000 EA: 1 Oct 8 15:56:04 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]> N(S): 074 0: 0 > N(R): 077 P: 0 > 5 bytes of data Oct 8 15:56:04 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]-- Restarting T203 counter Oct 8 15:56:04 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]Stopping T_203 timer Oct 8 15:56:04 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]Starting T_200 timer Oct 8 15:56:04 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]> Protocol Discriminator: Q.931 (8) len=5 Oct 8 15:56:04 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]> Call Ref: len= 2 (reference 3131/0xC3B) (Originator) Oct 8 15:56:04 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]> Message type: CONNECT ACKNOWLEDGE (15) Oct 8 15:56:04 DEBUG[2195] chan_zap.c: Echo cancellation already on Oct 8 15:56:04 VERBOSE[2195] logger.c: [Span 0 D-Channel 0] < [ 00 01 01 96 ] Oct 8 15:56:04 VERBOSE[2195] logger.c: [Span 0 D-Channel 0] < Supervisory frame: Oct 8 15:56:04 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]< SAPI: 00 C/R: 0 EA: 0 < TEI: 000 EA: 1 Oct 8 15:56:04 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]< Zero: 0 S: 0 01: 1 [ RR (receive ready) ] < N(R): 075 P/F: 0 < 0 bytes of data Oct 8 15:56:04 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]-- ACKing all packets from 73 to (but not including) 75 Oct 8 15:56:04 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]-- ACKing packet 74, new txqueue is -1 (-1 means empty) Oct 8 15:56:04 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]-- Since there was nothing left, stopping T200 counter Oct 8 15:56:04 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]-- Nothing left, starting T203 counter Oct 8 15:56:04 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]-- Restarting T203 counter Oct 8 15:56:04 VERBOSE[11513] logger.c: > Channel Zap/47-1 was answered. Oct 8 15:56:04 VERBOSE[11513] logger.c: -- Executing Answer("Zap/47-1", "") in new stack Oct 8 15:56:04 VERBOSE[11513] logger.c: -- Executing BackgroundDetect("Zap/47-1", "silence/10|1000|50|0") in new stack Oct 8 15:56:04 DEBUG[11513] app_talkdetect.c: Preparing detect of 'silence/10', sil=1000,min=50,max=-1 Oct 8 15:56:04 DEBUG[11513] channel.c: Scheduling timer at 160 sample intervals Oct 8 15:56:04 VERBOSE[11513] logger.c: -- Playing 'silence/10' (language 'fr') Oct 8 15:56:04 DEBUG[11513] app_talkdetect.c: Start of voice token! Oct 8 15:56:04 DEBUG[2200] chan_sip.c: Auto destroying call 'bcc26e4340e600e882363a0d96401221@192.168.1.31' Oct 8 15:56:04 DEBUG[2200] chan_sip.c: Auto destroying call 'bed2cda66eacd8bb2b8d58e952da5610@192.168.1.73' Oct 8 15:56:04 DEBUG[2416] manager.c: Manager received command 'Status' Oct 8 15:56:05 DEBUG[11513] app_talkdetect.c: Found unqualified token of 0 ms Oct 8 15:56:05 DEBUG[11513] app_talkdetect.c: Start of voice token! Oct 8 15:56:05 DEBUG[2416] manager.c: Manager received command 'Status' Oct 8 15:56:06 DEBUG[2200] chan_sip.c: Auto destroying call 'e6425fdfaf5e289d9ac9d77d536621bf@192.168.1.45' Oct 8 15:56:06 DEBUG[2200] chan_sip.c: Auto destroying call '2cdc3f49aa867427d5cd329a8373c2ef@192.168.1.23' Oct 8 15:56:06 DEBUG[2416] manager.c: Manager received command 'Status' Oct 8 15:56:07 DEBUG[11513] app_talkdetect.c: Found qualified token of 179 ms Oct 8 15:56:07 DEBUG[11513] channel.c: Scheduling timer at 0 sample intervals Oct 8 15:56:07 VERBOSE[11513] logger.c: -- Executing System("Zap/47-1", "/usr/bin/cwASTstocke.pl IVRoprecrutement MTX73733 ASTERISK47 1 "RBTresponse"") in new stack Oct 8 15:56:07 VERBOSE[11513] logger.c: -- Executing Goto("Zap/47-1", "oplus_recrue_f_info|s|1") in new stack Oct 8 15:56:07 VERBOSE[11513] logger.c: -- Goto (oplus_recrue_f_info,s,1) Oct 8 15:56:07 VERBOSE[11513] logger.c: -- Executing SetLanguage("Zap/47-1", "fr") in new stack Oct 8 15:56:07 VERBOSE[11513] logger.c: -- Executing BackGround("Zap/47-1", "custom/recrue/message-1") in new stack Oct 8 15:56:07 DEBUG[11513] channel.c: Scheduling timer at 160 sample intervals Oct 8 15:56:07 VERBOSE[11513] logger.c: -- Playing 'custom/recrue/message-1' (language 'fr') Oct 8 15:56:07 DEBUG[2200] chan_sip.c: Auto destroying call 'f98a57acb14e7b1cea84f8c80151f349@192.168.1.35' Oct 8 15:56:07 DEBUG[2416] manager.c: Manager received command 'Status' Oct 8 15:56:08 VERBOSE[2195] logger.c: [Span 0 D-Channel 1]T203 counter expired, sending RR and scheduling T203 again Oct 8 15:56:08 VERBOSE[2195] logger.c: [Span 0 D-Channel 1]Sending Receiver Ready (0) Oct 8 15:56:08 VERBOSE[2195] logger.c: [Span 0 D-Channel 1] > [ 00 01 01 01 ] Oct 8 15:56:08 VERBOSE[2195] logger.c: [Span 0 D-Channel 1] > Supervisory frame: Oct 8 15:56:08 VERBOSE[2195] logger.c: [Span 0 D-Channel 1]> SAPI: 00 C/R: 0 EA: 0 > TEI: 000 EA: 1 Oct 8 15:56:08 VERBOSE[2195] logger.c: [Span 0 D-Channel 1]> Zero: 0 S: 0 01: 1 [ RR (receive ready) ] > N(R): 000 P/F: 1 > 0 bytes of data Oct 8 15:56:08 VERBOSE[2195] logger.c: [Span 0 D-Channel 1]-- Restarting T203 counter Oct 8 15:56:08 VERBOSE[2195] logger.c: [Span 0 D-Channel 1] < [ 00 01 01 01 ] Oct 8 15:56:08 VERBOSE[2195] logger.c: [Span 0 D-Channel 1] < Supervisory frame: Oct 8 15:56:08 VERBOSE[2195] logger.c: [Span 0 D-Channel 1]< SAPI: 00 C/R: 0 EA: 0 < TEI: 000 EA: 1 Oct 8 15:56:08 VERBOSE[2195] logger.c: [Span 0 D-Channel 1]< Zero: 0 S: 0 01: 1 [ RR (receive ready) ] < N(R): 000 P/F: 1 < 0 bytes of data Oct 8 15:56:08 VERBOSE[2195] logger.c: [Span 0 D-Channel 1]-- ACKing all packets from 0 to (but not including) 0 Oct 8 15:56:08 VERBOSE[2195] logger.c: [Span 0 D-Channel 1]-- Since there was nothing left, stopping T200 counter Oct 8 15:56:08 VERBOSE[2195] logger.c: [Span 0 D-Channel 1]-- Stopping T203 counter since we got an ACK Oct 8 15:56:08 VERBOSE[2195] logger.c: [Span 0 D-Channel 1]-- Nothing left, starting T203 counter Oct 8 15:56:08 VERBOSE[2195] logger.c: [Span 0 D-Channel 1]-- Got RR response to our frame Oct 8 15:56:08 VERBOSE[2195] logger.c: [Span 0 D-Channel 1]-- Restarting T203 counter Oct 8 15:56:08 DEBUG[2416] manager.c: Manager received command 'Status' Oct 8 15:56:09 DEBUG[2416] manager.c: Manager received command 'Status' Oct 8 15:56:10 DEBUG[2416] manager.c: Manager received command 'Status' Oct 8 15:56:11 DEBUG[2416] manager.c: Manager received command 'Status' Oct 8 15:56:12 DEBUG[2200] chan_sip.c: Auto destroying call '066cbb28aa35715a49d832bd64378663@192.168.1.75' Oct 8 15:56:12 DEBUG[2200] chan_sip.c: Stopping retransmission on '631e354a44a846482f69cee23d7bf2e2@192.168.1.100' of Request 102: Match Found Oct 8 15:56:12 DEBUG[2200] chan_sip.c: Stopping retransmission on '28feb39a12cf3527652ca4450dec2b4d@192.168.1.100' of Request 102: Match Found Oct 8 15:56:12 DEBUG[2200] chan_sip.c: Stopping retransmission on '30f135a321f48128567f513e76f4e687@192.168.1.100' of Request 102: Match Found Oct 8 15:56:12 DEBUG[2200] chan_sip.c: Stopping retransmission on '5e49bc2e58e75591344212c6735b38ae@192.168.1.100' of Request 102: Match Found Oct 8 15:56:12 DEBUG[2200] chan_sip.c: Stopping retransmission on '25e6d63a7892873113bbe36a7953a238@192.168.1.100' of Request 102: Match Found Oct 8 15:56:12 DEBUG[2416] manager.c: Manager received command 'Status' Oct 8 15:56:13 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]T203 counter expired, sending RR and scheduling T203 again Oct 8 15:56:13 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]Sending Receiver Ready (77) Oct 8 15:56:13 VERBOSE[2195] logger.c: [Span 0 D-Channel 0] > [ 00 01 01 9b ] Oct 8 15:56:13 VERBOSE[2195] logger.c: [Span 0 D-Channel 0] > Supervisory frame: Oct 8 15:56:13 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]> SAPI: 00 C/R: 0 EA: 0 > TEI: 000 EA: 1 Oct 8 15:56:13 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]> Zero: 0 S: 0 01: 1 [ RR (receive ready) ] > N(R): 077 P/F: 1 > 0 bytes of data Oct 8 15:56:13 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]-- Restarting T203 counter Oct 8 15:56:13 VERBOSE[2195] logger.c: [Span 0 D-Channel 0] < [ 00 01 01 97 ] Oct 8 15:56:13 VERBOSE[2195] logger.c: [Span 0 D-Channel 0] < Supervisory frame: Oct 8 15:56:13 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]< SAPI: 00 C/R: 0 EA: 0 < TEI: 000 EA: 1 Oct 8 15:56:13 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]< Zero: 0 S: 0 01: 1 [ RR (receive ready) ] < N(R): 075 P/F: 1 < 0 bytes of data Oct 8 15:56:13 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]-- ACKing all packets from 74 to (but not including) 75 Oct 8 15:56:13 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]-- Since there was nothing left, stopping T200 counter Oct 8 15:56:13 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]-- Stopping T203 counter since we got an ACK Oct 8 15:56:13 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]-- Nothing left, starting T203 counter Oct 8 15:56:13 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]-- Got RR response to our frame Oct 8 15:56:13 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]-- Restarting T203 counter Oct 8 15:56:13 DEBUG[2416] manager.c: Manager received command 'Status' Oct 8 15:56:14 WARNING[2193] pbx_spool.c: Unable to set utime on /var/spool/asterisk/outgoing/389735.call: Operation not permitted Oct 8 15:56:14 DEBUG[2193] pbx_spool.c: Delaying retry since we're currently running '@–'ˆVAol/asterisk/outgoing/389735.call' Oct 8 15:56:14 DEBUG[2416] manager.c: Manager received command 'Status' Oct 8 15:56:15 DEBUG[2416] manager.c: Manager received command 'Status' Oct 8 15:56:16 DEBUG[2416] manager.c: Manager received command 'Status' Oct 8 15:56:17 DEBUG[2416] manager.c: Manager received command 'Status' Oct 8 15:56:18 VERBOSE[2195] logger.c: [Span 0 D-Channel 1]T203 counter expired, sending RR and scheduling T203 again Oct 8 15:56:18 VERBOSE[2195] logger.c: [Span 0 D-Channel 1]Sending Receiver Ready (0) Oct 8 15:56:18 VERBOSE[2195] logger.c: [Span 0 D-Channel 1] > [ 00 01 01 01 ] Oct 8 15:56:18 VERBOSE[2195] logger.c: [Span 0 D-Channel 1] > Supervisory frame: Oct 8 15:56:18 VERBOSE[2195] logger.c: [Span 0 D-Channel 1]> SAPI: 00 C/R: 0 EA: 0 > TEI: 000 EA: 1 Oct 8 15:56:18 VERBOSE[2195] logger.c: [Span 0 D-Channel 1]> Zero: 0 S: 0 01: 1 [ RR (receive ready) ] > N(R): 000 P/F: 1 > 0 bytes of data Oct 8 15:56:18 VERBOSE[2195] logger.c: [Span 0 D-Channel 1]-- Restarting T203 counter Oct 8 15:56:18 VERBOSE[2195] logger.c: [Span 0 D-Channel 1] < [ 00 01 01 01 ] Oct 8 15:56:18 VERBOSE[2195] logger.c: [Span 0 D-Channel 1] < Supervisory frame: Oct 8 15:56:18 VERBOSE[2195] logger.c: [Span 0 D-Channel 1]< SAPI: 00 C/R: 0 EA: 0 < TEI: 000 EA: 1 Oct 8 15:56:18 VERBOSE[2195] logger.c: [Span 0 D-Channel 1]< Zero: 0 S: 0 01: 1 [ RR (receive ready) ] < N(R): 000 P/F: 1 < 0 bytes of data Oct 8 15:56:18 VERBOSE[2195] logger.c: [Span 0 D-Channel 1]-- ACKing all packets from 0 to (but not including) 0 Oct 8 15:56:18 VERBOSE[2195] logger.c: [Span 0 D-Channel 1]-- Since there was nothing left, stopping T200 counter Oct 8 15:56:18 VERBOSE[2195] logger.c: [Span 0 D-Channel 1]-- Stopping T203 counter since we got an ACK Oct 8 15:56:18 VERBOSE[2195] logger.c: [Span 0 D-Channel 1]-- Nothing left, starting T203 counter Oct 8 15:56:18 VERBOSE[2195] logger.c: [Span 0 D-Channel 1]-- Got RR response to our frame Oct 8 15:56:18 VERBOSE[2195] logger.c: [Span 0 D-Channel 1]-- Restarting T203 counter Oct 8 15:56:18 DEBUG[2416] manager.c: Manager received command 'Status' Oct 8 15:56:19 DEBUG[2416] manager.c: Manager received command 'Status' Oct 8 15:56:20 DEBUG[2416] manager.c: Manager received command 'Status' Oct 8 15:56:21 DEBUG[2416] manager.c: Manager received command 'Status' Oct 8 15:56:22 DEBUG[2416] manager.c: Manager received command 'Status' Oct 8 15:56:22 DEBUG[2200] chan_sip.c: Auto destroying call '803d2eb7b52dcaa0c8145feb386c2598@192.168.1.38' Oct 8 15:56:22 DEBUG[2200] chan_sip.c: Auto destroying call '428b817d3c11b2a684baec1dc6cd0879@192.168.1.43' Oct 8 15:56:23 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]T203 counter expired, sending RR and scheduling T203 again Oct 8 15:56:23 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]Sending Receiver Ready (77) Oct 8 15:56:23 VERBOSE[2195] logger.c: [Span 0 D-Channel 0] > [ 00 01 01 9b ] Oct 8 15:56:23 VERBOSE[2195] logger.c: [Span 0 D-Channel 0] > Supervisory frame: Oct 8 15:56:23 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]> SAPI: 00 C/R: 0 EA: 0 > TEI: 000 EA: 1 Oct 8 15:56:23 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]> Zero: 0 S: 0 01: 1 [ RR (receive ready) ] > N(R): 077 P/F: 1 > 0 bytes of data Oct 8 15:56:23 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]-- Restarting T203 counter Oct 8 15:56:23 VERBOSE[2195] logger.c: [Span 0 D-Channel 0] < [ 00 01 01 97 ] Oct 8 15:56:23 VERBOSE[2195] logger.c: [Span 0 D-Channel 0] < Supervisory frame: Oct 8 15:56:23 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]< SAPI: 00 C/R: 0 EA: 0 < TEI: 000 EA: 1 Oct 8 15:56:23 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]< Zero: 0 S: 0 01: 1 [ RR (receive ready) ] < N(R): 075 P/F: 1 < 0 bytes of data Oct 8 15:56:23 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]-- ACKing all packets from 74 to (but not including) 75 Oct 8 15:56:23 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]-- Since there was nothing left, stopping T200 counter Oct 8 15:56:23 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]-- Stopping T203 counter since we got an ACK Oct 8 15:56:23 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]-- Nothing left, starting T203 counter Oct 8 15:56:23 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]-- Got RR response to our frame Oct 8 15:56:23 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]-- Restarting T203 counter Oct 8 15:56:23 DEBUG[2416] manager.c: Manager received command 'Status' Oct 8 15:56:24 DEBUG[2200] chan_sip.c: Stopping retransmission on '7922e35057dd06d3269e4a6f5b06182f@192.168.1.100' of Request 102: Match Found Oct 8 15:56:24 DEBUG[2200] chan_sip.c: Auto destroying call '0942987293addfd0235606a976e20b9a@192.168.1.46' Oct 8 15:56:24 DEBUG[11513] channel.c: Scheduling timer at 10 sample intervals Oct 8 15:56:24 DEBUG[11513] channel.c: Scheduling timer at 0 sample intervals Oct 8 15:56:24 DEBUG[11513] channel.c: Scheduling timer at 0 sample intervals Oct 8 15:56:24 VERBOSE[11513] logger.c: -- Executing BackGround("Zap/47-1", "custom/recrue/options-1") in new stack Oct 8 15:56:24 DEBUG[11513] channel.c: Scheduling timer at 160 sample intervals Oct 8 15:56:24 VERBOSE[11513] logger.c: -- Playing 'custom/recrue/options-1' (language 'fr') Oct 8 15:56:24 DEBUG[2416] manager.c: Manager received command 'Status' Oct 8 15:56:25 DEBUG[2200] chan_sip.c: Auto destroying call 'c0ba2ae03d20f4d82f6ff661b5b7ce1b@192.168.1.36' Oct 8 15:56:25 WARNING[2193] pbx_spool.c: Unable to set utime on /var/spool/asterisk/outgoing/389735.call: Operation not permitted Oct 8 15:56:25 DEBUG[2193] pbx_spool.c: Delaying retry since we're currently running '`˜'ˆVAol/asterisk/outgoing/389735.call' Oct 8 15:56:25 DEBUG[2416] manager.c: Manager received command 'Status' Oct 8 15:56:26 DEBUG[2200] chan_sip.c: Auto destroying call 'ae29e37214334d039a1d6bfde1cc1774@192.168.1.39' Oct 8 15:56:26 DEBUG[2200] chan_sip.c: Stopping retransmission on '58adb6133d9a0696486762fc29a9eb90@192.168.1.100' of Request 102: Match Found Oct 8 15:56:26 DEBUG[2200] chan_sip.c: Stopping retransmission on '2bbc765f3b84400e5e0d4c451868c0bc@192.168.1.100' of Request 102: Match Found Oct 8 15:56:26 DEBUG[2416] manager.c: Manager received command 'Status' Oct 8 15:56:27 DEBUG[2416] manager.c: Manager received command 'Status' Oct 8 15:56:28 VERBOSE[2195] logger.c: [Span 0 D-Channel 1]T203 counter expired, sending RR and scheduling T203 again Oct 8 15:56:28 VERBOSE[2195] logger.c: [Span 0 D-Channel 1]Sending Receiver Ready (0) Oct 8 15:56:28 VERBOSE[2195] logger.c: [Span 0 D-Channel 1] > [ 00 01 01 01 ] Oct 8 15:56:28 VERBOSE[2195] logger.c: [Span 0 D-Channel 1] > Supervisory frame: Oct 8 15:56:28 VERBOSE[2195] logger.c: [Span 0 D-Channel 1]> SAPI: 00 C/R: 0 EA: 0 > TEI: 000 EA: 1 Oct 8 15:56:28 VERBOSE[2195] logger.c: [Span 0 D-Channel 1]> Zero: 0 S: 0 01: 1 [ RR (receive ready) ] > N(R): 000 P/F: 1 > 0 bytes of data Oct 8 15:56:28 VERBOSE[2195] logger.c: [Span 0 D-Channel 1]-- Restarting T203 counter Oct 8 15:56:28 VERBOSE[2195] logger.c: [Span 0 D-Channel 1] < [ 00 01 01 01 ] Oct 8 15:56:28 VERBOSE[2195] logger.c: [Span 0 D-Channel 1] < Supervisory frame: Oct 8 15:56:28 VERBOSE[2195] logger.c: [Span 0 D-Channel 1]< SAPI: 00 C/R: 0 EA: 0 < TEI: 000 EA: 1 Oct 8 15:56:28 VERBOSE[2195] logger.c: [Span 0 D-Channel 1]< Zero: 0 S: 0 01: 1 [ RR (receive ready) ] < N(R): 000 P/F: 1 < 0 bytes of data Oct 8 15:56:28 VERBOSE[2195] logger.c: [Span 0 D-Channel 1]-- ACKing all packets from 0 to (but not including) 0 Oct 8 15:56:28 VERBOSE[2195] logger.c: [Span 0 D-Channel 1]-- Since there was nothing left, stopping T200 counter Oct 8 15:56:28 VERBOSE[2195] logger.c: [Span 0 D-Channel 1]-- Stopping T203 counter since we got an ACK Oct 8 15:56:28 VERBOSE[2195] logger.c: [Span 0 D-Channel 1]-- Nothing left, starting T203 counter Oct 8 15:56:28 VERBOSE[2195] logger.c: [Span 0 D-Channel 1]-- Got RR response to our frame Oct 8 15:56:28 VERBOSE[2195] logger.c: [Span 0 D-Channel 1]-- Restarting T203 counter Oct 8 15:56:28 DEBUG[2416] manager.c: Manager received command 'Status' Oct 8 15:56:29 DEBUG[2416] manager.c: Manager received command 'Status' Oct 8 15:56:30 DEBUG[2200] chan_sip.c: Auto destroying call 'ea6cc65be110b1291fc43651dbc91f77@192.168.1.42' Oct 8 15:56:30 DEBUG[2416] manager.c: Manager received command 'Status' Oct 8 15:56:31 DEBUG[2416] manager.c: Manager received command 'Status' Oct 8 15:56:32 DEBUG[2200] chan_sip.c: Auto destroying call '5ea0f1180b7d1f4fcb59a7c0355b4e64@192.168.1.50' Oct 8 15:56:32 DEBUG[2200] chan_sip.c: Auto destroying call '6cb43e20309bbc06278a20fed2c9cc10@192.168.1.49' Oct 8 15:56:32 DEBUG[2416] manager.c: Manager received command 'Status' Oct 8 15:56:33 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]T203 counter expired, sending RR and scheduling T203 again Oct 8 15:56:33 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]Sending Receiver Ready (77) Oct 8 15:56:33 VERBOSE[2195] logger.c: [Span 0 D-Channel 0] > [ 00 01 01 9b ] Oct 8 15:56:33 VERBOSE[2195] logger.c: [Span 0 D-Channel 0] > Supervisory frame: Oct 8 15:56:33 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]> SAPI: 00 C/R: 0 EA: 0 > TEI: 000 EA: 1 Oct 8 15:56:33 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]> Zero: 0 S: 0 01: 1 [ RR (receive ready) ] > N(R): 077 P/F: 1 > 0 bytes of data Oct 8 15:56:33 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]-- Restarting T203 counter Oct 8 15:56:33 VERBOSE[2195] logger.c: [Span 0 D-Channel 0] < [ 00 01 01 97 ] Oct 8 15:56:33 VERBOSE[2195] logger.c: [Span 0 D-Channel 0] < Supervisory frame: Oct 8 15:56:33 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]< SAPI: 00 C/R: 0 EA: 0 < TEI: 000 EA: 1 Oct 8 15:56:33 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]< Zero: 0 S: 0 01: 1 [ RR (receive ready) ] < N(R): 075 P/F: 1 < 0 bytes of data Oct 8 15:56:33 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]-- ACKing all packets from 74 to (but not including) 75 Oct 8 15:56:33 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]-- Since there was nothing left, stopping T200 counter Oct 8 15:56:33 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]-- Stopping T203 counter since we got an ACK Oct 8 15:56:33 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]-- Nothing left, starting T203 counter Oct 8 15:56:33 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]-- Got RR response to our frame Oct 8 15:56:33 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]-- Restarting T203 counter Oct 8 15:56:33 DEBUG[2416] manager.c: Manager received command 'Status' Oct 8 15:56:34 DEBUG[2416] manager.c: Manager received command 'Status' Oct 8 15:56:35 DEBUG[2200] chan_sip.c: Stopping retransmission on '111658c8047191772b5e655d51b26598@192.168.1.100' of Request 102: Match Found Oct 8 15:56:35 DEBUG[2200] chan_sip.c: Stopping retransmission on '64b84c975e0beed054038197576ae70c@192.168.1.100' of Request 102: Match Found Oct 8 15:56:35 DEBUG[2416] manager.c: Manager received command 'Status' Oct 8 15:56:36 DEBUG[2416] manager.c: Manager received command 'Status' Oct 8 15:56:36 WARNING[2193] pbx_spool.c: Unable to set utime on /var/spool/asterisk/outgoing/389735.call: Operation not permitted Oct 8 15:56:36 DEBUG[2193] pbx_spool.c: Delaying retry since we're currently running ' m$ˆVAol/asterisk/outgoing/389735.call' Oct 8 15:56:37 DEBUG[2416] manager.c: Manager received command 'Status' Oct 8 15:56:37 DEBUG[11513] channel.c: Scheduling timer at 112 sample intervals Oct 8 15:56:37 DEBUG[11513] channel.c: Scheduling timer at 0 sample intervals Oct 8 15:56:37 DEBUG[11513] channel.c: Scheduling timer at 0 sample intervals Oct 8 15:56:38 DEBUG[2200] chan_sip.c: Stopping retransmission on '60fb4e335d7884781f0f31301e2ac94a@192.168.1.100' of Request 102: Match Found Oct 8 15:56:38 VERBOSE[2195] logger.c: [Span 0 D-Channel 1]T203 counter expired, sending RR and scheduling T203 again Oct 8 15:56:38 VERBOSE[2195] logger.c: [Span 0 D-Channel 1]Sending Receiver Ready (0) Oct 8 15:56:38 VERBOSE[2195] logger.c: [Span 0 D-Channel 1] > [ 00 01 01 01 ] Oct 8 15:56:38 VERBOSE[2195] logger.c: [Span 0 D-Channel 1] > Supervisory frame: Oct 8 15:56:38 VERBOSE[2195] logger.c: [Span 0 D-Channel 1]> SAPI: 00 C/R: 0 EA: 0 > TEI: 000 EA: 1 Oct 8 15:56:38 VERBOSE[2195] logger.c: [Span 0 D-Channel 1]> Zero: 0 S: 0 01: 1 [ RR (receive ready) ] > N(R): 000 P/F: 1 > 0 bytes of data Oct 8 15:56:38 VERBOSE[2195] logger.c: [Span 0 D-Channel 1]-- Restarting T203 counter Oct 8 15:56:38 VERBOSE[2195] logger.c: [Span 0 D-Channel 1] < [ 00 01 01 01 ] Oct 8 15:56:38 VERBOSE[2195] logger.c: [Span 0 D-Channel 1] < Supervisory frame: Oct 8 15:56:38 VERBOSE[2195] logger.c: [Span 0 D-Channel 1]< SAPI: 00 C/R: 0 EA: 0 < TEI: 000 EA: 1 Oct 8 15:56:38 VERBOSE[2195] logger.c: [Span 0 D-Channel 1]< Zero: 0 S: 0 01: 1 [ RR (receive ready) ] < N(R): 000 P/F: 1 < 0 bytes of data Oct 8 15:56:38 VERBOSE[2195] logger.c: [Span 0 D-Channel 1]-- ACKing all packets from 0 to (but not including) 0 Oct 8 15:56:38 VERBOSE[2195] logger.c: [Span 0 D-Channel 1]-- Since there was nothing left, stopping T200 counter Oct 8 15:56:38 VERBOSE[2195] logger.c: [Span 0 D-Channel 1]-- Stopping T203 counter since we got an ACK Oct 8 15:56:38 VERBOSE[2195] logger.c: [Span 0 D-Channel 1]-- Nothing left, starting T203 counter Oct 8 15:56:38 VERBOSE[2195] logger.c: [Span 0 D-Channel 1]-- Got RR response to our frame Oct 8 15:56:38 VERBOSE[2195] logger.c: [Span 0 D-Channel 1]-- Restarting T203 counter Oct 8 15:56:38 DEBUG[2416] manager.c: Manager received command 'Status' Oct 8 15:56:39 DEBUG[2416] manager.c: Manager received command 'Status' Oct 8 15:56:40 DEBUG[2416] manager.c: Manager received command 'Status' Oct 8 15:56:41 DEBUG[2416] manager.c: Manager received command 'Status' Oct 8 15:56:42 DEBUG[2416] manager.c: Manager received command 'Status' Oct 8 15:56:43 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]T203 counter expired, sending RR and scheduling T203 again Oct 8 15:56:43 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]Sending Receiver Ready (77) Oct 8 15:56:43 VERBOSE[2195] logger.c: [Span 0 D-Channel 0] > [ 00 01 01 9b ] Oct 8 15:56:43 VERBOSE[2195] logger.c: [Span 0 D-Channel 0] > Supervisory frame: Oct 8 15:56:43 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]> SAPI: 00 C/R: 0 EA: 0 > TEI: 000 EA: 1 Oct 8 15:56:43 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]> Zero: 0 S: 0 01: 1 [ RR (receive ready) ] > N(R): 077 P/F: 1 > 0 bytes of data Oct 8 15:56:43 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]-- Restarting T203 counter Oct 8 15:56:43 VERBOSE[2195] logger.c: [Span 0 D-Channel 0] < [ 00 01 01 97 ] Oct 8 15:56:43 VERBOSE[2195] logger.c: [Span 0 D-Channel 0] < Supervisory frame: Oct 8 15:56:43 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]< SAPI: 00 C/R: 0 EA: 0 < TEI: 000 EA: 1 Oct 8 15:56:43 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]< Zero: 0 S: 0 01: 1 [ RR (receive ready) ] < N(R): 075 P/F: 1 < 0 bytes of data Oct 8 15:56:43 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]-- ACKing all packets from 74 to (but not including) 75 Oct 8 15:56:43 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]-- Since there was nothing left, stopping T200 counter Oct 8 15:56:43 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]-- Stopping T203 counter since we got an ACK Oct 8 15:56:43 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]-- Nothing left, starting T203 counter Oct 8 15:56:43 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]-- Got RR response to our frame Oct 8 15:56:43 VERBOSE[2195] logger.c: [Span 0 D-Channel 0]-- Restarting T203 counter Oct 8 15:56:43 DEBUG[2416] manager.c: Manager received command 'Status' Oct 8 15:56:44 DEBUG[2416] manager.c: Manager received command 'Status' Oct 8 15:56:45 DEBUG[2416] manager.c: Manager received command 'Status' Oct 8 15:56:46 DEBUG[2416] manager.c: Manager received command 'Status' Oct 8 15:56:47 DEBUG[2416] manager.c: Manager received command 'Status' Oct 8 15:56:47 WARNING[2193] pbx_spool.c: Unable to set utime on /var/spool/asterisk/outgoing/389735.call: Operation not permitted Oct 8 15:56:47 DEBUG[2193] pbx_spool.c: Delaying retry since we're currently running 'ض"ˆVAol/asterisk/outgoing/389735.call' Oct 8 15:56:48 VERBOSE[2195] logger.c: [Span 0 D-Channel 1]T203 counter expired, sending RR and scheduling T203 again Oct 8 15:56:48 VERBOSE[2195] logger.c: [Span 0 D-Channel 1]Sending Receiver Ready (0) Oct 8 15:56:48 VERBOSE[2195] logger.c: [Span 0 D-Channel 1] > [ 00 01 01 01 ] Oct 8 15:56:48 VERBOSE[2195] logger.c: [Span 0 D-Channel 1] > Supervisory frame: Oct 8 15:56:48 VERBOSE[2195] logger.c: [Span 0 D-Channel 1]> SAPI: 00 C/R: 0 EA: 0 > TEI: 000 EA: 1 Oct 8 15:56:48 VERBOSE[2195] logger.c: [Span 0 D-Channel 1]> Zero: 0 S: 0 01: 1 [ RR (receive ready) ] > N(R): 000 P/F: 1 > 0 bytes of data Oct 8 15:56:48 VERBOSE[2195] logger.c: [Span 0 D-Channel 1]-- Restarting T203 counter Oct 8 15:56:48 VERBOSE[2195] logger.c: [Span 0 D-Channel 1] < [ 00 01 01 01 ] Oct 8 15:56:48 VERBOSE[2195] logger.c: [Span 0 D-Channel 1] < Supervisory frame: Oct 8 15:56:48 VERBOSE[2195] logger.c: [Span 0 D-Channel 1]< SAPI: 00 C/R: 0 EA: 0 < TEI: 000 EA: 1 Oct 8 15:56:48 VERBOSE[2195] logger.c: [Span 0 D-Channel 1]< Zero: 0 S: 0 01: 1 [ RR (receive ready) ] < N(R): 000 P/F: 1 < 0 bytes of data Oct 8 15:56:48 VERBOSE[2195] logger.c: [Span 0 D-Channel 1]-- ACKing all packets from 0 to (but not including) 0 Oct 8 15:56:48 VERBOSE[2195] logger.c: [Span 0 D-Channel 1]-- Since there was nothing left, stopping T200 counter Oct 8 15:56:48 VERBOSE[2195] logger.c: [Span 0 D-Channel 1]-- Stopping T203 counter since we got an ACK Oct 8 15:56:48 VERBOSE[2195] logger.c: [Span 0 D-Channel 1]-- Nothing left, starting T203 counter Oct 8 15:56:48 VERBOSE[2195] logger.c: [Span 0 D-Channel 1]-- Got RR response to our frame Oct 8 15:56:48 VERBOSE[2195] logger.c: [Span 0 D-Channel 1]-- Restarting T203 counter Oct 8 15:56:48 VERBOSE[11513] logger.c: -- Timeout on Zap/47-1 Oct 8 15:56:48 VERBOSE[11513] logger.c: == CDR updated on Zap/47-1 Oct 8 15:56:48 VERBOSE[11513] logger.c: -- Executing System("Zap/47-1", "/usr/bin/cwASTstocke.pl IVRoprecrutement MTX73733 ASTERISK47 1 "RBTtime_out_1"") in new stack Oct 8 15:56:48 VERBOSE[11513] logger.c: -- Executing Goto("Zap/47-1", "oplus_recrue_f_hangup|s|1") in new stack Oct 8 15:56:48 VERBOSE[11513] logger.c: -- Goto (oplus_recrue_f_hangup,s,1) Oct 8 15:56:48 VERBOSE[11513] logger.c: -- Executing Hangup("Zap/47-1", "") in new stack Oct 8 15:56:48 VERBOSE[11513] logger.c: == Spawn extension (oplus_recrue_f_hangup, s, 1) exited non-zero on 'Zap/47-1' Oct 8 15:56:48 DEBUG[11513] cdr_addon_mysql.c: cdr_mysql: inserting a CDR record. Oct 8 15:56:48 DEBUG[11513] 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-10-08 15:56:04','\"18193593403\" <8009999999>','8009999999','s','oplus_recrue_f_hangup', 'Zap/47-1','','Hangup','',44,44,'ANSWERED',3,'oprecrutement') Oct 8 15:56:48 DEBUG[11513] chan_zap.c: Set option AUDIO MODE, value: ON(1) on Zap/47-1 Oct 8 15:56:48 DEBUG[11513] chan_zap.c: Hangup: channel: 47 index = 0, normal = 57, callwait = -1, thirdcall = -1 Oct 8 15:56:48 DEBUG[11513] chan_zap.c: Not yet hungup... Calling hangup once with icause, and clearing call Oct 8 15:56:48 VERBOSE[11513] logger.c: [Span 0 D-Channel 0] > [ 00 01 96 9a 08 02 0c 3b 45 08 02 81 90 ] Oct 8 15:56:48 VERBOSE[11513] logger.c: [Span 0 D-Channel 0] > Informational frame: Oct 8 15:56:48 VERBOSE[11513] logger.c: [Span 0 D-Channel 0]> SAPI: 00 C/R: 0 EA: 0 > TEI: 000 EA: 1 Oct 8 15:56:48 VERBOSE[11513] logger.c: [Span 0 D-Channel 0]> N(S): 075 0: 0 > N(R): 077 P: 0 > 9 bytes of data Oct 8 15:56:48 VERBOSE[11513] logger.c: [Span 0 D-Channel 0]-- Restarting T203 counter Oct 8 15:56:48 VERBOSE[11513] logger.c: [Span 0 D-Channel 0]Stopping T_203 timer Oct 8 15:56:48 VERBOSE[11513] logger.c: [Span 0 D-Channel 0]Starting T_200 timer Oct 8 15:56:48 VERBOSE[11513] logger.c: [Span 0 D-Channel 0]> Protocol Discriminator: Q.931 (8) len=9 Oct 8 15:56:48 VERBOSE[11513] logger.c: [Span 0 D-Channel 0]> Call Ref: len= 2 (reference 3131/0xC3B) (Originator) Oct 8 15:56:48 VERBOSE[11513] logger.c: [Span 0 D-Channel 0]> Message type: DISCONNECT (69) Oct 8 15:56:48 VERBOSE[11513] logger.c: > [Oct 8 15:56:48 VERBOSE[11513] logger.c: > [08Oct 8 15:56:48 VERBOSE[11513] logger.c: > [08 02Oct 8 15:56:48 VERBOSE[11513] logger.c: > [08 02 81Oct 8 15:56:48 VERBOSE[11513] logger.c: > [08 02 81 90Oct 8 15:56:48 VERBOSE[11513] logger.c: > [08 02 81 90] Oct 8 15:56:48 VERBOSE[11513] logger.c: [Span 0 D-Channel 0]> Cause (len= 4) [ Ext: 1 Coding: CCITT (ITU) standard (0) 0: 0 Location: Private network serving the local user (1) Oct 8 15:56:48 VERBOSE[11513] logger.c: [Span 0 D-Channel 0]> Ext: 1 Cause: Unknown (16), class = Normal Event (1) ] Oct 8 15:56:48 DEBUG[11513] chan_zap.c: disabled echo cancellation on channel 47 Oct 8 15:56:48 DEBUG[11513] chan_zap.c: Set option TDD MODE, value: OFF(0) on Zap/47-1 Oct 8 15:56:48 DEBUG[11513] chan_zap.c: Updated conferencing on 47, with 0 conference users Oct 8 15:56:48 DEBUG[11513] chan_zap.c: Set option AUDIO MODE, value: OFF(0) on Zap/47-1 Oct 8 15:56:48 DEBUG[11513] chan_zap.c: disabled echo cancellation on channel 47 Oct 8 15:56:48 VERBOSE[11513] logger.c: -- Hungup 'Zap/47-1' Oct 8 15:56:48 NOTICE[11513] pbx_spool.c: Call completed to Zap/47/18193593403