freeswitch@internal> 2010-01-07 11:20:04.960849 [DEBUG] sofia.c:4628 IP 87.68.244.32 Rejected by acl "domains". Falling back to Digest auth. 2010-01-07 11:20:05.94471 [DEBUG] sofia.c:4628 IP 87.68.244.32 Rejected by acl "domains". Falling back to Digest auth. 2010-01-07 11:20:05.94471 [NOTICE] switch_channel.c:602 New Channel sofia/internal/8898801@il.cellb.it [d75dfa40-fb6d-11de-9911-b7e694ca6e0b] 2010-01-07 11:20:05.94471 [DEBUG] switch_core_state_machine.c:398 (sofia/internal/8898801@il.cellb.it) Running State Change CS_NEW 2010-01-07 11:20:05.94471 [DEBUG] sofia.c:3289 Channel sofia/internal/8898801@il.cellb.it entering state [received][100] 2010-01-07 11:20:05.94471 [DEBUG] sofia.c:3296 Remote SDP: v=0 o=- 60424594 60424594 IN IP4 20.0.0.122 s=- c=IN IP4 87.68.244.32 t=0 0 m=audio 16482 RTP/AVP 0 2 4 8 18 96 97 98 101 a=rtpmap:0 PCMU/8000 a=rtpmap:2 G726-32/8000 a=rtpmap:4 G723/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729a/8000 a=rtpmap:96 G726-40/8000 a=rtpmap:97 G726-24/8000 a=rtpmap:98 G726-16/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:30 2010-01-07 11:20:05.94471 [DEBUG] switch_core_state_machine.c:404 (sofia/internal/8898801@il.cellb.it) State NEW 2010-01-07 11:20:05.94471 [DEBUG] sofia_glue.c:3071 Audio Codec Compare [PCMU:0:8000:30]/[PCMU:0:8000:20] 2010-01-07 11:20:05.94471 [DEBUG] sofia_glue.c:3071 Audio Codec Compare [PCMU:0:8000:30]/[PCMA:8:8000:20] 2010-01-07 11:20:05.94471 [DEBUG] sofia_glue.c:3071 Audio Codec Compare [PCMU:0:8000:30]/[GSM:3:8000:20] 2010-01-07 11:20:05.94471 [DEBUG] sofia_glue.c:3071 Audio Codec Compare [PCMU:0:8000:30]/[G722:9:8000:20] 2010-01-07 11:20:05.94471 [DEBUG] sofia_glue.c:3071 Audio Codec Compare [PCMU:0:8000:30]/[SPEEX:98:8000:20] 2010-01-07 11:20:05.94471 [DEBUG] sofia_glue.c:3071 Audio Codec Compare [PCMU:0:8000:30]/[SPEEX:99:16000:20] 2010-01-07 11:20:05.94471 [DEBUG] sofia_glue.c:3071 Audio Codec Compare [PCMU:0:8000:30]/[SPEEX:103:32000:20] 2010-01-07 11:20:05.94471 [DEBUG] sofia_glue.c:3119 Substituting codec PCMU@30i@8000h 2010-01-07 11:20:05.94471 [DEBUG] sofia_glue.c:2029 Set Codec sofia/internal/8898801@il.cellb.it PCMU/8000 30 ms 240 samples 2010-01-07 11:20:05.94471 [DEBUG] sofia_glue.c:3031 Set 2833 dtmf payload to 101 2010-01-07 11:20:05.94471 [DEBUG] sofia.c:3455 (sofia/internal/8898801@il.cellb.it) State Change CS_NEW -> CS_INIT 2010-01-07 11:20:05.94471 [DEBUG] switch_core_session.c:932 Send signal sofia/internal/8898801@il.cellb.it [BREAK] 2010-01-07 11:20:05.97885 [DEBUG] switch_core_state_machine.c:398 (sofia/internal/8898801@il.cellb.it) Running State Change CS_INIT 2010-01-07 11:20:05.97885 [DEBUG] switch_core_state_machine.c:481 (sofia/internal/8898801@il.cellb.it) State INIT 2010-01-07 11:20:05.97885 [DEBUG] mod_sofia.c:83 sofia/internal/8898801@il.cellb.it SOFIA INIT 2010-01-07 11:20:05.97885 [DEBUG] mod_sofia.c:111 (sofia/internal/8898801@il.cellb.it) State Change CS_INIT -> CS_ROUTING 2010-01-07 11:20:05.97885 [DEBUG] switch_core_session.c:932 Send signal sofia/internal/8898801@il.cellb.it [BREAK] 2010-01-07 11:20:05.97885 [DEBUG] switch_core_state_machine.c:481 (sofia/internal/8898801@il.cellb.it) State INIT going to sleep 2010-01-07 11:20:05.97885 [DEBUG] switch_core_state_machine.c:398 (sofia/internal/8898801@il.cellb.it) Running State Change CS_ROUTING 2010-01-07 11:20:05.97885 [DEBUG] switch_core_state_machine.c:484 (sofia/internal/8898801@il.cellb.it) State ROUTING 2010-01-07 11:20:05.97885 [DEBUG] mod_sofia.c:130 sofia/internal/8898801@il.cellb.it SOFIA ROUTING 2010-01-07 11:20:05.97885 [DEBUG] switch_core_state_machine.c:78 sofia/internal/8898801@il.cellb.it Standard ROUTING 2010-01-07 11:20:05.97885 [INFO] mod_dialplan_xml.c:315 Processing 8898801->036979700 in context default Dialplan: sofia/internal/8898801@il.cellb.it parsing [default->localxtens] continue=false Dialplan: sofia/internal/8898801@il.cellb.it Regex (FAIL) [localxtens] destination_number(036979700) =~ /^(0?9?88988[0-4][0-9])$/ break=on-false Dialplan: sofia/internal/8898801@il.cellb.it parsing [default->To_PSTN] continue=false Dialplan: sofia/internal/8898801@il.cellb.it Regex (PASS) [To_PSTN] destination_number(036979700) =~ /^(.*)$/ break=on-false Dialplan: sofia/internal/8898801@il.cellb.it Action bridge(openzap/1/a/036979700) 2010-01-07 11:20:05.98953 [DEBUG] switch_core_state_machine.c:114 (sofia/internal/8898801@il.cellb.it) State Change CS_ROUTING -> CS_EXECUTE 2010-01-07 11:20:05.98953 [DEBUG] switch_core_session.c:932 Send signal sofia/internal/8898801@il.cellb.it [BREAK] 2010-01-07 11:20:05.98953 [DEBUG] switch_core_state_machine.c:484 (sofia/internal/8898801@il.cellb.it) State ROUTING going to sleep 2010-01-07 11:20:05.98953 [DEBUG] switch_core_state_machine.c:398 (sofia/internal/8898801@il.cellb.it) Running State Change CS_EXECUTE 2010-01-07 11:20:05.98953 [DEBUG] switch_core_state_machine.c:491 (sofia/internal/8898801@il.cellb.it) State EXECUTE 2010-01-07 11:20:05.98953 [DEBUG] mod_sofia.c:173 sofia/internal/8898801@il.cellb.it SOFIA EXECUTE 2010-01-07 11:20:05.98953 [DEBUG] switch_core_state_machine.c:151 sofia/internal/8898801@il.cellb.it Standard EXECUTE EXECUTE sofia/internal/8898801@il.cellb.it bridge(openzap/1/a/036979700) 2010-01-07 11:20:05.98953 [DEBUG] mod_openzap.c:344 Set codec PCMA 20ms 2010-01-07 11:20:05.98953 [DEBUG] mod_openzap.c:1073 Connect outbound channel OpenZAP/1:1/036979700 2010-01-07 11:20:05.98953 [NOTICE] switch_channel.c:602 New Channel OpenZAP/1:1/036979700 [d75e7e8e-fb6d-11de-9911-b7e694ca6e0b] 2010-01-07 11:20:05.98953 [DEBUG] mod_openzap.c:1085 (OpenZAP/1:1/036979700) State Change CS_NEW -> CS_INIT 2010-01-07 11:20:05.98953 [DEBUG] switch_core_session.c:932 Send signal OpenZAP/1:1/036979700 [BREAK] 2010-01-07 11:20:05.98953 [DEBUG] ozmod_libpri.c:55 Changing state on 1:1 from DOWN to DIALING 2010-01-07 11:20:05.98953 [DEBUG] switch_core_state_machine.c:398 (OpenZAP/1:1/036979700) Running State Change CS_INIT 2010-01-07 11:20:05.98953 [DEBUG] switch_core_state_machine.c:481 (OpenZAP/1:1/036979700) State INIT 2010-01-07 11:20:05.98953 [DEBUG] mod_openzap.c:368 (OpenZAP/1:1/036979700) State Change CS_INIT -> CS_ROUTING 2010-01-07 11:20:05.98953 [DEBUG] switch_core_session.c:932 Send signal OpenZAP/1:1/036979700 [BREAK] 2010-01-07 11:20:05.98953 [DEBUG] switch_core_state_machine.c:481 (OpenZAP/1:1/036979700) State INIT going to sleep 2010-01-07 11:20:05.98953 [DEBUG] switch_core_state_machine.c:398 (OpenZAP/1:1/036979700) Running State Change CS_ROUTING 2010-01-07 11:20:05.98953 [DEBUG] switch_core_state_machine.c:484 (OpenZAP/1:1/036979700) State ROUTING 2010-01-07 11:20:05.100026 [DEBUG] mod_openzap.c:391 OpenZAP/1:1/036979700 CHANNEL ROUTING 2010-01-07 11:20:05.100026 [DEBUG] switch_ivr_originate.c:63 (OpenZAP/1:1/036979700) State Change CS_ROUTING -> CS_CONSUME_MEDIA 2010-01-07 11:20:05.100026 [DEBUG] switch_core_session.c:932 Send signal OpenZAP/1:1/036979700 [BREAK] 2010-01-07 11:20:05.100026 [DEBUG] switch_core_state_machine.c:484 (OpenZAP/1:1/036979700) State ROUTING going to sleep 2010-01-07 11:20:05.100026 [DEBUG] switch_core_state_machine.c:398 (OpenZAP/1:1/036979700) Running State Change CS_CONSUME_MEDIA 2010-01-07 11:20:05.100026 [DEBUG] switch_core_state_machine.c:503 (OpenZAP/1:1/036979700) State CONSUME_MEDIA 2010-01-07 11:20:05.155077 [DEBUG] ozmod_libpri.c:429 1:1 STATE [DIALING] 2010-01-07 11:20:05.155077 [DEBUG] ozmod_libpri.c:106 -- Making new call for cr 32784 2010-01-07 11:20:05.155077 [DEBUG] ozmod_libpri.c:106 -- Finally transmitting 43, since window opened up (0) 2010-01-07 11:20:05.155077 [DEBUG] ozmod_libpri.c:106 > [ 00 01 56 6c 08 02 00 10 05 04 03 80 90 a3 18 03 a1 83 81 6c 09 00 81 38 38 39 38 38 30 31 70 0a 80 30 33 36 39 37 39 37 30 30 74 0a 00 01 8f 38 38 39 38 38 30 31 a1 ] 2010-01-07 11:20:05.155077 [DEBUG] ozmod_libpri.c:106 > Informational frame: 2010-01-07 11:20:05.155077 [DEBUG] ozmod_libpri.c:106 > SAPI: 00 C/R: 0 EA: 0 > TEI: 000 EA: 1 2010-01-07 11:20:05.155077 [DEBUG] ozmod_libpri.c:106 > N(S): 043 0: 0 > N(R): 054 P: 0 > 51 bytes of data 2010-01-07 11:20:05.155077 [DEBUG] ozmod_libpri.c:106 Stopping T_203 timer 2010-01-07 11:20:05.155077 [DEBUG] ozmod_libpri.c:106 Starting T_200 timer 2010-01-07 11:20:05.155077 [DEBUG] ozmod_libpri.c:106 -- Restarting T200 timer 2010-01-07 11:20:05.155077 [DEBUG] ozmod_libpri.c:106 > Protocol Discriminator: Q.931 (8) len=51 2010-01-07 11:20:05.155077 [DEBUG] ozmod_libpri.c:106 > Call Ref: len= 2 (reference 16/0x10) (Originator) 2010-01-07 11:20:05.155077 [DEBUG] ozmod_libpri.c:106 > Message type: SETUP (5) 2010-01-07 11:20:05.155077 [DEBUG] ozmod_libpri.c:106 > [04 03 80 90 a3] 2010-01-07 11:20:05.155077 [DEBUG] ozmod_libpri.c:106 > Bearer Capability (len= 5) [ Ext: 1 Q.931 Std: 0 Info transfer capability: Speech (0) 2010-01-07 11:20:05.155077 [DEBUG] ozmod_libpri.c:106 > Ext: 1 Trans mode/rate: 64kbps, circuit-mode (16) 2010-01-07 11:20:05.155077 [DEBUG] ozmod_libpri.c:106 > User information layer 1: A-Law (35) 2010-01-07 11:20:05.155077 [DEBUG] ozmod_libpri.c:106 > [18 03 a1 83 81] 2010-01-07 11:20:05.155077 [DEBUG] ozmod_libpri.c:106 > Channel ID (len= 5) [ Ext: 1 IntID: Implicit PRI Spare: 0 Preferred Dchan: 0 2010-01-07 11:20:05.155077 [DEBUG] ozmod_libpri.c:106 > ChanSel: As indicated in following octets 2010-01-07 11:20:05.155077 [DEBUG] ozmod_libpri.c:106 > Ext: 1 Coding: 0 Number Specified Channel Type: 3 2010-01-07 11:20:05.155077 [DEBUG] ozmod_libpri.c:106 > Ext: 1 Channel: 1 ] 2010-01-07 11:20:05.155077 [DEBUG] ozmod_libpri.c:106 > [6c 09 00 81 38 38 39 38 38 30 31] 2010-01-07 11:20:05.155077 [DEBUG] ozmod_libpri.c:106 > Calling Number (len=11) [ Ext: 0 TON: Unknown Number Type (0) NPI: Unknown Number Plan (0) 2010-01-07 11:20:05.155077 [DEBUG] ozmod_libpri.c:106 > Presentation: Presentation permitted, user number passed network screening (1) '8898801' ] 2010-01-07 11:20:05.155077 [DEBUG] ozmod_libpri.c:106 > [70 0a 80 30 33 36 39 37 39 37 30 30] 2010-01-07 11:20:05.155077 [DEBUG] ozmod_libpri.c:106 > Called Number (len=12) [ Ext: 1 TON: Unknown Number Type (0) NPI: Unknown Number Plan (0) '036979700' ] 2010-01-07 11:20:05.155077 [DEBUG] ozmod_libpri.c:106 > [74 0a 00 01 8f 38 38 39 38 38 30 31] 2010-01-07 11:20:05.155077 [DEBUG] ozmod_libpri.c:106 > Redirecting Number (len=12) [ Ext: 0 TON: Unknown Number Type (0) NPI: Unknown Number Plan (0)2010-01-07 11:20:05.155077 [DEBUG] ozmod_libpri.c:106 > Ext: 0 Presentation: Presentation permitted, user number passed network screening (1)2010-01-07 11:20:05.155077 [DEBUG] ozmod_libpri.c:106 > Ext: 1 Reason: Forwarded unconditionally (15)2010-01-07 11:20:05.155077 [DEBUG] ozmod_libpri.c:106 '8898801' ] 2010-01-07 11:20:05.155077 [DEBUG] ozmod_libpri.c:106 > [a1] 2010-01-07 11:20:05.155077 [DEBUG] ozmod_libpri.c:106 > Sending Complete (len= 1) 2010-01-07 11:20:05.155077 [DEBUG] ozmod_libpri.c:106 q931.c:3134 q931_setup: call 32784 on channel 1 enters state 1 (Call Initiated) 2010-01-07 11:20:05.168170 [DEBUG] ozmod_libpri.c:106 < [ 00 01 01 58 ] 2010-01-07 11:20:05.168170 [DEBUG] ozmod_libpri.c:106 < Supervisory frame: 2010-01-07 11:20:05.168170 [DEBUG] ozmod_libpri.c:106 < SAPI: 00 C/R: 0 EA: 0 < TEI: 000 EA: 1 2010-01-07 11:20:05.168170 [DEBUG] ozmod_libpri.c:106 < Zero: 0 S: 0 01: 1 [ RR (receive ready) ] < N(R): 044 P/F: 0 < 0 bytes of data 2010-01-07 11:20:05.168170 [DEBUG] ozmod_libpri.c:106 Handling message for SAPI/TEI=0/0 2010-01-07 11:20:05.168170 [DEBUG] ozmod_libpri.c:106 -- ACKing all packets from 42 to (but not including) 44 2010-01-07 11:20:05.168170 [DEBUG] ozmod_libpri.c:106 -- ACKing packet 43, new txqueue is -1 (-1 means empty) 2010-01-07 11:20:05.168170 [DEBUG] ozmod_libpri.c:106 -- Since there was nothing left, stopping T200 counter 2010-01-07 11:20:05.168170 [DEBUG] ozmod_libpri.c:106 -- Nothing left, starting T203 counter 2010-01-07 11:20:05.168170 [DEBUG] ozmod_libpri.c:106 -- Restarting T203 timer 2010-01-07 11:20:05.289206 [DEBUG] ozmod_libpri.c:106 < [ 02 01 6c 58 08 02 80 10 02 18 03 a9 83 81 ] 2010-01-07 11:20:05.289206 [DEBUG] ozmod_libpri.c:106 < Informational frame: 2010-01-07 11:20:05.289206 [DEBUG] ozmod_libpri.c:106 < SAPI: 00 C/R: 1 EA: 0 < TEI: 000 EA: 1 2010-01-07 11:20:05.289206 [DEBUG] ozmod_libpri.c:106 < N(S): 054 0: 0 < N(R): 044 P: 0 < 10 bytes of data 2010-01-07 11:20:05.289206 [DEBUG] ozmod_libpri.c:106 Handling message for SAPI/TEI=0/0 2010-01-07 11:20:05.289206 [DEBUG] ozmod_libpri.c:106 -- ACKing all packets from 43 to (but not including) 44 2010-01-07 11:20:05.289206 [DEBUG] ozmod_libpri.c:106 -- Since there was nothing left, stopping T200 counter 2010-01-07 11:20:05.289206 [DEBUG] ozmod_libpri.c:106 -- Stopping T203 counter since we got an ACK 2010-01-07 11:20:05.289206 [DEBUG] ozmod_libpri.c:106 -- Nothing left, starting T203 counter 2010-01-07 11:20:05.289206 [DEBUG] ozmod_libpri.c:106 < Protocol Discriminator: Q.931 (8) len=10 2010-01-07 11:20:05.289206 [DEBUG] ozmod_libpri.c:106 < Call Ref: len= 2 (reference 16/0x10) (Terminator) 2010-01-07 11:20:05.289206 [DEBUG] ozmod_libpri.c:106 < Message type: CALL PROCEEDING (2) 2010-01-07 11:20:05.289206 [DEBUG] ozmod_libpri.c:106 < [18 03 a9 83 81] 2010-01-07 11:20:05.289206 [DEBUG] ozmod_libpri.c:106 < Channel ID (len= 5) [ Ext: 1 IntID: Implicit PRI Spare: 0 Exclusive Dchan: 0 2010-01-07 11:20:05.289206 [DEBUG] ozmod_libpri.c:106 < ChanSel: As indicated in following octets 2010-01-07 11:20:05.289206 [DEBUG] ozmod_libpri.c:106 < Ext: 1 Coding: 0 Number Specified Channel Type: 3 2010-01-07 11:20:05.289206 [DEBUG] ozmod_libpri.c:106 < Ext: 1 Channel: 1 ] 2010-01-07 11:20:05.289206 [DEBUG] ozmod_libpri.c:106 -- Processing IE 24 (cs0, Channel Identification) 2010-01-07 11:20:05.289206 [DEBUG] ozmod_libpri.c:106 q931.c:3683 q931_receive: call 32784 on channel 1 enters state 3 (Outgoing call Proceeding) 2010-01-07 11:20:05.289206 [DEBUG] ozmod_libpri.c:106 Sending Receiver Ready (55) 2010-01-07 11:20:05.289206 [DEBUG] ozmod_libpri.c:106 > [ 02 01 01 6e ] 2010-01-07 11:20:05.289206 [DEBUG] ozmod_libpri.c:106 > Supervisory frame: 2010-01-07 11:20:05.289206 [DEBUG] ozmod_libpri.c:106 > SAPI: 00 C/R: 1 EA: 0 > TEI: 000 EA: 1 2010-01-07 11:20:05.289206 [DEBUG] ozmod_libpri.c:106 > Zero: 0 S: 0 01: 1 [ RR (receive ready) ] > N(R): 055 P/F: 0 > 0 bytes of data 2010-01-07 11:20:05.289206 [DEBUG] ozmod_libpri.c:106 -- Restarting T203 timer 2010-01-07 11:20:05.289206 [DEBUG] ozmod_libpri.c:703 -- Proceeding on channel 1:1 2010-01-07 11:20:05.289206 [DEBUG] ozmod_libpri.c:704 Changing state on 1:1 from DIALING to PROGRESS_MEDIA 2010-01-07 11:20:05.289206 [DEBUG] ozmod_libpri.c:429 1:1 STATE [PROGRESS_MEDIA] 2010-01-07 11:20:05.289206 [DEBUG] mod_openzap.c:1481 got clear channel sig [PROGRESS_MEDIA] 2010-01-07 11:20:05.289206 [NOTICE] mod_openzap.c:1522 Pre-Answer OpenZAP/1:1/036979700! 2010-01-07 11:20:05.289206 [DEBUG] switch_channel.c:1778 Send signal sofia/internal/8898801@il.cellb.it [BREAK] 2010-01-07 11:20:05.289206 [DEBUG] switch_ivr_originate.c:2017 sofia/internal/8898801@il.cellb.it receive message [PROGRESS] 2010-01-07 11:20:05.289206 [INFO] switch_ivr_originate.c:2017 Sending early media 2010-01-07 11:20:05.290302 [DEBUG] sofia_glue.c:2263 AUDIO RTP [sofia/internal/8898801@il.cellb.it] 81.218.11.30 port 28614 -> 87.68.244.32 port 16482 codec: 0 ms: 30 2010-01-07 11:20:05.290302 [DEBUG] switch_rtp.c:1138 Starting timer [soft] 240 bytes per 30ms 2010-01-07 11:20:05.291378 [INFO] mod_sofia.c:1506 Ring SDP: v=0 o=FreeSWITCH 1262827391 1262827392 IN IP4 81.218.11.30 s=FreeSWITCH c=IN IP4 81.218.11.30 t=0 0 m=audio 28614 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:30 a=sendrecv 2010-01-07 11:20:05.291378 [NOTICE] mod_sofia.c:1509 Pre-Answer sofia/internal/8898801@il.cellb.it! 2010-01-07 11:20:05.291378 [DEBUG] switch_core_session.c:630 Send signal sofia/internal/8898801@il.cellb.it [BREAK] 2010-01-07 11:20:05.291378 [DEBUG] sofia.c:3289 Channel sofia/internal/8898801@il.cellb.it entering state [early][183] 2010-01-07 11:20:05.291378 [DEBUG] switch_ivr_originate.c:2061 Originate Resulted in Success: [OpenZAP/1:1/036979700] 2010-01-07 11:20:05.291378 [DEBUG] switch_channel.c:182 OpenZAP/1:1/036979700 receive message [AUDIO_SYNC] 2010-01-07 11:20:05.291378 [DEBUG] switch_channel.c:182 sofia/internal/8898801@il.cellb.it receive message [AUDIO_SYNC] 2010-01-07 11:20:05.291378 [DEBUG] switch_ivr_bridge.c:889 OpenZAP/1:1/036979700 receive message [BRIDGE] 2010-01-07 11:20:05.291378 [DEBUG] switch_core_session.c:630 Send signal OpenZAP/1:1/036979700 [BREAK] 2010-01-07 11:20:05.291378 [DEBUG] switch_ivr_bridge.c:896 sofia/internal/8898801@il.cellb.it receive message [BRIDGE] 2010-01-07 11:20:05.291378 [DEBUG] switch_core_session.c:630 Send signal sofia/internal/8898801@il.cellb.it [BREAK] 2010-01-07 11:20:05.291378 [DEBUG] switch_ivr_bridge.c:940 (OpenZAP/1:1/036979700) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA 2010-01-07 11:20:05.291378 [DEBUG] switch_core_session.c:932 Send signal OpenZAP/1:1/036979700 [BREAK] 2010-01-07 11:20:05.311196 [DEBUG] switch_core_state_machine.c:503 (OpenZAP/1:1/036979700) State CONSUME_MEDIA going to sleep 2010-01-07 11:20:05.311196 [DEBUG] switch_core_state_machine.c:398 (OpenZAP/1:1/036979700) Running State Change CS_EXCHANGE_MEDIA 2010-01-07 11:20:05.311196 [DEBUG] switch_core_state_machine.c:494 (OpenZAP/1:1/036979700) State EXCHANGE_MEDIA 2010-01-07 11:20:05.311196 [DEBUG] mod_openzap.c:525 CHANNEL EXCHANGE_MEDIA 2010-01-07 11:20:05.331041 [DEBUG] switch_core_io.c:649 sofia/internal/8898801@il.cellb.it receive message [TRANSCODING_NECESSARY] 2010-01-07 11:20:05.331041 [DEBUG] switch_core_io.c:892 Engaging Write Buffer at 480 bytes to accommodate 320->480 2010-01-07 11:20:05.451500 [DEBUG] switch_core_io.c:649 OpenZAP/1:1/036979700 receive message [TRANSCODING_NECESSARY] 2010-01-07 11:20:05.451500 [DEBUG] switch_core_io.c:892 Engaging Write Buffer at 320 bytes to accommodate 480->320 2010-01-07 11:20:06.438737 [DEBUG] ozmod_libpri.c:106 < [ 02 01 6e 58 08 02 80 10 45 08 02 80 81 1e 02 80 88 ] 2010-01-07 11:20:06.438737 [DEBUG] ozmod_libpri.c:106 < Informational frame: 2010-01-07 11:20:06.438737 [DEBUG] ozmod_libpri.c:106 < SAPI: 00 C/R: 1 EA: 0 < TEI: 000 EA: 1 2010-01-07 11:20:06.438737 [DEBUG] ozmod_libpri.c:106 < N(S): 055 0: 0 < N(R): 044 P: 0 < 13 bytes of data 2010-01-07 11:20:06.438737 [DEBUG] ozmod_libpri.c:106 Handling message for SAPI/TEI=0/0 2010-01-07 11:20:06.438737 [DEBUG] ozmod_libpri.c:106 -- ACKing all packets from 43 to (but not including) 44 2010-01-07 11:20:06.438737 [DEBUG] ozmod_libpri.c:106 -- Since there was nothing left, stopping T200 counter 2010-01-07 11:20:06.438737 [DEBUG] ozmod_libpri.c:106 -- Stopping T203 counter since we got an ACK 2010-01-07 11:20:06.438737 [DEBUG] ozmod_libpri.c:106 -- Nothing left, starting T203 counter 2010-01-07 11:20:06.438737 [DEBUG] ozmod_libpri.c:106 < Protocol Discriminator: Q.931 (8) len=13 2010-01-07 11:20:06.438737 [DEBUG] ozmod_libpri.c:106 < Call Ref: len= 2 (reference 16/0x10) (Terminator) 2010-01-07 11:20:06.438737 [DEBUG] ozmod_libpri.c:106 < Message type: DISCONNECT (69) 2010-01-07 11:20:06.438737 [DEBUG] ozmod_libpri.c:106 < [08 02 80 81] 2010-01-07 11:20:06.438737 [DEBUG] ozmod_libpri.c:106 < Cause (len= 4) [ Ext: 1 Coding: CCITT (ITU) standard (0) Spare: 0 Location: User (0) 2010-01-07 11:20:06.438737 [DEBUG] ozmod_libpri.c:106 < Ext: 1 Cause: Unallocated (unassigned) number (1), class = Normal Event (0) ] 2010-01-07 11:20:06.438737 [DEBUG] ozmod_libpri.c:106 < [1e 02 80 88] 2010-01-07 11:20:06.438737 [DEBUG] ozmod_libpri.c:106 < Progress Indicator (len= 4) [ Ext: 1 Coding: CCITT (ITU) standard (0) 0: 0 Location: User (0) 2010-01-07 11:20:06.438737 [DEBUG] ozmod_libpri.c:106 < Ext: 1 Progress Description: Inband information or appropriate pattern now available. (8) ] 2010-01-07 11:20:06.438737 [DEBUG] ozmod_libpri.c:106 -- Processing IE 8 (cs0, Cause) 2010-01-07 11:20:06.438737 [DEBUG] ozmod_libpri.c:106 -- Processing IE 30 (cs0, Progress Indicator) 2010-01-07 11:20:06.438737 [DEBUG] ozmod_libpri.c:106 q931.c:3826 q931_receive: call 32784 on channel 1 enters state 12 (Disconnect Indication) 2010-01-07 11:20:06.438737 [DEBUG] ozmod_libpri.c:106 Sending Receiver Ready (56) 2010-01-07 11:20:06.438737 [DEBUG] ozmod_libpri.c:106 > [ 02 01 01 70 ] 2010-01-07 11:20:06.438737 [DEBUG] ozmod_libpri.c:106 > Supervisory frame: 2010-01-07 11:20:06.438737 [DEBUG] ozmod_libpri.c:106 > SAPI: 00 C/R: 1 EA: 0 > TEI: 000 EA: 1 2010-01-07 11:20:06.438737 [DEBUG] ozmod_libpri.c:106 > Zero: 0 S: 0 01: 1 [ RR (receive ready) ] > N(R): 056 P/F: 0 > 0 bytes of data 2010-01-07 11:20:06.438737 [DEBUG] ozmod_libpri.c:106 -- Restarting T203 timer 2010-01-07 11:20:06.438737 [DEBUG] ozmod_libpri.c:650 -- Hangup on channel 1:1 2010-01-07 11:20:06.438737 [DEBUG] ozmod_libpri.c:106 NEW_HANGUP DEBUG: Calling q931_hangup, ourstate Disconnect Indication, peerstate Disconnect Request 2010-01-07 11:20:06.438737 [DEBUG] ozmod_libpri.c:106 q931.c:2967 q931_release: call 32784 on channel 1 enters state 19 (Release Request) 2010-01-07 11:20:06.438737 [DEBUG] ozmod_libpri.c:106 -- Finally transmitting 44, since window opened up (0) 2010-01-07 11:20:06.438737 [DEBUG] ozmod_libpri.c:106 > [ 00 01 58 70 08 02 00 10 4d ] 2010-01-07 11:20:06.438737 [DEBUG] ozmod_libpri.c:106 > Informational frame: 2010-01-07 11:20:06.438737 [DEBUG] ozmod_libpri.c:106 > SAPI: 00 C/R: 0 EA: 0 > TEI: 000 EA: 1 2010-01-07 11:20:06.438737 [DEBUG] ozmod_libpri.c:106 > N(S): 044 0: 0 > N(R): 056 P: 0 > 5 bytes of data 2010-01-07 11:20:06.438737 [DEBUG] ozmod_libpri.c:106 Stopping T_203 timer 2010-01-07 11:20:06.438737 [DEBUG] ozmod_libpri.c:106 Starting T_200 timer 2010-01-07 11:20:06.438737 [DEBUG] ozmod_libpri.c:106 -- Restarting T200 timer 2010-01-07 11:20:06.438737 [DEBUG] ozmod_libpri.c:106 > Protocol Discriminator: Q.931 (8) len=5 2010-01-07 11:20:06.438737 [DEBUG] ozmod_libpri.c:106 > Call Ref: len= 2 (reference 16/0x10) (Originator) 2010-01-07 11:20:06.438737 [DEBUG] ozmod_libpri.c:106 > Message type: RELEASE (77) 2010-01-07 11:20:06.438737 [DEBUG] ozmod_libpri.c:106 NEW_HANGUP DEBUG: Destroying the call, ourstate Release Request, peerstate Disconnect Request 2010-01-07 11:20:06.438737 [DEBUG] ozmod_libpri.c:654 Changing state on 1:1 from PROGRESS_MEDIA to TERMINATING 2010-01-07 11:20:06.438737 [DEBUG] ozmod_libpri.c:429 1:1 STATE [TERMINATING] 2010-01-07 11:20:06.438737 [DEBUG] mod_openzap.c:1481 got clear channel sig [STOP] 2010-01-07 11:20:06.438737 [NOTICE] mod_openzap.c:1500 Hangup OpenZAP/1:1/036979700 [CS_EXCHANGE_MEDIA] [UNALLOCATED_NUMBER] 2010-01-07 11:20:06.438737 [DEBUG] switch_channel.c:1683 Send signal OpenZAP/1:1/036979700 [KILL] 2010-01-07 11:20:06.438737 [DEBUG] switch_core_session.c:932 Send signal OpenZAP/1:1/036979700 [BREAK] 2010-01-07 11:20:06.438737 [DEBUG] ozmod_libpri.c:583 Changing state on 1:1 from TERMINATING to DOWN 2010-01-07 11:20:06.447060 [DEBUG] ozmod_libpri.c:106 < [ 00 01 01 5a ] 2010-01-07 11:20:06.447060 [DEBUG] ozmod_libpri.c:106 < Supervisory frame: 2010-01-07 11:20:06.447060 [DEBUG] ozmod_libpri.c:106 < SAPI: 00 C/R: 0 EA: 0 < TEI: 000 EA: 1 2010-01-07 11:20:06.447060 [DEBUG] ozmod_libpri.c:106 < Zero: 0 S: 0 01: 1 [ RR (receive ready) ] < N(R): 045 P/F: 0 < 0 bytes of data 2010-01-07 11:20:06.447060 [DEBUG] ozmod_libpri.c:106 Handling message for SAPI/TEI=0/0 2010-01-07 11:20:06.447060 [DEBUG] ozmod_libpri.c:106 -- ACKing all packets from 43 to (but not including) 45 2010-01-07 11:20:06.447060 [DEBUG] ozmod_libpri.c:106 -- ACKing packet 44, new txqueue is -1 (-1 means empty) 2010-01-07 11:20:06.447060 [DEBUG] ozmod_libpri.c:106 -- Since there was nothing left, stopping T200 counter 2010-01-07 11:20:06.447060 [DEBUG] ozmod_libpri.c:106 -- Nothing left, starting T203 counter 2010-01-07 11:20:06.447060 [DEBUG] ozmod_libpri.c:106 -- Restarting T203 timer 2010-01-07 11:20:06.447060 [DEBUG] ozmod_libpri.c:429 1:1 STATE [DOWN] 2010-01-07 11:20:06.447060 [DEBUG] zap_io.c:1200 channel done 1:1 2010-01-07 11:20:06.450660 [DEBUG] switch_ivr_bridge.c:452 BRIDGE THREAD DONE [OpenZAP/1:1/036979700] 2010-01-07 11:20:06.450660 [DEBUG] switch_ivr_bridge.c:454 Send signal sofia/internal/8898801@il.cellb.it [BREAK] 2010-01-07 11:20:06.450660 [DEBUG] switch_core_state_machine.c:494 (OpenZAP/1:1/036979700) State EXCHANGE_MEDIA going to sleep 2010-01-07 11:20:06.450660 [DEBUG] switch_core_state_machine.c:398 (OpenZAP/1:1/036979700) Running State Change CS_HANGUP 2010-01-07 11:20:06.450660 [DEBUG] switch_core_state_machine.c:434 (OpenZAP/1:1/036979700) State HANGUP 2010-01-07 11:20:06.450660 [DEBUG] mod_openzap.c:486 OpenZAP/1:1/036979700 CHANNEL HANGUP 2010-01-07 11:20:06.450660 [DEBUG] switch_core_state_machine.c:46 OpenZAP/1:1/036979700 Standard HANGUP, cause: UNALLOCATED_NUMBER 2010-01-07 11:20:06.450660 [DEBUG] switch_core_state_machine.c:434 (OpenZAP/1:1/036979700) State HANGUP going to sleep 2010-01-07 11:20:06.450660 [DEBUG] switch_core_state_machine.c:476 (OpenZAP/1:1/036979700) State Change CS_HANGUP -> CS_REPORTING 2010-01-07 11:20:06.450660 [DEBUG] switch_core_session.c:932 Send signal OpenZAP/1:1/036979700 [BREAK] 2010-01-07 11:20:06.450660 [DEBUG] switch_core_state_machine.c:398 (OpenZAP/1:1/036979700) Running State Change CS_REPORTING 2010-01-07 11:20:06.450660 [DEBUG] switch_core_state_machine.c:612 (OpenZAP/1:1/036979700) State REPORTING 2010-01-07 11:20:06.450660 [DEBUG] switch_core_state_machine.c:53 OpenZAP/1:1/036979700 Standard REPORTING, cause: UNALLOCATED_NUMBER 2010-01-07 11:20:06.450660 [DEBUG] switch_core_state_machine.c:612 (OpenZAP/1:1/036979700) State REPORTING going to sleep 2010-01-07 11:20:06.450660 [DEBUG] switch_core_state_machine.c:411 (OpenZAP/1:1/036979700) State Change CS_REPORTING -> CS_DESTROY 2010-01-07 11:20:06.450660 [DEBUG] switch_core_session.c:1068 Session 32 (OpenZAP/1:1/036979700) Locked, Waiting on external entities 2010-01-07 11:20:06.502306 [NOTICE] switch_ivr_bridge.c:419 Hangup sofia/internal/8898801@il.cellb.it [CS_EXECUTE] [UNALLOCATED_NUMBER] 2010-01-07 11:20:06.502306 [DEBUG] switch_channel.c:1683 Send signal sofia/internal/8898801@il.cellb.it [KILL] 2010-01-07 11:20:06.502306 [DEBUG] switch_core_session.c:932 Send signal sofia/internal/8898801@il.cellb.it [BREAK] 2010-01-07 11:20:06.502306 [DEBUG] switch_ivr_bridge.c:452 BRIDGE THREAD DONE [sofia/internal/8898801@il.cellb.it] 2010-01-07 11:20:06.502306 [DEBUG] switch_ivr_bridge.c:454 Send signal OpenZAP/1:1/036979700 [BREAK] 2010-01-07 11:20:06.502306 [NOTICE] switch_core_session.c:1086 Session 32 (OpenZAP/1:1/036979700) Ended 2010-01-07 11:20:06.502306 [NOTICE] switch_core_session.c:1088 Close Channel OpenZAP/1:1/036979700 [CS_DESTROY] 2010-01-07 11:20:06.502306 [DEBUG] switch_core_state_machine.c:564 (OpenZAP/1:1/036979700) State DESTROY 2010-01-07 11:20:06.502306 [DEBUG] switch_core_state_machine.c:60 OpenZAP/1:1/036979700 Standard DESTROY 2010-01-07 11:20:06.502306 [DEBUG] switch_core_state_machine.c:564 (OpenZAP/1:1/036979700) State DESTROY going to sleep 2010-01-07 11:20:06.502306 [DEBUG] switch_core_state_machine.c:491 (sofia/internal/8898801@il.cellb.it) State EXECUTE going to sleep 2010-01-07 11:20:06.502306 [DEBUG] switch_core_state_machine.c:398 (sofia/internal/8898801@il.cellb.it) Running State Change CS_HANGUP 2010-01-07 11:20:06.502306 [DEBUG] switch_core_state_machine.c:434 (sofia/internal/8898801@il.cellb.it) State HANGUP 2010-01-07 11:20:06.502306 [DEBUG] mod_sofia.c:338 Channel sofia/internal/8898801@il.cellb.it hanging up, cause: UNALLOCATED_NUMBER 2010-01-07 11:20:06.502306 [DEBUG] mod_sofia.c:417 Responding to INVITE with: 404 2010-01-07 11:20:06.503555 [DEBUG] switch_core_state_machine.c:46 sofia/internal/8898801@il.cellb.it Standard HANGUP, cause: UNALLOCATED_NUMBER 2010-01-07 11:20:06.503555 [DEBUG] switch_core_state_machine.c:434 (sofia/internal/8898801@il.cellb.it) State HANGUP going to sleep 2010-01-07 11:20:06.503555 [DEBUG] switch_core_state_machine.c:476 (sofia/internal/8898801@il.cellb.it) State Change CS_HANGUP -> CS_REPORTING 2010-01-07 11:20:06.503555 [DEBUG] switch_core_session.c:932 Send signal sofia/internal/8898801@il.cellb.it [BREAK] 2010-01-07 11:20:06.503555 [DEBUG] switch_core_state_machine.c:398 (sofia/internal/8898801@il.cellb.it) Running State Change CS_REPORTING 2010-01-07 11:20:06.503555 [DEBUG] switch_core_state_machine.c:612 (sofia/internal/8898801@il.cellb.it) State REPORTING 2010-01-07 11:20:06.503555 [DEBUG] switch_core_state_machine.c:53 sofia/internal/8898801@il.cellb.it Standard REPORTING, cause: UNALLOCATED_NUMBER 2010-01-07 11:20:06.503555 [DEBUG] switch_core_state_machine.c:612 (sofia/internal/8898801@il.cellb.it) State REPORTING going to sleep 2010-01-07 11:20:06.503555 [DEBUG] switch_core_state_machine.c:411 (sofia/internal/8898801@il.cellb.it) State Change CS_REPORTING -> CS_DESTROY 2010-01-07 11:20:06.503555 [DEBUG] switch_core_session.c:1068 Session 31 (sofia/internal/8898801@il.cellb.it) Locked, Waiting on external entities 2010-01-07 11:20:06.503555 [NOTICE] switch_core_session.c:1086 Session 31 (sofia/internal/8898801@il.cellb.it) Ended 2010-01-07 11:20:06.503555 [NOTICE] switch_core_session.c:1088 Close Channel sofia/internal/8898801@il.cellb.it [CS_DESTROY] 2010-01-07 11:20:06.503555 [DEBUG] switch_core_state_machine.c:564 (sofia/internal/8898801@il.cellb.it) State DESTROY 2010-01-07 11:20:06.503555 [DEBUG] mod_sofia.c:255 sofia/internal/8898801@il.cellb.it SOFIA DESTROY 2010-01-07 11:20:06.503555 [DEBUG] switch_core_state_machine.c:60 sofia/internal/8898801@il.cellb.it Standard DESTROY 2010-01-07 11:20:06.503555 [DEBUG] switch_core_state_machine.c:564 (sofia/internal/8898801@il.cellb.it) State DESTROY going to sleep 2010-01-07 11:20:06.538132 [DEBUG] ozmod_libpri.c:106 < [ 02 01 70 5a 08 02 80 10 5a 08 03 80 e0 08 ] 2010-01-07 11:20:06.538132 [DEBUG] ozmod_libpri.c:106 < Informational frame: 2010-01-07 11:20:06.538132 [DEBUG] ozmod_libpri.c:106 < SAPI: 00 C/R: 1 EA: 0 < TEI: 000 EA: 1 2010-01-07 11:20:06.538132 [DEBUG] ozmod_libpri.c:106 < N(S): 056 0: 0 < N(R): 045 P: 0 < 10 bytes of data 2010-01-07 11:20:06.538132 [DEBUG] ozmod_libpri.c:106 Handling message for SAPI/TEI=0/0 2010-01-07 11:20:06.538132 [DEBUG] ozmod_libpri.c:106 -- ACKing all packets from 44 to (but not including) 45 2010-01-07 11:20:06.538132 [DEBUG] ozmod_libpri.c:106 -- Since there was nothing left, stopping T200 counter 2010-01-07 11:20:06.538132 [DEBUG] ozmod_libpri.c:106 -- Stopping T203 counter since we got an ACK 2010-01-07 11:20:06.538132 [DEBUG] ozmod_libpri.c:106 -- Nothing left, starting T203 counter 2010-01-07 11:20:06.538132 [DEBUG] ozmod_libpri.c:106 < Protocol Discriminator: Q.931 (8) len=10 2010-01-07 11:20:06.538132 [DEBUG] ozmod_libpri.c:106 < Call Ref: len= 2 (reference 16/0x10) (Terminator) 2010-01-07 11:20:06.538132 [DEBUG] ozmod_libpri.c:106 < Message type: RELEASE COMPLETE (90) 2010-01-07 11:20:06.538132 [DEBUG] ozmod_libpri.c:106 < [08 03 80 e0 08] 2010-01-07 11:20:06.538132 [DEBUG] ozmod_libpri.c:106 < Cause (len= 5) [ Ext: 1 Coding: CCITT (ITU) standard (0) Spare: 0 Location: User (0) 2010-01-07 11:20:06.538132 [DEBUG] ozmod_libpri.c:106 < Ext: 1 Cause: Mandatory information element is missing (96), class = Protocol Error (e.g. unknown message) (6) ] 2010-01-07 11:20:06.538132 [DEBUG] ozmod_libpri.c:106 < Cause data 1: 08 (8) 2010-01-07 11:20:06.538132 [DEBUG] ozmod_libpri.c:106 -- Making new call for cr 32784 2010-01-07 11:20:06.538132 [DEBUG] ozmod_libpri.c:106 -- Processing IE 8 (cs0, Cause) 2010-01-07 11:20:06.538132 [DEBUG] ozmod_libpri.c:106 NEW_HANGUP DEBUG: Calling q931_hangup, ourstate Null, peerstate Null 2010-01-07 11:20:06.538132 [DEBUG] ozmod_libpri.c:106 NEW_HANGUP DEBUG: Destroying the call, ourstate Null, peerstate Null 2010-01-07 11:20:06.538132 [DEBUG] ozmod_libpri.c:106 Sending Receiver Ready (57) 2010-01-07 11:20:06.538132 [DEBUG] ozmod_libpri.c:106 > [ 02 01 01 72 ] 2010-01-07 11:20:06.538132 [DEBUG] ozmod_libpri.c:106 > Supervisory frame: 2010-01-07 11:20:06.538132 [DEBUG] ozmod_libpri.c:106 > SAPI: 00 C/R: 1 EA: 0 > TEI: 000 EA: 1 2010-01-07 11:20:06.538132 [DEBUG] ozmod_libpri.c:106 > Zero: 0 S: 0 01: 1 [ RR (receive ready) ] > N(R): 057 P/F: 0 > 0 bytes of data 2010-01-07 11:20:06.538132 [DEBUG] ozmod_libpri.c:106 -- Restarting T203 timer