Jul 18 12:51:48 DEBUG[4200] chan_sip.c: Checking SIP call limits for device 201 Jul 18 12:51:48 DEBUG[4200] chan_sip.c: build_route: Contact hop: "Marzia Ridolfi" Jul 18 12:51:48 VERBOSE[4187] logger.c: Extension Changed 201 new state InUse for Notify User 200 Jul 18 12:51:48 VERBOSE[4668] logger.c: -- Executing NoOp("SIP/201-08270aa8", "Real Number: 03356307910") in new stack Jul 18 12:51:48 VERBOSE[4668] logger.c: -- Executing Macro("SIP/201-08270aa8", "superdial|1|ZAP/G10|3356307910||tT") in new stack Jul 18 12:51:48 VERBOSE[4668] logger.c: -- Executing NoOp("SIP/201-08270aa8", "Peer 1 using ZAP/G10 to call 3356307910 for with options tT") in new stack Jul 18 12:51:48 DEBUG[4668] app_macro.c: Executed application: Noop Jul 18 12:51:48 DEBUG[4668] pbx.c: Function result is '201' Jul 18 12:51:48 VERBOSE[4668] logger.c: -- Executing Set("SIP/201-08270aa8", "CDR(accountcode)=0557870201") in new stack Jul 18 12:51:48 DEBUG[4668] app_macro.c: Executed application: Set Jul 18 12:51:48 VERBOSE[4668] logger.c: -- Executing Set("SIP/201-08270aa8", "CALLERID(all)=05578701 <05578701>") in new stack Jul 18 12:51:48 DEBUG[4668] app_macro.c: Executed application: Set Jul 18 12:51:48 VERBOSE[4668] logger.c: -- Executing Dial("SIP/201-08270aa8", "ZAP/G10/3356307910||tT") in new stack Jul 18 12:51:48 DEBUG[4668] dsp.c: dsp busy pattern set to 0,0 Jul 18 12:51:48 VERBOSE[4668] logger.c: -- Making new call for cr 32791 Jul 18 12:51:48 VERBOSE[4668] logger.c: -- Requested transfer capability: 0x00 - SPEECH Jul 18 12:51:48 VERBOSE[4668] logger.c: > Protocol Discriminator: Q.931 (8) len=50 Jul 18 12:51:48 VERBOSE[4668] logger.c: > Call Ref: len= 2 (reference 23/0x17) (Originator) Jul 18 12:51:48 VERBOSE[4668] logger.c: > Message type: SETUP (5) Jul 18 12:51:48 VERBOSE[4668] logger.c: > [04 03 80 90 a3] Jul 18 12:51:48 VERBOSE[4668] logger.c: > Bearer Capability (len= 5) [ Ext: 1 Q.931 Std: 0 Info transfer capability: Speech (0) Jul 18 12:51:48 VERBOSE[4668] logger.c: > Ext: 1 Trans mode/rate: 64kbps, circuit-mode (16) Jul 18 12:51:48 VERBOSE[4668] logger.c: > Ext: 1 User information layer 1: A-Law (35) Jul 18 12:51:48 VERBOSE[4668] logger.c: > [18 03 a9 83 8d] Jul 18 12:51:48 VERBOSE[4668] logger.c: > Channel ID (len= 5) [ Ext: 1 IntID: Implicit, PRI Spare: 0, Exclusive Dchan: 0 Jul 18 12:51:48 VERBOSE[4668] logger.c: > ChanSel: Reserved Jul 18 12:51:48 VERBOSE[4668] logger.c: > Ext: 1 Coding: 0 Number Specified Channel Type: 3 Jul 18 12:51:48 VERBOSE[4668] logger.c: > Ext: 1 Channel: 13 ] Jul 18 12:51:48 VERBOSE[4668] logger.c: > [28 08 30 35 35 37 38 37 30 31] Jul 18 12:51:48 VERBOSE[4668] logger.c: > Display (len= 8) [ 05578701 ] Jul 18 12:51:48 VERBOSE[4668] logger.c: > [6c 0a 00 80 30 35 35 37 38 37 30 31] Jul 18 12:51:48 VERBOSE[4668] logger.c: > Calling Number (len=12) [ Ext: 0 TON: Unknown Number Type (0) NPI: Unknown Number Plan (0) Jul 18 12:51:48 VERBOSE[4668] logger.c: > Presentation: Presentation permitted, user number not screened (0) '05578701' ] Jul 18 12:51:48 VERBOSE[4668] logger.c: > [70 0b 80 33 33 35 36 33 30 37 39 31 30] Jul 18 12:51:48 VERBOSE[4668] logger.c: > Called Number (len=13) [ Ext: 1 TON: Unknown Number Type (0) NPI: Unknown Number Plan (0) '3356307910' ] Jul 18 12:51:48 DEBUG[4187] channel.c: Avoiding initial deadlock for 'Zap/13-1' Jul 18 12:51:48 VERBOSE[4668] logger.c: -- Called G10/3356307910 Jul 18 12:51:48 DEBUG[4200] chan_sip.c: Stopping retransmission on '3c26700d3345-9dkgio6qiqpc@snom360-000413236BDE' of Request 114: Match Found Jul 18 12:51:48 DEBUG[4668] chan_sip.c: Oooh, format changed to 4 Jul 18 12:51:48 VERBOSE[4193] logger.c: < Protocol Discriminator: Q.931 (8) len=10 Jul 18 12:51:48 VERBOSE[4193] logger.c: < Call Ref: len= 2 (reference 23/0x17) (Terminator) Jul 18 12:51:48 VERBOSE[4193] logger.c: < Message type: SETUP ACKNOWLEDGE (13) Jul 18 12:51:48 VERBOSE[4193] logger.c: < [18 03 a9 83 8d] Jul 18 12:51:48 VERBOSE[4193] logger.c: < Channel ID (len= 5) [ Ext: 1 IntID: Implicit, PRI Spare: 0, Exclusive Dchan: 0 Jul 18 12:51:48 VERBOSE[4193] logger.c: < ChanSel: Reserved Jul 18 12:51:48 VERBOSE[4193] logger.c: < Ext: 1 Coding: 0 Number Specified Channel Type: 3 Jul 18 12:51:48 VERBOSE[4193] logger.c: < Ext: 1 Channel: 13 ] Jul 18 12:51:48 VERBOSE[4193] logger.c: -- Processing IE 24 (cs0, Channel Identification) Jul 18 12:51:52 DEBUG[4616] channel.c: Got a FRAME_CONTROL (3) frame on channel Zap/15-1 Jul 18 12:51:52 DEBUG[4616] channel.c: Bridge stops bridging channels SIP/234-0825bf90 and Zap/15-1 Jul 18 12:51:52 DEBUG[4616] channel.c: Driver for channel 'SIP/234-0825bf90' does not support indication 3, emulating it Jul 18 12:51:52 DEBUG[4616] channel.c: Scheduling timer at 160 sample intervals Jul 18 12:51:52 DEBUG[4616] channel.c: Generator got voice, switching to phase locked mode Jul 18 12:51:52 DEBUG[4616] channel.c: Scheduling timer at 0 sample intervals Jul 18 12:51:52 DEBUG[4616] channel.c: Scheduling timer at 0 sample intervals Jul 18 12:51:54 VERBOSE[4193] logger.c: < Protocol Discriminator: Q.931 (8) len=9 Jul 18 12:51:54 VERBOSE[4193] logger.c: < Call Ref: len= 2 (reference 23/0x17) (Terminator) Jul 18 12:51:54 VERBOSE[4193] logger.c: < Message type: ALERTING (1) Jul 18 12:51:54 VERBOSE[4193] logger.c: < [1e 02 82 88] Jul 18 12:51:54 VERBOSE[4193] logger.c: < Progress Indicator (len= 4) [ Ext: 1 Coding: CCITT (ITU) standard (0) 0: 0 Location: Public network serving the local user (2) Jul 18 12:51:54 VERBOSE[4193] logger.c: < Ext: 1 Progress Description: Inband information or appropriate pattern now available. (8) ] Jul 18 12:51:54 VERBOSE[4193] logger.c: -- Processing IE 30 (cs0, Progress Indicator) Jul 18 12:51:54 DEBUG[4193] chan_zap.c: Enabled echo cancellation on channel 13 Jul 18 12:51:54 VERBOSE[4668] logger.c: -- Zap/13-1 is ringing Jul 18 12:52:03 VERBOSE[4193] logger.c: < Protocol Discriminator: Q.931 (8) len=9 Jul 18 12:52:03 VERBOSE[4193] logger.c: < Call Ref: len= 2 (reference 23/0x17) (Terminator) Jul 18 12:52:03 VERBOSE[4193] logger.c: < Message type: CONNECT (7) Jul 18 12:52:03 VERBOSE[4193] logger.c: < [4c 02 00 a3] Jul 18 12:52:03 VERBOSE[4193] logger.c: < Connected Number (len= 4) [ Ext: 0 TON: Unknown Number Type (0) NPI: Unknown Number Plan (0)Jul 18 12:52:03 VERBOSE[4193] logger.c: < Connected Number (len= 4) [ Ext: 0 TON: Unknown Number Type (0) NPI: Unknown Number Plan (0) < Ext: 1 Presentation: Presentation prohibited of network provided number (35)Jul 18 12:52:03 VERBOSE[4193] logger.c: < Connected Number (len= 4) [ Ext: 0 TON: Unknown Number Type (0) NPI: Unknown Number Plan (0) Jul 18 12:52:03 VERBOSE[4193] logger.c: -- Processing IE 76 (cs0, Connected Number) Jul 18 12:52:03 VERBOSE[4193] logger.c: > Protocol Discriminator: Q.931 (8) len=5 Jul 18 12:52:03 VERBOSE[4193] logger.c: > Call Ref: len= 2 (reference 23/0x17) (Originator) Jul 18 12:52:03 VERBOSE[4193] logger.c: > Message type: CONNECT ACKNOWLEDGE (15) Jul 18 12:52:03 DEBUG[4193] chan_zap.c: Echo cancellation already on Jul 18 12:52:03 VERBOSE[4668] logger.c: -- Zap/13-1 answered SIP/201-08270aa8 Jul 18 12:52:03 DEBUG[4200] chan_sip.c: Stopping retransmission on '15b42390-71951173@10.0.0.145' of Response 101: Match Found Jul 18 12:52:03 DEBUG[4200] chan_sip.c: Auto destroying call '3350887522@10_0_0_132' Jul 18 12:52:07 DEBUG[4200] chan_sip.c: Auto destroying call '1464177043@10_0_0_143' Jul 18 12:52:10 DEBUG[4668] channel.c: Got a FRAME_CONTROL (5) frame on channel Zap/13-1 Jul 18 12:52:10 DEBUG[4668] channel.c: Bridge stops bridging channels SIP/201-08270aa8 and Zap/13-1 Jul 18 12:52:10 DEBUG[4668] chan_zap.c: Set option AUDIO MODE, value: ON(1) on Zap/13-1 Jul 18 12:52:10 DEBUG[4668] chan_zap.c: Hangup: channel: 13 index = 0, normal = 26, callwait = -1, thirdcall = -1 Jul 18 12:52:10 DEBUG[4668] chan_zap.c: Not yet hungup... Calling hangup once with icause, and clearing call Jul 18 12:52:10 VERBOSE[4668] logger.c: NEW_HANGUP DEBUG: Calling q931_hangup, ourstate Active, peerstate Connect Request Jul 18 12:52:10 VERBOSE[4668] logger.c: > Protocol Discriminator: Q.931 (8) len=9 Jul 18 12:52:10 VERBOSE[4668] logger.c: > Call Ref: len= 2 (reference 23/0x17) (Originator) Jul 18 12:52:10 VERBOSE[4668] logger.c: > Message type: DISCONNECT (69) Jul 18 12:52:10 VERBOSE[4668] logger.c: > [08 02 81 90] Jul 18 12:52:10 VERBOSE[4668] logger.c: > Cause (len= 4) [ Ext: 1 Coding: CCITT (ITU) standard (0) 0: 0 Location: Private network serving the local user (1) Jul 18 12:52:10 VERBOSE[4668] logger.c: > Ext: 1 Cause: Normal Clearing (16), class = Normal Event (1) ] Jul 18 12:52:10 DEBUG[4668] chan_zap.c: disabled echo cancellation on channel 13 Jul 18 12:52:10 DEBUG[4668] chan_zap.c: Set option TDD MODE, value: OFF(0) on Zap/13-1 Jul 18 12:52:10 DEBUG[4668] chan_zap.c: Updated conferencing on 13, with 0 conference users Jul 18 12:52:10 DEBUG[4668] chan_zap.c: Set option AUDIO MODE, value: OFF(0) on Zap/13-1 Jul 18 12:52:10 DEBUG[4668] chan_zap.c: disabled echo cancellation on channel 13 Jul 18 12:52:10 VERBOSE[4668] logger.c: -- Hungup 'Zap/13-1' Jul 18 12:52:10 DEBUG[4668] app_dial.c: Exiting with DIALSTATUS=ANSWER. Jul 18 12:52:10 VERBOSE[4668] logger.c: == Spawn extension (macro-superdial, s, 4) exited non-zero on 'SIP/201-08270aa8' in macro 'superdial' Jul 18 12:52:10 VERBOSE[4668] logger.c: == Spawn extension (macro-superdial, s, 4) exited non-zero on 'SIP/201-08270aa8' Jul 18 12:52:10 DEBUG[4668] chan_sip.c: update_call_counter(201) - decrement call limit counter Jul 18 12:52:10 DEBUG[4668] pbx.c: Function result is '"05578701" <05578701>' Jul 18 12:52:10 DEBUG[4668] pbx.c: Function result is '05578701' Jul 18 12:52:10 DEBUG[4668] pbx.c: Function result is '03356307910' Jul 18 12:52:10 DEBUG[4668] pbx.c: Function result is 'harmoring' Jul 18 12:52:10 DEBUG[4668] pbx.c: Function result is 'SIP/201-08270aa8' Jul 18 12:52:10 DEBUG[4668] pbx.c: Function result is 'Zap/13-1' Jul 18 12:52:10 DEBUG[4668] pbx.c: Function result is 'Dial' Jul 18 12:52:10 DEBUG[4668] pbx.c: Function result is 'ZAP/G10/3356307910||tT' Jul 18 12:52:10 DEBUG[4668] pbx.c: Function result is '2007-07-18 12:51:48' Jul 18 12:52:10 DEBUG[4668] pbx.c: Function result is '2007-07-18 12:52:03' Jul 18 12:52:10 DEBUG[4668] pbx.c: Function result is '2007-07-18 12:52:10' Jul 18 12:52:10 DEBUG[4668] pbx.c: Function result is '22' Jul 18 12:52:10 DEBUG[4668] pbx.c: Function result is '7' Jul 18 12:52:10 DEBUG[4668] pbx.c: Function result is 'ANSWERED' Jul 18 12:52:10 DEBUG[4668] pbx.c: Function result is 'DOCUMENTATION' Jul 18 12:52:10 DEBUG[4668] pbx.c: Function result is '0557870201' Jul 18 12:52:10 DEBUG[4668] pbx.c: Function result is '1184755908.80' Jul 18 12:52:10 DEBUG[4668] pbx.c: Function result is '(null)' Jul 18 12:52:10 DEBUG[4668] cdr_addon_mysql.c: cdr_mysql: inserting a CDR record. Jul 18 12:52:10 DEBUG[4668] 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 ('2007-07-18 12:51:48','\"05578701\" <05578701>','05578701','03356307910','harmoring', 'SIP/201-08270aa8','Zap/13-1','Dial','ZAP/G10/3356307910||tT',22,7,'ANSWERED',3,'0557870201') Jul 18 12:52:10 VERBOSE[4187] logger.c: Extension Changed 201 new state Idle for Notify User 200 Jul 18 12:52:10 DEBUG[4200] chan_sip.c: Stopping retransmission on '15b42390-71951173@10.0.0.145' of Request 102: Match Found Jul 18 12:52:10 DEBUG[4200] chan_sip.c: Stopping retransmission on '3c26700d3345-9dkgio6qiqpc@snom360-000413236BDE' of Request 115: Match Found Jul 18 12:52:10 VERBOSE[4193] logger.c: < Protocol Discriminator: Q.931 (8) len=5 Jul 18 12:52:10 VERBOSE[4193] logger.c: < Call Ref: len= 2 (reference 23/0x17) (Terminator) Jul 18 12:52:10 VERBOSE[4193] logger.c: < Message type: RELEASE (77) Jul 18 12:52:10 VERBOSE[4193] logger.c: NEW_HANGUP DEBUG: Calling q931_hangup, ourstate Null, peerstate Release Request Jul 18 12:52:10 VERBOSE[4193] logger.c: > Protocol Discriminator: Q.931 (8) len=9 Jul 18 12:52:10 VERBOSE[4193] logger.c: > Call Ref: len= 2 (reference 23/0x17) (Originator) Jul 18 12:52:10 VERBOSE[4193] logger.c: > Message type: RELEASE COMPLETE (90) Jul 18 12:52:10 VERBOSE[4193] logger.c: > [08 02 81 90] Jul 18 12:52:10 VERBOSE[4193] logger.c: > Cause (len= 4) [ Ext: 1 Coding: CCITT (ITU) standard (0) 0: 0 Location: Private network serving the local user (1) Jul 18 12:52:10 VERBOSE[4193] logger.c: > Ext: 1 Cause: Normal Clearing (16), class = Normal Event (1) ] Jul 18 12:52:10 VERBOSE[4193] logger.c: NEW_HANGUP DEBUG: Calling q931_hangup, ourstate Null, peerstate Null Jul 18 12:52:10 VERBOSE[4193] logger.c: NEW_HANGUP DEBUG: Destroying the call, ourstate Null, peerstate Null