Skip to content

Instantly share code, notes, and snippets.

@zuriby

zuriby/libpri-openzap-bridge-outbound-calls-not-working.cs

Created January 7, 2010 09:39
Show Gist options
  • Save zuriby/271113 to your computer and use it in GitHub Desktop.
Save zuriby/271113 to your computer and use it in GitHub Desktop.
Download ZIP
Raw
libpri-openzap-bridge-outbound-calls-not-working.cs
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/[email protected] [d75dfa40-fb6d-11de-9911-b7e694ca6e0b]
2010-01-07 11:20:05.94471 [DEBUG] switch_core_state_machine.c:398 (sofia/internal/[email protected]) Running State Change CS_NEW
2010-01-07 11:20:05.94471 [DEBUG] sofia.c:3289 Channel sofia/internal/[email protected] 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/[email protected]) 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/[email protected] 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/[email protected]) State Change CS_NEW -> CS_INIT
2010-01-07 11:20:05.94471 [DEBUG] switch_core_session.c:932 Send signal sofia/internal/[email protected] [BREAK]
2010-01-07 11:20:05.97885 [DEBUG] switch_core_state_machine.c:398 (sofia/internal/[email protected]) Running State Change CS_INIT
2010-01-07 11:20:05.97885 [DEBUG] switch_core_state_machine.c:481 (sofia/internal/[email protected]) State INIT
2010-01-07 11:20:05.97885 [DEBUG] mod_sofia.c:83 sofia/internal/[email protected] SOFIA INIT
2010-01-07 11:20:05.97885 [DEBUG] mod_sofia.c:111 (sofia/internal/[email protected]) State Change CS_INIT -> CS_ROUTING
2010-01-07 11:20:05.97885 [DEBUG] switch_core_session.c:932 Send signal sofia/internal/[email protected] [BREAK]
2010-01-07 11:20:05.97885 [DEBUG] switch_core_state_machine.c:481 (sofia/internal/[email protected]) State INIT going to sleep
2010-01-07 11:20:05.97885 [DEBUG] switch_core_state_machine.c:398 (sofia/internal/[email protected]) Running State Change CS_ROUTING
2010-01-07 11:20:05.97885 [DEBUG] switch_core_state_machine.c:484 (sofia/internal/[email protected]) State ROUTING
2010-01-07 11:20:05.97885 [DEBUG] mod_sofia.c:130 sofia/internal/[email protected] SOFIA ROUTING
2010-01-07 11:20:05.97885 [DEBUG] switch_core_state_machine.c:78 sofia/internal/[email protected] Standard ROUTING
2010-01-07 11:20:05.97885 [INFO] mod_dialplan_xml.c:315 Processing 8898801->036979700 in context default
Dialplan: sofia/internal/[email protected] parsing [default->localxtens] continue=false
Dialplan: sofia/internal/[email protected] Regex (FAIL) [localxtens] destination_number(036979700) =~ /^(0?9?88988[0-4][0-9])$/ break=on-false
Dialplan: sofia/internal/[email protected] parsing [default->To_PSTN] continue=false
Dialplan: sofia/internal/[email protected] Regex (PASS) [To_PSTN] destination_number(036979700) =~ /^(.*)$/ break=on-false
Dialplan: sofia/internal/[email protected] Action bridge(openzap/1/a/036979700)
2010-01-07 11:20:05.98953 [DEBUG] switch_core_state_machine.c:114 (sofia/internal/[email protected]) State Change CS_ROUTING -> CS_EXECUTE
2010-01-07 11:20:05.98953 [DEBUG] switch_core_session.c:932 Send signal sofia/internal/[email protected] [BREAK]
2010-01-07 11:20:05.98953 [DEBUG] switch_core_state_machine.c:484 (sofia/internal/[email protected]) State ROUTING going to sleep
2010-01-07 11:20:05.98953 [DEBUG] switch_core_state_machine.c:398 (sofia/internal/[email protected]) Running State Change CS_EXECUTE
2010-01-07 11:20:05.98953 [DEBUG] switch_core_state_machine.c:491 (sofia/internal/[email protected]) State EXECUTE
2010-01-07 11:20:05.98953 [DEBUG] mod_sofia.c:173 sofia/internal/[email protected] SOFIA EXECUTE
2010-01-07 11:20:05.98953 [DEBUG] switch_core_state_machine.c:151 sofia/internal/[email protected] Standard EXECUTE
EXECUTE sofia/internal/[email protected] 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/[email protected] [BREAK]
2010-01-07 11:20:05.289206 [DEBUG] switch_ivr_originate.c:2017 sofia/internal/[email protected] 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/[email protected]] 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/[email protected]!
2010-01-07 11:20:05.291378 [DEBUG] switch_core_session.c:630 Send signal sofia/internal/[email protected] [BREAK]
2010-01-07 11:20:05.291378 [DEBUG] sofia.c:3289 Channel sofia/internal/[email protected] 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/[email protected] 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/[email protected] receive message [BRIDGE]
2010-01-07 11:20:05.291378 [DEBUG] switch_core_session.c:630 Send signal sofia/internal/[email protected] [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/[email protected] 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/[email protected] [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/[email protected] [CS_EXECUTE] [UNALLOCATED_NUMBER]
2010-01-07 11:20:06.502306 [DEBUG] switch_channel.c:1683 Send signal sofia/internal/[email protected] [KILL]
2010-01-07 11:20:06.502306 [DEBUG] switch_core_session.c:932 Send signal sofia/internal/[email protected] [BREAK]
2010-01-07 11:20:06.502306 [DEBUG] switch_ivr_bridge.c:452 BRIDGE THREAD DONE [sofia/internal/[email protected]]
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/[email protected]) State EXECUTE going to sleep
2010-01-07 11:20:06.502306 [DEBUG] switch_core_state_machine.c:398 (sofia/internal/[email protected]) Running State Change CS_HANGUP
2010-01-07 11:20:06.502306 [DEBUG] switch_core_state_machine.c:434 (sofia/internal/[email protected]) State HANGUP
2010-01-07 11:20:06.502306 [DEBUG] mod_sofia.c:338 Channel sofia/internal/[email protected] 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/[email protected] Standard HANGUP, cause: UNALLOCATED_NUMBER
2010-01-07 11:20:06.503555 [DEBUG] switch_core_state_machine.c:434 (sofia/internal/[email protected]) State HANGUP going to sleep
2010-01-07 11:20:06.503555 [DEBUG] switch_core_state_machine.c:476 (sofia/internal/[email protected]) State Change CS_HANGUP -> CS_REPORTING
2010-01-07 11:20:06.503555 [DEBUG] switch_core_session.c:932 Send signal sofia/internal/[email protected] [BREAK]
2010-01-07 11:20:06.503555 [DEBUG] switch_core_state_machine.c:398 (sofia/internal/[email protected]) Running State Change CS_REPORTING
2010-01-07 11:20:06.503555 [DEBUG] switch_core_state_machine.c:612 (sofia/internal/[email protected]) State REPORTING
2010-01-07 11:20:06.503555 [DEBUG] switch_core_state_machine.c:53 sofia/internal/[email protected] Standard REPORTING, cause: UNALLOCATED_NUMBER
2010-01-07 11:20:06.503555 [DEBUG] switch_core_state_machine.c:612 (sofia/internal/[email protected]) State REPORTING going to sleep
2010-01-07 11:20:06.503555 [DEBUG] switch_core_state_machine.c:411 (sofia/internal/[email protected]) State Change CS_REPORTING -> CS_DESTROY
2010-01-07 11:20:06.503555 [DEBUG] switch_core_session.c:1068 Session 31 (sofia/internal/[email protected]) Locked, Waiting on external entities
2010-01-07 11:20:06.503555 [NOTICE] switch_core_session.c:1086 Session 31 (sofia/internal/[email protected]) Ended
2010-01-07 11:20:06.503555 [NOTICE] switch_core_session.c:1088 Close Channel sofia/internal/[email protected] [CS_DESTROY]
2010-01-07 11:20:06.503555 [DEBUG] switch_core_state_machine.c:564 (sofia/internal/[email protected]) State DESTROY
2010-01-07 11:20:06.503555 [DEBUG] mod_sofia.c:255 sofia/internal/[email protected] SOFIA DESTROY
2010-01-07 11:20:06.503555 [DEBUG] switch_core_state_machine.c:60 sofia/internal/[email protected] Standard DESTROY
2010-01-07 11:20:06.503555 [DEBUG] switch_core_state_machine.c:564 (sofia/internal/[email protected]) 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
Raw
libpri-openzap-bridge-outbound-calls-working.cs
freeswitch@internal>
freeswitch@internal>
freeswitch@internal>
freeswitch@internal>
freeswitch@internal> 2010-01-07 11:21:01.569773 [DEBUG] sofia.c:4628 IP 87.68.244.32 Rejected by acl "domains". Falling back to Digest auth.
2010-01-07 11:21:01.635137 [DEBUG] sofia.c:4628 IP 87.68.244.32 Rejected by acl "domains". Falling back to Digest auth.
2010-01-07 11:21:01.636205 [NOTICE] switch_channel.c:602 New Channel sofia/internal/[email protected] [f9116b7c-fb6d-11de-9911-b7e694ca6e0b]
2010-01-07 11:21:01.637273 [DEBUG] sofia.c:3289 Channel sofia/internal/[email protected] entering state [received][100]
2010-01-07 11:21:01.637273 [DEBUG] sofia.c:3296 Remote SDP:
v=0
o=- 60430268 60430268 IN IP4 20.0.0.122
s=-
c=IN IP4 87.68.244.32
t=0 0
m=audio 16384 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:21:01.637273 [DEBUG] sofia_glue.c:3071 Audio Codec Compare [PCMU:0:8000:30]/[PCMU:0:8000:20]
2010-01-07 11:21:01.637273 [DEBUG] sofia_glue.c:3071 Audio Codec Compare [PCMU:0:8000:30]/[PCMA:8:8000:20]
2010-01-07 11:21:01.637273 [DEBUG] sofia_glue.c:3071 Audio Codec Compare [PCMU:0:8000:30]/[GSM:3:8000:20]
2010-01-07 11:21:01.637273 [DEBUG] sofia_glue.c:3071 Audio Codec Compare [PCMU:0:8000:30]/[G722:9:8000:20]
2010-01-07 11:21:01.637273 [DEBUG] sofia_glue.c:3071 Audio Codec Compare [PCMU:0:8000:30]/[SPEEX:98:8000:20]
2010-01-07 11:21:01.637273 [DEBUG] sofia_glue.c:3071 Audio Codec Compare [PCMU:0:8000:30]/[SPEEX:99:16000:20]
2010-01-07 11:21:01.637273 [DEBUG] sofia_glue.c:3071 Audio Codec Compare [PCMU:0:8000:30]/[SPEEX:103:32000:20]
2010-01-07 11:21:01.637273 [DEBUG] sofia_glue.c:3119 Substituting codec PCMU@30i@8000h
2010-01-07 11:21:01.637273 [DEBUG] sofia_glue.c:2029 Set Codec sofia/internal/[email protected] PCMU/8000 30 ms 240 samples
2010-01-07 11:21:01.637273 [DEBUG] sofia_glue.c:3031 Set 2833 dtmf payload to 101
2010-01-07 11:21:01.637273 [DEBUG] sofia.c:3455 (sofia/internal/[email protected]) State Change CS_NEW -> CS_INIT
2010-01-07 11:21:01.637273 [DEBUG] switch_core_session.c:932 Send signal sofia/internal/[email protected] [BREAK]
2010-01-07 11:21:01.638610 [DEBUG] switch_core_state_machine.c:398 (sofia/internal/[email protected]) Running State Change CS_INIT
2010-01-07 11:21:01.638610 [DEBUG] switch_core_state_machine.c:481 (sofia/internal/[email protected]) State INIT
2010-01-07 11:21:01.638610 [DEBUG] mod_sofia.c:83 sofia/internal/[email protected] SOFIA INIT
2010-01-07 11:21:01.638610 [DEBUG] mod_sofia.c:111 (sofia/internal/[email protected]) State Change CS_INIT -> CS_ROUTING
2010-01-07 11:21:01.638610 [DEBUG] switch_core_session.c:932 Send signal sofia/internal/[email protected] [BREAK]
2010-01-07 11:21:01.638610 [DEBUG] switch_core_state_machine.c:481 (sofia/internal/[email protected]) State INIT going to sleep
2010-01-07 11:21:01.638610 [DEBUG] switch_core_state_machine.c:398 (sofia/internal/[email protected]) Running State Change CS_ROUTING
2010-01-07 11:21:01.638610 [DEBUG] switch_core_state_machine.c:484 (sofia/internal/[email protected]) State ROUTING
2010-01-07 11:21:01.638610 [DEBUG] mod_sofia.c:130 sofia/internal/[email protected] SOFIA ROUTING
2010-01-07 11:21:01.638610 [DEBUG] switch_core_state_machine.c:78 sofia/internal/[email protected] Standard ROUTING
2010-01-07 11:21:01.638610 [INFO] mod_dialplan_xml.c:315 Processing 8898801->098898513 in context default
Dialplan: sofia/internal/[email protected] parsing [default->localxtens] continue=false
Dialplan: sofia/internal/[email protected] Regex (FAIL) [localxtens] destination_number(098898513) =~ /^(0?9?88988[0-4][0-9])$/ break=on-false
Dialplan: sofia/internal/[email protected] parsing [default->To_PSTN] continue=false
Dialplan: sofia/internal/[email protected] Regex (PASS) [To_PSTN] destination_number(098898513) =~ /^(.*)$/ break=on-false
Dialplan: sofia/internal/[email protected] Action bridge(openzap/1/a/098898513)
2010-01-07 11:21:01.638610 [DEBUG] switch_core_state_machine.c:114 (sofia/internal/[email protected]) State Change CS_ROUTING -> CS_EXECUTE
2010-01-07 11:21:01.638610 [DEBUG] switch_core_session.c:932 Send signal sofia/internal/[email protected] [BREAK]
2010-01-07 11:21:01.638610 [DEBUG] switch_core_state_machine.c:484 (sofia/internal/[email protected]) State ROUTING going to sleep
2010-01-07 11:21:01.638610 [DEBUG] switch_core_state_machine.c:398 (sofia/internal/[email protected]) Running State Change CS_EXECUTE
2010-01-07 11:21:01.639681 [DEBUG] switch_core_state_machine.c:491 (sofia/internal/[email protected]) State EXECUTE
2010-01-07 11:21:01.639681 [DEBUG] mod_sofia.c:173 sofia/internal/[email protected] SOFIA EXECUTE
2010-01-07 11:21:01.639681 [DEBUG] switch_core_state_machine.c:151 sofia/internal/[email protected] Standard EXECUTE
EXECUTE sofia/internal/[email protected] bridge(openzap/1/a/098898513)
2010-01-07 11:21:01.639681 [DEBUG] mod_openzap.c:344 Set codec PCMA 20ms
2010-01-07 11:21:01.639681 [DEBUG] mod_openzap.c:1073 Connect outbound channel OpenZAP/1:1/098898513
2010-01-07 11:21:01.639681 [NOTICE] switch_channel.c:602 New Channel OpenZAP/1:1/098898513 [f911e2c8-fb6d-11de-9911-b7e694ca6e0b]
2010-01-07 11:21:01.639681 [DEBUG] mod_openzap.c:1085 (OpenZAP/1:1/098898513) State Change CS_NEW -> CS_INIT
2010-01-07 11:21:01.639681 [DEBUG] switch_core_session.c:932 Send signal OpenZAP/1:1/098898513 [BREAK]
2010-01-07 11:21:01.639681 [DEBUG] ozmod_libpri.c:55 Changing state on 1:1 from DOWN to DIALING
2010-01-07 11:21:01.639681 [DEBUG] switch_core_state_machine.c:398 (OpenZAP/1:1/098898513) Running State Change CS_INIT
2010-01-07 11:21:01.639681 [DEBUG] switch_core_state_machine.c:481 (OpenZAP/1:1/098898513) State INIT
2010-01-07 11:21:01.639681 [DEBUG] mod_openzap.c:368 (OpenZAP/1:1/098898513) State Change CS_INIT -> CS_ROUTING
2010-01-07 11:21:01.639681 [DEBUG] switch_core_session.c:932 Send signal OpenZAP/1:1/098898513 [BREAK]
2010-01-07 11:21:01.639681 [DEBUG] switch_core_state_machine.c:481 (OpenZAP/1:1/098898513) State INIT going to sleep
2010-01-07 11:21:01.639681 [DEBUG] switch_core_state_machine.c:398 (OpenZAP/1:1/098898513) Running State Change CS_ROUTING
2010-01-07 11:21:01.639681 [DEBUG] switch_core_state_machine.c:484 (OpenZAP/1:1/098898513) State ROUTING
2010-01-07 11:21:01.639681 [DEBUG] mod_openzap.c:391 OpenZAP/1:1/098898513 CHANNEL ROUTING
2010-01-07 11:21:01.639681 [DEBUG] switch_ivr_originate.c:63 (OpenZAP/1:1/098898513) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2010-01-07 11:21:01.639681 [DEBUG] switch_core_session.c:932 Send signal OpenZAP/1:1/098898513 [BREAK]
2010-01-07 11:21:01.639681 [DEBUG] switch_core_state_machine.c:484 (OpenZAP/1:1/098898513) State ROUTING going to sleep
2010-01-07 11:21:01.639681 [DEBUG] switch_core_state_machine.c:398 (OpenZAP/1:1/098898513) Running State Change CS_CONSUME_MEDIA
2010-01-07 11:21:01.639681 [DEBUG] switch_core_state_machine.c:503 (OpenZAP/1:1/098898513) State CONSUME_MEDIA
2010-01-07 11:21:01.713963 [DEBUG] ozmod_libpri.c:429 1:1 STATE [DIALING]
2010-01-07 11:21:01.713963 [DEBUG] ozmod_libpri.c:106 -- Making new call for cr 32785
2010-01-07 11:21:01.713963 [DEBUG] ozmod_libpri.c:106 -- Finally transmitting 45, since window opened up (0)
2010-01-07 11:21:01.713963 [DEBUG] ozmod_libpri.c:106
> [ 00 01 5a 72 08 02 00 11 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 39 38 38 39 38 35 31 33 74 0a 00 01 8f 38 38 39 38 38 30 31 a1 ]
2010-01-07 11:21:01.713963 [DEBUG] ozmod_libpri.c:106
> Informational frame:
2010-01-07 11:21:01.713963 [DEBUG] ozmod_libpri.c:106 > SAPI: 00 C/R: 0 EA: 0
> TEI: 000 EA: 1
2010-01-07 11:21:01.713963 [DEBUG] ozmod_libpri.c:106 > N(S): 045 0: 0
> N(R): 057 P: 0
> 51 bytes of data
2010-01-07 11:21:01.713963 [DEBUG] ozmod_libpri.c:106 Stopping T_203 timer
2010-01-07 11:21:01.713963 [DEBUG] ozmod_libpri.c:106 Starting T_200 timer
2010-01-07 11:21:01.713963 [DEBUG] ozmod_libpri.c:106 -- Restarting T200 timer
2010-01-07 11:21:01.713963 [DEBUG] ozmod_libpri.c:106 > Protocol Discriminator: Q.931 (8) len=51
2010-01-07 11:21:01.713963 [DEBUG] ozmod_libpri.c:106 > Call Ref: len= 2 (reference 17/0x11) (Originator)
2010-01-07 11:21:01.713963 [DEBUG] ozmod_libpri.c:106 > Message type: SETUP (5)
2010-01-07 11:21:01.713963 [DEBUG] ozmod_libpri.c:106 > [04 03 80 90 a3]
2010-01-07 11:21:01.713963 [DEBUG] ozmod_libpri.c:106 > Bearer Capability (len= 5) [ Ext: 1 Q.931 Std: 0 Info transfer capability: Speech (0)
2010-01-07 11:21:01.713963 [DEBUG] ozmod_libpri.c:106 > Ext: 1 Trans mode/rate: 64kbps, circuit-mode (16)
2010-01-07 11:21:01.713963 [DEBUG] ozmod_libpri.c:106 > User information layer 1: A-Law (35)
2010-01-07 11:21:01.713963 [DEBUG] ozmod_libpri.c:106 > [18 03 a1 83 81]
2010-01-07 11:21:01.713963 [DEBUG] ozmod_libpri.c:106 > Channel ID (len= 5) [ Ext: 1 IntID: Implicit PRI Spare: 0 Preferred Dchan: 0
2010-01-07 11:21:01.713963 [DEBUG] ozmod_libpri.c:106 > ChanSel: As indicated in following octets
2010-01-07 11:21:01.713963 [DEBUG] ozmod_libpri.c:106 > Ext: 1 Coding: 0 Number Specified Channel Type: 3
2010-01-07 11:21:01.713963 [DEBUG] ozmod_libpri.c:106 > Ext: 1 Channel: 1 ]
2010-01-07 11:21:01.713963 [DEBUG] ozmod_libpri.c:106 > [6c 09 00 81 38 38 39 38 38 30 31]
2010-01-07 11:21:01.713963 [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:21:01.713963 [DEBUG] ozmod_libpri.c:106 > Presentation: Presentation permitted, user number passed network screening (1) '8898801' ]
2010-01-07 11:21:01.713963 [DEBUG] ozmod_libpri.c:106 > [70 0a 80 30 39 38 38 39 38 35 31 33]
2010-01-07 11:21:01.713963 [DEBUG] ozmod_libpri.c:106 > Called Number (len=12) [ Ext: 1 TON: Unknown Number Type (0) NPI: Unknown Number Plan (0) '098898513' ]
2010-01-07 11:21:01.713963 [DEBUG] ozmod_libpri.c:106 > [74 0a 00 01 8f 38 38 39 38 38 30 31]
2010-01-07 11:21:01.713963 [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:21:01.713963 [DEBUG] ozmod_libpri.c:106
> Ext: 0 Presentation: Presentation permitted, user number passed network screening (1)2010-01-07 11:21:01.713963 [DEBUG] ozmod_libpri.c:106
> Ext: 1 Reason: Forwarded unconditionally (15)2010-01-07 11:21:01.713963 [DEBUG] ozmod_libpri.c:106 '8898801' ]
2010-01-07 11:21:01.713963 [DEBUG] ozmod_libpri.c:106 > [a1]
2010-01-07 11:21:01.713963 [DEBUG] ozmod_libpri.c:106 > Sending Complete (len= 1)
2010-01-07 11:21:01.713963 [DEBUG] ozmod_libpri.c:106 q931.c:3134 q931_setup: call 32785 on channel 1 enters state 1 (Call Initiated)
2010-01-07 11:21:01.726894 [DEBUG] ozmod_libpri.c:106
< [ 00 01 01 5c ]
2010-01-07 11:21:01.726894 [DEBUG] ozmod_libpri.c:106
< Supervisory frame:
2010-01-07 11:21:01.726894 [DEBUG] ozmod_libpri.c:106 < SAPI: 00 C/R: 0 EA: 0
< TEI: 000 EA: 1
2010-01-07 11:21:01.726894 [DEBUG] ozmod_libpri.c:106 < Zero: 0 S: 0 01: 1 [ RR (receive ready) ]
< N(R): 046 P/F: 0
< 0 bytes of data
2010-01-07 11:21:01.726894 [DEBUG] ozmod_libpri.c:106 Handling message for SAPI/TEI=0/0
2010-01-07 11:21:01.726894 [DEBUG] ozmod_libpri.c:106 -- ACKing all packets from 44 to (but not including) 46
2010-01-07 11:21:01.726894 [DEBUG] ozmod_libpri.c:106 -- ACKing packet 45, new txqueue is -1 (-1 means empty)
2010-01-07 11:21:01.726894 [DEBUG] ozmod_libpri.c:106 -- Since there was nothing left, stopping T200 counter
2010-01-07 11:21:01.726894 [DEBUG] ozmod_libpri.c:106 -- Nothing left, starting T203 counter
2010-01-07 11:21:01.726894 [DEBUG] ozmod_libpri.c:106 -- Restarting T203 timer
2010-01-07 11:21:01.888978 [DEBUG] ozmod_libpri.c:106
< [ 02 01 72 5c 08 02 80 11 02 18 03 a9 83 81 ]
2010-01-07 11:21:01.888978 [DEBUG] ozmod_libpri.c:106
< Informational frame:
2010-01-07 11:21:01.888978 [DEBUG] ozmod_libpri.c:106 < SAPI: 00 C/R: 1 EA: 0
< TEI: 000 EA: 1
2010-01-07 11:21:01.888978 [DEBUG] ozmod_libpri.c:106 < N(S): 057 0: 0
< N(R): 046 P: 0
< 10 bytes of data
2010-01-07 11:21:01.888978 [DEBUG] ozmod_libpri.c:106 Handling message for SAPI/TEI=0/0
2010-01-07 11:21:01.888978 [DEBUG] ozmod_libpri.c:106 -- ACKing all packets from 45 to (but not including) 46
2010-01-07 11:21:01.888978 [DEBUG] ozmod_libpri.c:106 -- Since there was nothing left, stopping T200 counter
2010-01-07 11:21:01.888978 [DEBUG] ozmod_libpri.c:106 -- Stopping T203 counter since we got an ACK
2010-01-07 11:21:01.888978 [DEBUG] ozmod_libpri.c:106 -- Nothing left, starting T203 counter
2010-01-07 11:21:01.888978 [DEBUG] ozmod_libpri.c:106 < Protocol Discriminator: Q.931 (8) len=10
2010-01-07 11:21:01.888978 [DEBUG] ozmod_libpri.c:106 < Call Ref: len= 2 (reference 17/0x11) (Terminator)
2010-01-07 11:21:01.888978 [DEBUG] ozmod_libpri.c:106 < Message type: CALL PROCEEDING (2)
2010-01-07 11:21:01.888978 [DEBUG] ozmod_libpri.c:106 < [18 03 a9 83 81]
2010-01-07 11:21:01.888978 [DEBUG] ozmod_libpri.c:106 < Channel ID (len= 5) [ Ext: 1 IntID: Implicit PRI Spare: 0 Exclusive Dchan: 0
2010-01-07 11:21:01.888978 [DEBUG] ozmod_libpri.c:106 < ChanSel: As indicated in following octets
2010-01-07 11:21:01.888978 [DEBUG] ozmod_libpri.c:106 < Ext: 1 Coding: 0 Number Specified Channel Type: 3
2010-01-07 11:21:01.888978 [DEBUG] ozmod_libpri.c:106 < Ext: 1 Channel: 1 ]
2010-01-07 11:21:01.888978 [DEBUG] ozmod_libpri.c:106 -- Processing IE 24 (cs0, Channel Identification)
2010-01-07 11:21:01.888978 [DEBUG] ozmod_libpri.c:106 q931.c:3683 q931_receive: call 32785 on channel 1 enters state 3 (Outgoing call Proceeding)
2010-01-07 11:21:01.888978 [DEBUG] ozmod_libpri.c:106 Sending Receiver Ready (58)
2010-01-07 11:21:01.888978 [DEBUG] ozmod_libpri.c:106
> [ 02 01 01 74 ]
2010-01-07 11:21:01.888978 [DEBUG] ozmod_libpri.c:106
> Supervisory frame:
2010-01-07 11:21:01.888978 [DEBUG] ozmod_libpri.c:106 > SAPI: 00 C/R: 1 EA: 0
> TEI: 000 EA: 1
2010-01-07 11:21:01.888978 [DEBUG] ozmod_libpri.c:106 > Zero: 0 S: 0 01: 1 [ RR (receive ready) ]
> N(R): 058 P/F: 0
> 0 bytes of data
2010-01-07 11:21:01.888978 [DEBUG] ozmod_libpri.c:106 -- Restarting T203 timer
2010-01-07 11:21:01.888978 [DEBUG] ozmod_libpri.c:703 -- Proceeding on channel 1:1
2010-01-07 11:21:01.888978 [DEBUG] ozmod_libpri.c:704 Changing state on 1:1 from DIALING to PROGRESS_MEDIA
2010-01-07 11:21:01.888978 [DEBUG] ozmod_libpri.c:429 1:1 STATE [PROGRESS_MEDIA]
2010-01-07 11:21:01.888978 [DEBUG] mod_openzap.c:1481 got clear channel sig [PROGRESS_MEDIA]
2010-01-07 11:21:01.888978 [NOTICE] mod_openzap.c:1522 Pre-Answer OpenZAP/1:1/098898513!
2010-01-07 11:21:01.888978 [DEBUG] switch_channel.c:1778 Send signal sofia/internal/[email protected] [BREAK]
2010-01-07 11:21:01.890107 [DEBUG] switch_ivr_originate.c:2017 sofia/internal/[email protected] receive message [PROGRESS]
2010-01-07 11:21:01.890107 [INFO] switch_ivr_originate.c:2017 Sending early media
2010-01-07 11:21:01.890107 [DEBUG] sofia_glue.c:2263 AUDIO RTP [sofia/internal/[email protected]] 81.218.11.30 port 25694 -> 87.68.244.32 port 16384 codec: 0 ms: 30
2010-01-07 11:21:01.890107 [DEBUG] switch_rtp.c:1138 Starting timer [soft] 240 bytes per 30ms
2010-01-07 11:21:01.891180 [INFO] mod_sofia.c:1506 Ring SDP:
v=0
o=FreeSWITCH 1262830367 1262830368 IN IP4 81.218.11.30
s=FreeSWITCH
c=IN IP4 81.218.11.30
t=0 0
m=audio 25694 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:21:01.891180 [NOTICE] mod_sofia.c:1509 Pre-Answer sofia/internal/[email protected]!
2010-01-07 11:21:01.891180 [DEBUG] switch_core_session.c:630 Send signal sofia/internal/[email protected] [BREAK]
2010-01-07 11:21:01.891180 [DEBUG] switch_ivr_originate.c:2061 Originate Resulted in Success: [OpenZAP/1:1/098898513]
2010-01-07 11:21:01.891180 [DEBUG] switch_channel.c:182 OpenZAP/1:1/098898513 receive message [AUDIO_SYNC]
2010-01-07 11:21:01.891180 [DEBUG] switch_channel.c:182 sofia/internal/[email protected] receive message [AUDIO_SYNC]
2010-01-07 11:21:01.891180 [DEBUG] sofia.c:3289 Channel sofia/internal/[email protected] entering state [early][183]
2010-01-07 11:21:01.892318 [DEBUG] switch_ivr_bridge.c:889 OpenZAP/1:1/098898513 receive message [BRIDGE]
2010-01-07 11:21:01.892318 [DEBUG] switch_core_session.c:630 Send signal OpenZAP/1:1/098898513 [BREAK]
2010-01-07 11:21:01.892318 [DEBUG] switch_ivr_bridge.c:896 sofia/internal/[email protected] receive message [BRIDGE]
2010-01-07 11:21:01.892318 [DEBUG] switch_core_session.c:630 Send signal sofia/internal/[email protected] [BREAK]
2010-01-07 11:21:01.892318 [DEBUG] switch_ivr_bridge.c:940 (OpenZAP/1:1/098898513) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA
2010-01-07 11:21:01.892318 [DEBUG] switch_core_session.c:932 Send signal OpenZAP/1:1/098898513 [BREAK]
2010-01-07 11:21:01.911663 [DEBUG] switch_core_state_machine.c:503 (OpenZAP/1:1/098898513) State CONSUME_MEDIA going to sleep
2010-01-07 11:21:01.911663 [DEBUG] switch_core_state_machine.c:398 (OpenZAP/1:1/098898513) Running State Change CS_EXCHANGE_MEDIA
2010-01-07 11:21:01.911663 [DEBUG] switch_core_state_machine.c:494 (OpenZAP/1:1/098898513) State EXCHANGE_MEDIA
2010-01-07 11:21:01.911663 [DEBUG] mod_openzap.c:525 CHANNEL EXCHANGE_MEDIA
2010-01-07 11:21:01.932050 [DEBUG] switch_core_io.c:649 sofia/internal/[email protected] receive message [TRANSCODING_NECESSARY]
2010-01-07 11:21:01.932050 [DEBUG] switch_core_io.c:892 Engaging Write Buffer at 480 bytes to accommodate 320->480
2010-01-07 11:21:01.971773 [DEBUG] switch_core_io.c:649 OpenZAP/1:1/098898513 receive message [TRANSCODING_NECESSARY]
2010-01-07 11:21:01.971773 [DEBUG] switch_core_io.c:892 Engaging Write Buffer at 320 bytes to accommodate 480->320
2010-01-07 11:21:02.488740 [DEBUG] ozmod_libpri.c:106
< [ 02 01 74 5c 08 02 80 11 01 ]
2010-01-07 11:21:02.488740 [DEBUG] ozmod_libpri.c:106
< Informational frame:
2010-01-07 11:21:02.488740 [DEBUG] ozmod_libpri.c:106 < SAPI: 00 C/R: 1 EA: 0
< TEI: 000 EA: 1
2010-01-07 11:21:02.488740 [DEBUG] ozmod_libpri.c:106 < N(S): 058 0: 0
< N(R): 046 P: 0
< 5 bytes of data
2010-01-07 11:21:02.488740 [DEBUG] ozmod_libpri.c:106 Handling message for SAPI/TEI=0/0
2010-01-07 11:21:02.488740 [DEBUG] ozmod_libpri.c:106 -- ACKing all packets from 45 to (but not including) 46
2010-01-07 11:21:02.488740 [DEBUG] ozmod_libpri.c:106 -- Since there was nothing left, stopping T200 counter
2010-01-07 11:21:02.488740 [DEBUG] ozmod_libpri.c:106 -- Stopping T203 counter since we got an ACK
2010-01-07 11:21:02.488740 [DEBUG] ozmod_libpri.c:106 -- Nothing left, starting T203 counter
2010-01-07 11:21:02.488740 [DEBUG] ozmod_libpri.c:106 < Protocol Discriminator: Q.931 (8) len=5
2010-01-07 11:21:02.488740 [DEBUG] ozmod_libpri.c:106 < Call Ref: len= 2 (reference 17/0x11) (Terminator)
2010-01-07 11:21:02.488740 [DEBUG] ozmod_libpri.c:106 < Message type: ALERTING (1)
2010-01-07 11:21:02.488740 [DEBUG] ozmod_libpri.c:106 q931.c:3596 q931_receive: call 32785 on channel 1 enters state 4 (Call Delivered)
2010-01-07 11:21:02.488740 [DEBUG] ozmod_libpri.c:106 Sending Receiver Ready (59)
2010-01-07 11:21:02.488740 [DEBUG] ozmod_libpri.c:106
> [ 02 01 01 76 ]
2010-01-07 11:21:02.488740 [DEBUG] ozmod_libpri.c:106
> Supervisory frame:
2010-01-07 11:21:02.488740 [DEBUG] ozmod_libpri.c:106 > SAPI: 00 C/R: 1 EA: 0
> TEI: 000 EA: 1
2010-01-07 11:21:02.488740 [DEBUG] ozmod_libpri.c:106 > Zero: 0 S: 0 01: 1 [ RR (receive ready) ]
> N(R): 059 P/F: 0
> 0 bytes of data
2010-01-07 11:21:02.488740 [DEBUG] ozmod_libpri.c:106 -- Restarting T203 timer
2010-01-07 11:21:02.488740 [DEBUG] ozmod_libpri.c:728 -- Ringing on channel 1:1
2010-01-07 11:21:02.488740 [WARNING] ozmod_libpri.c:729 VETO Changing state on 1:1 from PROGRESS_MEDIA to PROGRESS
2010-01-07 11:21:05.130473 [DEBUG] sofia.c:3289 Channel sofia/internal/[email protected] entering state [terminated][487]
2010-01-07 11:21:05.130473 [NOTICE] sofia.c:3849 Hangup sofia/internal/[email protected] [CS_EXECUTE] [ORIGINATOR_CANCEL]
2010-01-07 11:21:05.130473 [DEBUG] switch_channel.c:1683 Send signal sofia/internal/[email protected] [KILL]
2010-01-07 11:21:05.130473 [DEBUG] switch_core_session.c:932 Send signal sofia/internal/[email protected] [BREAK]
2010-01-07 11:21:05.131595 [DEBUG] switch_ivr_bridge.c:371 sofia/internal/[email protected] ending bridge by request from write function
2010-01-07 11:21:05.131595 [DEBUG] switch_ivr_bridge.c:426 OpenZAP/1:1/098898513 receive message [UNBRIDGE]
2010-01-07 11:21:05.131595 [DEBUG] switch_core_session.c:630 Send signal OpenZAP/1:1/098898513 [BREAK]
2010-01-07 11:21:05.131595 [DEBUG] switch_ivr_bridge.c:452 BRIDGE THREAD DONE [OpenZAP/1:1/098898513]
2010-01-07 11:21:05.131595 [DEBUG] switch_ivr_bridge.c:454 Send signal sofia/internal/[email protected] [BREAK]
2010-01-07 11:21:05.131595 [NOTICE] switch_ivr_bridge.c:503 Hangup OpenZAP/1:1/098898513 [CS_EXCHANGE_MEDIA] [NORMAL_CLEARING]
2010-01-07 11:21:05.131595 [DEBUG] switch_channel.c:1683 Send signal OpenZAP/1:1/098898513 [KILL]
2010-01-07 11:21:05.131595 [DEBUG] switch_core_session.c:932 Send signal OpenZAP/1:1/098898513 [BREAK]
2010-01-07 11:21:05.131595 [DEBUG] switch_core_state_machine.c:494 (OpenZAP/1:1/098898513) State EXCHANGE_MEDIA going to sleep
2010-01-07 11:21:05.131595 [DEBUG] switch_core_state_machine.c:398 (OpenZAP/1:1/098898513) Running State Change CS_HANGUP
2010-01-07 11:21:05.131595 [DEBUG] switch_core_state_machine.c:434 (OpenZAP/1:1/098898513) State HANGUP
2010-01-07 11:21:05.131595 [DEBUG] mod_openzap.c:473 Changing state on 1:1 from PROGRESS_MEDIA to HANGUP
2010-01-07 11:21:05.131595 [DEBUG] mod_openzap.c:486 OpenZAP/1:1/098898513 CHANNEL HANGUP
2010-01-07 11:21:05.131595 [DEBUG] switch_core_state_machine.c:46 OpenZAP/1:1/098898513 Standard HANGUP, cause: NORMAL_CLEARING
2010-01-07 11:21:05.131595 [DEBUG] switch_core_state_machine.c:434 (OpenZAP/1:1/098898513) State HANGUP going to sleep
2010-01-07 11:21:05.131595 [DEBUG] switch_core_state_machine.c:476 (OpenZAP/1:1/098898513) State Change CS_HANGUP -> CS_REPORTING
2010-01-07 11:21:05.131595 [DEBUG] switch_core_session.c:932 Send signal OpenZAP/1:1/098898513 [BREAK]
2010-01-07 11:21:05.131595 [DEBUG] switch_core_state_machine.c:398 (OpenZAP/1:1/098898513) Running State Change CS_REPORTING
2010-01-07 11:21:05.131595 [DEBUG] switch_core_state_machine.c:612 (OpenZAP/1:1/098898513) State REPORTING
2010-01-07 11:21:05.131595 [DEBUG] switch_core_state_machine.c:53 OpenZAP/1:1/098898513 Standard REPORTING, cause: NORMAL_CLEARING
2010-01-07 11:21:05.131595 [DEBUG] switch_core_state_machine.c:612 (OpenZAP/1:1/098898513) State REPORTING going to sleep
2010-01-07 11:21:05.131595 [DEBUG] switch_core_state_machine.c:411 (OpenZAP/1:1/098898513) State Change CS_REPORTING -> CS_DESTROY
2010-01-07 11:21:05.131595 [DEBUG] switch_core_session.c:1068 Session 34 (OpenZAP/1:1/098898513) Locked, Waiting on external entities
2010-01-07 11:21:05.152252 [DEBUG] switch_ivr_bridge.c:377 sofia/internal/[email protected] ending bridge by request from read function
2010-01-07 11:21:05.152252 [DEBUG] switch_ivr_bridge.c:452 BRIDGE THREAD DONE [sofia/internal/[email protected]]
2010-01-07 11:21:05.152252 [DEBUG] switch_ivr_bridge.c:454 Send signal OpenZAP/1:1/098898513 [BREAK]
2010-01-07 11:21:05.152252 [NOTICE] switch_core_session.c:1086 Session 34 (OpenZAP/1:1/098898513) Ended
2010-01-07 11:21:05.152252 [NOTICE] switch_core_session.c:1088 Close Channel OpenZAP/1:1/098898513 [CS_DESTROY]
2010-01-07 11:21:05.152252 [DEBUG] switch_core_state_machine.c:564 (OpenZAP/1:1/098898513) State DESTROY
2010-01-07 11:21:05.152252 [DEBUG] switch_core_state_machine.c:60 OpenZAP/1:1/098898513 Standard DESTROY
2010-01-07 11:21:05.152252 [DEBUG] switch_core_state_machine.c:564 (OpenZAP/1:1/098898513) State DESTROY going to sleep
2010-01-07 11:21:05.152252 [DEBUG] switch_core_state_machine.c:491 (sofia/internal/[email protected]) State EXECUTE going to sleep
2010-01-07 11:21:05.152252 [DEBUG] switch_core_state_machine.c:398 (sofia/internal/[email protected]) Running State Change CS_HANGUP
2010-01-07 11:21:05.153373 [DEBUG] switch_core_state_machine.c:434 (sofia/internal/[email protected]) State HANGUP
2010-01-07 11:21:05.153373 [DEBUG] mod_sofia.c:306 sofia/internal/[email protected] Overriding SIP cause 487 with 487 from the other leg
2010-01-07 11:21:05.153373 [DEBUG] mod_sofia.c:338 Channel sofia/internal/[email protected] hanging up, cause: ORIGINATOR_CANCEL
2010-01-07 11:21:05.153373 [DEBUG] switch_core_state_machine.c:46 sofia/internal/[email protected] Standard HANGUP, cause: ORIGINATOR_CANCEL
2010-01-07 11:21:05.153373 [DEBUG] switch_core_state_machine.c:434 (sofia/internal/[email protected]) State HANGUP going to sleep
2010-01-07 11:21:05.153373 [DEBUG] switch_core_state_machine.c:476 (sofia/internal/[email protected]) State Change CS_HANGUP -> CS_REPORTING
2010-01-07 11:21:05.153373 [DEBUG] switch_core_session.c:932 Send signal sofia/internal/[email protected] [BREAK]
2010-01-07 11:21:05.153373 [DEBUG] switch_core_state_machine.c:398 (sofia/internal/[email protected]) Running State Change CS_REPORTING
2010-01-07 11:21:05.153373 [DEBUG] switch_core_state_machine.c:612 (sofia/internal/[email protected]) State REPORTING
2010-01-07 11:21:05.153373 [DEBUG] switch_core_state_machine.c:53 sofia/internal/[email protected] Standard REPORTING, cause: ORIGINATOR_CANCEL
2010-01-07 11:21:05.153373 [DEBUG] switch_core_state_machine.c:612 (sofia/internal/[email protected]) State REPORTING going to sleep
2010-01-07 11:21:05.153373 [DEBUG] switch_core_state_machine.c:411 (sofia/internal/[email protected]) State Change CS_REPORTING -> CS_DESTROY
2010-01-07 11:21:05.153373 [DEBUG] switch_core_session.c:1068 Session 33 (sofia/internal/[email protected]) Locked, Waiting on external entities
2010-01-07 11:21:05.153373 [NOTICE] switch_core_session.c:1086 Session 33 (sofia/internal/[email protected]) Ended
2010-01-07 11:21:05.153373 [NOTICE] switch_core_session.c:1088 Close Channel sofia/internal/[email protected] [CS_DESTROY]
2010-01-07 11:21:05.154510 [DEBUG] switch_core_state_machine.c:564 (sofia/internal/[email protected]) State DESTROY
2010-01-07 11:21:05.154510 [DEBUG] mod_sofia.c:255 sofia/internal/[email protected] SOFIA DESTROY
2010-01-07 11:21:05.154510 [DEBUG] switch_core_state_machine.c:60 sofia/internal/[email protected] Standard DESTROY
2010-01-07 11:21:05.154510 [DEBUG] switch_core_state_machine.c:564 (sofia/internal/[email protected]) State DESTROY going to sleep
2010-01-07 11:21:05.223476 [DEBUG] ozmod_libpri.c:429 1:1 STATE [HANGUP]
2010-01-07 11:21:05.223476 [DEBUG] ozmod_libpri.c:106 NEW_HANGUP DEBUG: Calling q931_hangup, ourstate Call Delivered, peerstate Call Received
2010-01-07 11:21:05.223476 [DEBUG] ozmod_libpri.c:106 q931.c:3015 q931_disconnect: call 32785 on channel 1 enters state 11 (Disconnect Request)
2010-01-07 11:21:05.223476 [DEBUG] ozmod_libpri.c:106 -- Finally transmitting 46, since window opened up (0)
2010-01-07 11:21:05.223476 [DEBUG] ozmod_libpri.c:106
> [ 00 01 5c 76 08 02 00 11 45 08 02 81 90 ]
2010-01-07 11:21:05.223476 [DEBUG] ozmod_libpri.c:106
> Informational frame:
2010-01-07 11:21:05.223476 [DEBUG] ozmod_libpri.c:106 > SAPI: 00 C/R: 0 EA: 0
> TEI: 000 EA: 1
2010-01-07 11:21:05.223476 [DEBUG] ozmod_libpri.c:106 > N(S): 046 0: 0
> N(R): 059 P: 0
> 9 bytes of data
2010-01-07 11:21:05.223476 [DEBUG] ozmod_libpri.c:106 Stopping T_203 timer
2010-01-07 11:21:05.223476 [DEBUG] ozmod_libpri.c:106 Starting T_200 timer
2010-01-07 11:21:05.223476 [DEBUG] ozmod_libpri.c:106 -- Restarting T200 timer
2010-01-07 11:21:05.223476 [DEBUG] ozmod_libpri.c:106 > Protocol Discriminator: Q.931 (8) len=9
2010-01-07 11:21:05.223476 [DEBUG] ozmod_libpri.c:106 > Call Ref: len= 2 (reference 17/0x11) (Originator)
2010-01-07 11:21:05.223476 [DEBUG] ozmod_libpri.c:106 > Message type: DISCONNECT (69)
2010-01-07 11:21:05.223476 [DEBUG] ozmod_libpri.c:106 > [08 02 81 90]
2010-01-07 11:21:05.223476 [DEBUG] ozmod_libpri.c:106 > Cause (len= 4) [ Ext: 1 Coding: CCITT (ITU) standard (0) Spare: 0 Location: Private network serving the local user (1)
2010-01-07 11:21:05.223476 [DEBUG] ozmod_libpri.c:106 > Ext: 1 Cause: Normal Clearing (16), class = Normal Event (1) ]
2010-01-07 11:21:05.223476 [DEBUG] ozmod_libpri.c:106 NEW_HANGUP DEBUG: Destroying the call, ourstate Disconnect Request, peerstate Disconnect Indication
2010-01-07 11:21:05.223476 [DEBUG] ozmod_libpri.c:571 Changing state on 1:1 from HANGUP to DOWN
2010-01-07 11:21:05.231396 [DEBUG] ozmod_libpri.c:106
< [ 00 01 01 5e ]
2010-01-07 11:21:05.231396 [DEBUG] ozmod_libpri.c:106
< Supervisory frame:
2010-01-07 11:21:05.231396 [DEBUG] ozmod_libpri.c:106 < SAPI: 00 C/R: 0 EA: 0
< TEI: 000 EA: 1
2010-01-07 11:21:05.231396 [DEBUG] ozmod_libpri.c:106 < Zero: 0 S: 0 01: 1 [ RR (receive ready) ]
< N(R): 047 P/F: 0
< 0 bytes of data
2010-01-07 11:21:05.231396 [DEBUG] ozmod_libpri.c:106 Handling message for SAPI/TEI=0/0
2010-01-07 11:21:05.231396 [DEBUG] ozmod_libpri.c:106 -- ACKing all packets from 45 to (but not including) 47
2010-01-07 11:21:05.231396 [DEBUG] ozmod_libpri.c:106 -- ACKing packet 46, new txqueue is -1 (-1 means empty)
2010-01-07 11:21:05.231396 [DEBUG] ozmod_libpri.c:106 -- Since there was nothing left, stopping T200 counter
2010-01-07 11:21:05.231396 [DEBUG] ozmod_libpri.c:106 -- Nothing left, starting T203 counter
2010-01-07 11:21:05.231396 [DEBUG] ozmod_libpri.c:106 -- Restarting T203 timer
2010-01-07 11:21:05.231396 [DEBUG] ozmod_libpri.c:429 1:1 STATE [DOWN]
2010-01-07 11:21:05.231396 [DEBUG] zap_io.c:1200 channel done 1:1
2010-01-07 11:21:05.288353 [DEBUG] ozmod_libpri.c:106
< [ 02 01 76 5e 08 02 80 11 4d ]
2010-01-07 11:21:05.288353 [DEBUG] ozmod_libpri.c:106
< Informational frame:
2010-01-07 11:21:05.288353 [DEBUG] ozmod_libpri.c:106 < SAPI: 00 C/R: 1 EA: 0
< TEI: 000 EA: 1
2010-01-07 11:21:05.288353 [DEBUG] ozmod_libpri.c:106 < N(S): 059 0: 0
< N(R): 047 P: 0
< 5 bytes of data
2010-01-07 11:21:05.288353 [DEBUG] ozmod_libpri.c:106 Handling message for SAPI/TEI=0/0
2010-01-07 11:21:05.288353 [DEBUG] ozmod_libpri.c:106 -- ACKing all packets from 46 to (but not including) 47
2010-01-07 11:21:05.288353 [DEBUG] ozmod_libpri.c:106 -- Since there was nothing left, stopping T200 counter
2010-01-07 11:21:05.288353 [DEBUG] ozmod_libpri.c:106 -- Stopping T203 counter since we got an ACK
2010-01-07 11:21:05.288353 [DEBUG] ozmod_libpri.c:106 -- Nothing left, starting T203 counter
2010-01-07 11:21:05.288353 [DEBUG] ozmod_libpri.c:106 < Protocol Discriminator: Q.931 (8) len=5
2010-01-07 11:21:05.288353 [DEBUG] ozmod_libpri.c:106 < Call Ref: len= 2 (reference 17/0x11) (Terminator)
2010-01-07 11:21:05.288353 [DEBUG] ozmod_libpri.c:106 < Message type: RELEASE (77)
2010-01-07 11:21:05.288353 [DEBUG] ozmod_libpri.c:106 -- Making new call for cr 32785
2010-01-07 11:21:05.288353 [DEBUG] ozmod_libpri.c:106 -- Finally transmitting 47, since window opened up (0)
2010-01-07 11:21:05.288353 [DEBUG] ozmod_libpri.c:106
> [ 00 01 5e 78 08 02 00 11 5a 08 02 81 d1 ]
2010-01-07 11:21:05.288353 [DEBUG] ozmod_libpri.c:106
> Informational frame:
2010-01-07 11:21:05.288353 [DEBUG] ozmod_libpri.c:106 > SAPI: 00 C/R: 0 EA: 0
> TEI: 000 EA: 1
2010-01-07 11:21:05.288353 [DEBUG] ozmod_libpri.c:106 > N(S): 047 0: 0
> N(R): 060 P: 0
> 9 bytes of data
2010-01-07 11:21:05.288353 [DEBUG] ozmod_libpri.c:106 Stopping T_203 timer
2010-01-07 11:21:05.288353 [DEBUG] ozmod_libpri.c:106 Starting T_200 timer
2010-01-07 11:21:05.288353 [DEBUG] ozmod_libpri.c:106 -- Restarting T200 timer
2010-01-07 11:21:05.288353 [DEBUG] ozmod_libpri.c:106 > Protocol Discriminator: Q.931 (8) len=9
2010-01-07 11:21:05.288353 [DEBUG] ozmod_libpri.c:106 > Call Ref: len= 2 (reference 17/0x11) (Originator)
2010-01-07 11:21:05.288353 [DEBUG] ozmod_libpri.c:106 > Message type: RELEASE COMPLETE (90)
2010-01-07 11:21:05.288353 [DEBUG] ozmod_libpri.c:106 > [08 02 81 d1]
2010-01-07 11:21:05.288353 [DEBUG] ozmod_libpri.c:106 > Cause (len= 4) [ Ext: 1 Coding: CCITT (ITU) standard (0) Spare: 0 Location: Private network serving the local user (1)
2010-01-07 11:21:05.288353 [DEBUG] ozmod_libpri.c:106 > Ext: 1 Cause: Invalid call reference value (81), class = Invalid message (e.g. parameter out of range) (5) ]
2010-01-07 11:21:05.288353 [DEBUG] ozmod_libpri.c:106 NEW_HANGUP DEBUG: Calling q931_hangup, ourstate Null, peerstate Null
2010-01-07 11:21:05.288353 [DEBUG] ozmod_libpri.c:106 NEW_HANGUP DEBUG: Destroying the call, ourstate Null, peerstate Null
2010-01-07 11:21:05.288353 [DEBUG] ozmod_libpri.c:106 -- Restarting T203 timer
2010-01-07 11:21:05.296142 [DEBUG] ozmod_libpri.c:106
< [ 00 01 01 60 ]
2010-01-07 11:21:05.296142 [DEBUG] ozmod_libpri.c:106
< Supervisory frame:
2010-01-07 11:21:05.296142 [DEBUG] ozmod_libpri.c:106 < SAPI: 00 C/R: 0 EA: 0
< TEI: 000 EA: 1
2010-01-07 11:21:05.296142 [DEBUG] ozmod_libpri.c:106 < Zero: 0 S: 0 01: 1 [ RR (receive ready) ]
< N(R): 048 P/F: 0
< 0 bytes of data
2010-01-07 11:21:05.296142 [DEBUG] ozmod_libpri.c:106 Handling message for SAPI/TEI=0/0
2010-01-07 11:21:05.296142 [DEBUG] ozmod_libpri.c:106 -- ACKing all packets from 46 to (but not including) 48
2010-01-07 11:21:05.296142 [DEBUG] ozmod_libpri.c:106 -- ACKing packet 47, new txqueue is -1 (-1 means empty)
2010-01-07 11:21:05.296142 [DEBUG] ozmod_libpri.c:106 -- Since there was nothing left, stopping T200 counter
2010-01-07 11:21:05.296142 [DEBUG] ozmod_libpri.c:106 -- Stopping T203 counter since we got an ACK
2010-01-07 11:21:05.296142 [DEBUG] ozmod_libpri.c:106 -- Nothing left, starting T203 counter
2010-01-07 11:21:05.296142 [DEBUG] ozmod_libpri.c:106 -- Restarting T203 timer
Raw
originate from CLI.cs
freeswitch@snaptrunk> originate openzap/1/a/036979700 XML public
2010-01-07 12:30:13.348232 [NOTICE] switch_channel.c:602 New Channel OpenZAP/1:1/036979700 [a3ae5ea6-fb77-11de-9911-b7e694ca6e0b]
2010-01-07 12:30:13.530242 [NOTICE] mod_openzap.c:1522 Pre-Answer OpenZAP/1:1/036979700!
API CALL [originate(openzap/1/a/036979700 XML public)] output:
+OK a3ae5ea6-fb77-11de-9911-b7e694ca6e0b
2010-01-07 12:30:13.531343 [NOTICE] switch_ivr.c:1349 Transfer OpenZAP/1:1/036979700 to public[XML@default]
freeswitch@snaptrunk> 2010-01-07 12:30:14.630755 [NOTICE] mod_openzap.c:1500 Hangup OpenZAP/1:1/036979700 [CS_CONSUME_MEDIA] [UNALLOCATED_NUMBER]
2010-01-07 12:30:14.630755 [NOTICE] switch_core_session.c:1086 Session 70 (OpenZAP/1:1/036979700) Ended
2010-01-07 12:30:14.630755 [NOTICE] switch_core_session.c:1088 Close Channel OpenZAP/1:1/036979700 [CS_DESTROY]
freeswitch@snaptrunk>
freeswitch@snaptrunk>
freeswitch@snaptrunk>
freeswitch@snaptrunk> originate openzap/1/a/036979700 XML public
2010-01-07 12:30:18.366885 [NOTICE] switch_channel.c:602 New Channel OpenZAP/1:1/036979700 [a6ac366e-fb77-11de-9911-b7e694ca6e0b]
2010-01-07 12:30:18.530557 [NOTICE] mod_openzap.c:1522 Pre-Answer OpenZAP/1:1/036979700!
API CALL [originate(openzap/1/a/036979700 XML public)] output:
+OK a6ac366e-fb77-11de-9911-b7e694ca6e0b
2010-01-07 12:30:18.530557 [NOTICE] switch_ivr.c:1349 Transfer OpenZAP/1:1/036979700 to public[XML@default]
freeswitch@snaptrunk> 2010-01-07 12:30:19.681171 [NOTICE] mod_openzap.c:1500 Hangup OpenZAP/1:1/036979700 [CS_CONSUME_MEDIA] [UNALLOCATED_NUMBER]
2010-01-07 12:30:19.682254 [NOTICE] switch_core_session.c:1086 Session 71 (OpenZAP/1:1/036979700) Ended
2010-01-07 12:30:19.682254 [NOTICE] switch_core_session.c:1088 Close Channel OpenZAP/1:1/036979700 [CS_DESTROY]
freeswitch@snaptrunk>
freeswitch@snaptrunk> originate openzap/1/a/036979700 XML public
2010-01-07 12:30:21.326156 [NOTICE] switch_channel.c:602 New Channel OpenZAP/1:1/036979700 [a86fc484-fb77-11de-9911-b7e694ca6e0b]
2010-01-07 12:30:21.530575 [NOTICE] mod_openzap.c:1522 Pre-Answer OpenZAP/1:1/036979700!
API CALL [originate(openzap/1/a/036979700 XML public)] output:
+OK a86fc484-fb77-11de-9911-b7e694ca6e0b
2010-01-07 12:30:21.530575 [NOTICE] switch_ivr.c:1349 Transfer OpenZAP/1:1/036979700 to public[XML@default]
freeswitch@snaptrunk> 2010-01-07 12:30:23.981146 [WARNING] ozmod_libpri.c:729 VETO Changing state on 1:1 from PROGRESS_MEDIA to PROGRESS
freeswitch@snaptrunk> 2010-01-07 12:30:30.281029 [NOTICE] mod_openzap.c:1511 Channel [OpenZAP/1:1/036979700] has been answered
freeswitch@snaptrunk>
freeswitch@snaptrunk>
freeswitch@snaptrunk> 2010-01-07 12:30:40.731394 [NOTICE] mod_openzap.c:1500 Hangup OpenZAP/1:1/036979700 [CS_CONSUME_MEDIA] [NORMAL_CLEARING]
2010-01-07 12:30:40.731394 [NOTICE] switch_core_session.c:1086 Session 72 (OpenZAP/1:1/036979700) Ended
2010-01-07 12:30:40.731394 [NOTICE] switch_core_session.c:1088 Close Channel OpenZAP/1:1/036979700 [CS_DESTROY]
freeswitch@snaptrunk>
freeswitch@snaptrunk>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment