[Freeswitch-users] bind_meta_app: "already broadcasting..broadcast aborted" if bound via event socket

Wed Aug 26 13:59:02 PDT 2009

For your information, revision 14644 committed by anthm fixes this.
Again, thanks!

2009/8/26 Harry Vangberg <harry at vangberg.name>:
> Hello.
>
> After pestering the IRC channel for a few days with useless
> information, I think I've finally made a breakthrough, but I have no
> idea why it works this way.
>
> Basically, what I want to achieve is: A calls in and is bridged to B
> (1234). If B presses *1, he should be taken out, and A be bridged to C
> (8888) instead. Pretty simple.
>
> With the following dialplan it works very nicely:
>
>    <extension name="ivr">
>      <condition field="destination_number" expression="^(\d+)$">
>        <action application="set" data="bypass_media=false"/>
>        <action application="answer"/>
>        <action application="bind_meta_app" data="1 b a
> bridge::sofia/gateway/secretgw/8888"/>
>        <action application="bridge" data="sofia/gateway/secretgw/1234" />
>      </condition>
>    </extension>
>
> On the other hand, if I try to replicate the above via an outbound
> event socket it fails with a: "already broadcasting...broadcast
> aborted". In this case my dialplan XML looks like this:
>
>    <extension name="ff-ivr">
>      <condition field="destination_number" expression="^(.*)$">
>        <action application="set" data="bypass_media=false"/>
>        <action application="socket" data="127.0.0.1:8084 full"/>
>      </condition>
>    </extension>
>
> And this is the event socket communication (in reality I use a Ruby
> framework, do a bunch of database calls etc., but for the sake of
> clarity I'm mimicking it with a netcat session):
>
> --------------------------------
> $ nc -v -l 127.0.0.1 8084
> connect
>
> Event-Name: CHANNEL_DATA
> Core-UUID: ba78636a-9241-11de-ac94-b736da546252
> FreeSWITCH-Hostname: ip-10-226-231-225
> FreeSWITCH-IPv4: 10.226.231.225
> FreeSWITCH-IPv6: %3A%3A1
> Event-Date-Local: 2009-08-26%2013%3A43%3A20
> Event-Date-GMT: Wed,%2026%20Aug%202009%2013%3A43%3A20%20GMT
> Event-Date-Timestamp: 1251294200244673
> Event-Calling-File: mod_event_socket.c
> Event-Calling-Function: parse_command
> Event-Calling-Line-Number: 1482
> Channel-Username: hemmeligt
> Channel-Dialplan: XML
> Channel-Caller-ID-Name: hemmeligt
> Channel-Caller-ID-Number: hemmeligt
> Channel-Network-Addr: 129.142.224.250
> Channel-Destination-Number: 77344541
> Channel-Unique-ID: 681102bc-9246-11de-ac94-b736da546252
> Channel-Source: mod_sofia
> Channel-Context: public
> Channel-Channel-Name: sofia/external/hemmeligt%40129.142.224.250
> Channel-Profile-Index: 1
> Channel-Profile-Created-Time: 1251294195778388
> Channel-Channel-Created-Time: 1251294195778388
> Channel-Channel-Answered-Time: 0
> Channel-Channel-Progress-Time: 0
> Channel-Channel-Progress-Media-Time: 0
> Channel-Channel-Hangup-Time: 0
> Channel-Channel-Transfer-Time: 0
> Channel-Screen-Bit: false
> Channel-Privacy-Hide-Name: true
> Channel-Privacy-Hide-Number: true
> Channel-State: CS_EXECUTE
> Channel-State-Number: 4
> Channel-Name: sofia/external/hemmeligt%40129.142.224.250
> Unique-ID: 681102bc-9246-11de-ac94-b736da546252
> Call-Direction: inbound
> Presence-Call-Direction: inbound
> Answer-State: ringing
> Channel-Read-Codec-Name: PCMA
> Channel-Read-Codec-Rate: 8000
> Channel-Write-Codec-Name: PCMA
> Channel-Write-Codec-Rate: 8000
> Caller-Username: hemmeligt
> Caller-Dialplan: XML
> Caller-Caller-ID-Name: hemmeligt
> Caller-Caller-ID-Number: hemmeligt
> Caller-Network-Addr: 129.142.224.250
> Caller-Destination-Number: 77344541
> Caller-Unique-ID: 681102bc-9246-11de-ac94-b736da546252
> Caller-Source: mod_sofia
> Caller-Context: public
> Caller-Channel-Name: sofia/external/hemmeligt%40129.142.224.250
> Caller-Profile-Index: 1
> Caller-Profile-Created-Time: 1251294195778388
> Caller-Channel-Created-Time: 1251294195778388
> Caller-Channel-Answered-Time: 0
> Caller-Channel-Progress-Time: 0
> Caller-Channel-Progress-Media-Time: 0
> Caller-Channel-Hangup-Time: 0
> Caller-Channel-Transfer-Time: 0
> Caller-Screen-Bit: false
> Caller-Privacy-Hide-Name: true
> Caller-Privacy-Hide-Number: true
> variable_sip_received_ip: 129.142.224.250
> variable_sip_received_port: 5060
> variable_sip_via_protocol: udp
> variable_sip_from_user: hemmeligt
> variable_sip_from_uri: hemmeligt%40129.142.224.250
> variable_sip_from_host: 129.142.224.250
> variable_sip_from_user_stripped: hemmeligt
> variable_sip_from_tag: as19641342
> variable_sofia_profile_name: external
> variable_sip_Remote-Party-ID:
> %22hemmeligt%22%20%3Csip%3Ahemmeligt%40129.142.224.250%3E%3Bprivacy%3Dfull%3Bscreen%3Dno
> variable_sip_cid_type: rpid
> variable_sip_req_user: 77344541
> variable_sip_req_port: 5080
> variable_sip_req_uri: 77344541%4079.125.42.248%3A5080
> variable_sip_req_host: 79.125.42.248
> variable_sip_to_user: 77344541
> variable_sip_to_port: 5080
> variable_sip_to_uri: 77344541%4079.125.42.248%3A5080
> variable_sip_to_host: 79.125.42.248
> variable_sip_contact_user: hemmeligt
> variable_sip_contact_uri: hemmeligt%40129.142.224.250
> variable_sip_contact_host: 129.142.224.250
> variable_channel_name: sofia/external/hemmeligt%40129.142.224.250
> variable_sip_call_id: 1aa24dab25cf03f07933f7136822ceff%40129.142.224.250
> variable_sip_user_agent: Condor_gw1
> variable_sip_via_host: 129.142.224.250
> variable_sip_via_port: 5060
> variable_sip_via_rport: 5060
> variable_max_forwards: 70
> variable_switch_r_sdp:
> v%3D0%0D%0Ao%3Droot%2018982%2018982%20IN%20IP4%20129.142.224.250%0D%0As%3Dsession%0D%0Ac%3DIN%20IP4%20129.142.224.250%0D%0At%3D0%200%0D%0Am%3Daudio%2015430%20RTP/AVP%208%200%203%2097%20101%0D%0Aa%3Drtpmap%3A8%20PCMA/8000%0D%0Aa%3Drtpmap%3A0%20PCMU/8000%0D%0Aa%3Drtpmap%3A3%20GSM/8000%0D%0Aa%3Drtpmap%3A97%20iLBC/8000%0D%0Aa%3Dfmtp%3A97%20mode%3D30%0D%0Aa%3Drtpmap%3A101%20telephone-event/8000%0D%0Aa%3Dfmtp%3A101%200-16%0D%0Aa%3DsilenceSupp%3Aoff%20-%20-%20-%20-%0D%0Aa%3Dptime%3A20%0D%0A
> variable_remote_media_ip: 129.142.224.250
> variable_remote_media_port: 15430
> variable_read_codec: PCMA
> variable_read_rate: 8000
> variable_write_codec: PCMA
> variable_write_rate: 8000
> variable_endpoint_disposition: RECEIVED
> variable_bypass_media: false
> variable_current_application_data: 127.0.0.1%3A8084%20full
> variable_current_application: socket
> variable_socket_host: 127.0.0.1
> Content-Type: command/reply
> Reply-Text: %2BOK%0A
> Socket-Mode: static
> Control: full
>
> sendmsg
> call-command: execute
> execute-app-name: answer
>
> Content-Type: command/reply
> Reply-Text: +OK
>
> sendmsg
> call-command: execute
> execute-app-name: bind_meta_app
> execute-app-arg: 1 b a bridge::sofia/gateway/secretgw/8888
>
> Content-Type: command/reply
> Reply-Text: +OK
>
> sendmsg
> call-command: execute
> execute-app-name: bridge
> execute-app-arg: sofia/gateway/secretgw/1234
>
> Content-Type: command/reply
> Reply-Text: +OK
> --------------------------------
>
> And on the FreeSWITCH side:
>
> 2009-08-26 13:43:15.778388 [NOTICE] switch_channel.c:602 New Channel
> sofia/external/hemmeligt at 129.142.224.250
> [681102bc-9246-11de-ac94-b736da546252]
> 2009-08-26 13:43:15.778388 [DEBUG] sofia.c:3302 Channel
> sofia/external/hemmeligt at 129.142.224.250 entering state
> [received][100]
> 2009-08-26 13:43:15.778388 [DEBUG] sofia.c:3309 Remote SDP:
> v=0
> o=root 18982 18982 IN IP4 129.142.224.250
> s=session
> c=IN IP4 129.142.224.250
> t=0 0
> m=audio 15430 RTP/AVP 8 0 3 97 101
> a=rtpmap:8 PCMA/8000
> a=rtpmap:0 PCMU/8000
> a=rtpmap:3 GSM/8000
> a=rtpmap:97 iLBC/8000
> a=fmtp:97 mode=30
> a=rtpmap:101 telephone-event/8000
> a=fmtp:101 0-16
> a=silenceSupp:off - - - -
> a=ptime:20
>
> 2009-08-26 13:43:15.778388 [DEBUG] sofia_glue.c:3132 Audio Codec
> Compare [PCMA:8:8000:20]/[PCMA:8:8000:20]
> 2009-08-26 13:43:15.778388 [DEBUG] sofia_glue.c:2090 Set Codec
> sofia/external/hemmeligt at 129.142.224.250 PCMA/8000 20 ms 160 samples
> 2009-08-26 13:43:15.778388 [DEBUG] sofia_glue.c:3092 Set 2833 dtmf
> payload to 101
> 2009-08-26 13:43:15.778388 [DEBUG] sofia.c:3468
> (sofia/external/hemmeligt at 129.142.224.250) State Change CS_NEW ->
> CS_INIT
> 2009-08-26 13:43:15.778388 [DEBUG] switch_core_session.c:932 Send
> signal sofia/external/hemmeligt at 129.142.224.250 [BREAK]
> 2009-08-26 13:43:15.778388 [DEBUG] switch_core_state_machine.c:398
> (sofia/external/hemmeligt at 129.142.224.250) Running State Change
> CS_INIT
> 2009-08-26 13:43:15.778388 [DEBUG] switch_core_state_machine.c:481
> (sofia/external/hemmeligt at 129.142.224.250) State INIT
> 2009-08-26 13:43:15.778388 [DEBUG] mod_sofia.c:83
> sofia/external/hemmeligt at 129.142.224.250 SOFIA INIT
> 2009-08-26 13:43:15.778388 [DEBUG] mod_sofia.c:111
> (sofia/external/hemmeligt at 129.142.224.250) State Change CS_INIT ->
> CS_ROUTING
> 2009-08-26 13:43:15.778388 [DEBUG] switch_core_session.c:932 Send
> signal sofia/external/hemmeligt at 129.142.224.250 [BREAK]
> 2009-08-26 13:43:15.778388 [DEBUG] switch_core_state_machine.c:481
> (sofia/external/hemmeligt at 129.142.224.250) State INIT going to sleep
> 2009-08-26 13:43:15.778388 [DEBUG] switch_core_state_machine.c:398
> (sofia/external/hemmeligt at 129.142.224.250) Running State Change
> CS_ROUTING
> 2009-08-26 13:43:15.778388 [DEBUG] switch_core_state_machine.c:484
> (sofia/external/hemmeligt at 129.142.224.250) State ROUTING
> 2009-08-26 13:43:15.778388 [DEBUG] mod_sofia.c:130
> sofia/external/hemmeligt at 129.142.224.250 SOFIA ROUTING
> 2009-08-26 13:43:15.778388 [DEBUG] switch_core_state_machine.c:78
> sofia/external/hemmeligt at 129.142.224.250 Standard ROUTING
> 2009-08-26 13:43:15.778388 [INFO] mod_dialplan_xml.c:315 Processing
> hemmeligt->77344541 in context public
> Dialplan: sofia/external/hemmeligt at 129.142.224.250 parsing
> [public->ff-ivr] continue=false
> Dialplan: sofia/external/hemmeligt at 129.142.224.250 Regex (PASS)
> [ff-ivr] destination_number(77344541) =~ /^(.*)$/ break=on-false
> Dialplan: sofia/external/hemmeligt at 129.142.224.250 Action
> set(bypass_media=false)
> Dialplan: sofia/external/hemmeligt at 129.142.224.250 Action
> socket(127.0.0.1:8084 full)
> 2009-08-26 13:43:15.778388 [DEBUG] switch_core_state_machine.c:114
> (sofia/external/hemmeligt at 129.142.224.250) State Change CS_ROUTING ->
> CS_EXECUTE
> 2009-08-26 13:43:15.778388 [DEBUG] switch_core_session.c:932 Send
> signal sofia/external/hemmeligt at 129.142.224.250 [BREAK]
> 2009-08-26 13:43:15.778388 [DEBUG] switch_core_state_machine.c:484
> (sofia/external/hemmeligt at 129.142.224.250) State ROUTING going to
> sleep
> 2009-08-26 13:43:15.778388 [DEBUG] switch_core_state_machine.c:398
> (sofia/external/hemmeligt at 129.142.224.250) Running State Change
> CS_EXECUTE
> 2009-08-26 13:43:15.778388 [DEBUG] switch_core_state_machine.c:491
> (sofia/external/hemmeligt at 129.142.224.250) State EXECUTE
> 2009-08-26 13:43:15.778388 [DEBUG] mod_sofia.c:173
> sofia/external/hemmeligt at 129.142.224.250 SOFIA EXECUTE
> 2009-08-26 13:43:15.778388 [DEBUG] switch_core_state_machine.c:151
> sofia/external/hemmeligt at 129.142.224.250 Standard EXECUTE
> EXECUTE sofia/external/hemmeligt at 129.142.224.250 set(bypass_media=false)
> 2009-08-26 13:43:15.778388 [DEBUG] mod_dptools.c:748
> sofia/external/hemmeligt at 129.142.224.250 SET [bypass_media]=[false]
> EXECUTE sofia/external/hemmeligt at 129.142.224.250 socket(127.0.0.1:8084 full)
> 2009-08-26 13:43:21.701447 [DEBUG] switch_ivr.c:540
> sofia/external/hemmeligt at 129.142.224.250 Command Execute answer()
> EXECUTE sofia/external/hemmeligt at 129.142.224.250 answer()
> 2009-08-26 13:43:21.701447 [DEBUG] mod_dptools.c:649
> sofia/external/hemmeligt at 129.142.224.250 receive message [ANSWER]
> 2009-08-26 13:43:21.701447 [DEBUG] sofia_glue.c:2324 AUDIO RTP
> [sofia/external/hemmeligt at 129.142.224.250] 10.226.231.225 port 19016
> -> 129.142.224.250 port 15430 codec: 8 ms: 20
> 2009-08-26 13:43:21.701447 [DEBUG] switch_rtp.c:1138 Starting timer
> [soft] 160 bytes per 20ms
> 2009-08-26 13:43:21.702447 [DEBUG] mod_sofia.c:536 Local SDP
> sofia/external/hemmeligt at 129.142.224.250:
> v=0
> o=FreeSWITCH 1251275185 1251275186 IN IP4 79.125.42.248
> s=FreeSWITCH
> c=IN IP4 79.125.42.248
> t=0 0
> m=audio 19016 RTP/AVP 8 101
> a=rtpmap:8 PCMA/8000
> a=rtpmap:101 telephone-event/8000
> a=fmtp:101 0-16
> a=silenceSupp:off - - - -
> a=ptime:20
> a=sendrecv
>
> 2009-08-26 13:43:21.702447 [DEBUG] switch_core_session.c:630 Send
> signal sofia/external/hemmeligt at 129.142.224.250 [BREAK]
> 2009-08-26 13:43:21.702447 [NOTICE] mod_dptools.c:649 Channel
> [sofia/external/hemmeligt at 129.142.224.250] has been answered
> 2009-08-26 13:43:21.702447 [DEBUG] switch_channel.c:182
> sofia/external/hemmeligt at 129.142.224.250 receive message [AUDIO_SYNC]
> 2009-08-26 13:43:21.702447 [DEBUG] sofia.c:3302 Channel
> sofia/external/hemmeligt at 129.142.224.250 entering state
> [completed][200]
> 2009-08-26 13:43:21.782616 [DEBUG] sofia.c:3302 Channel
> sofia/external/hemmeligt at 129.142.224.250 entering state [ready][200]
> 2009-08-26 13:43:26.388737 [DEBUG] switch_ivr.c:540
> sofia/external/hemmeligt at 129.142.224.250 Command Execute
> bind_meta_app(1 b a bridge::sofia/gateway/secretgw/8888)
> EXECUTE sofia/external/hemmeligt at 129.142.224.250 bind_meta_app(1 b a
> bridge::sofia/gateway/secretgw/8888)
> 2009-08-26 13:43:26.388737 [INFO] switch_ivr_async.c:1795 Bound B-Leg:
> 1 bridge::sofia/gateway/secretgw/8888
> 2009-08-26 13:43:29.684236 [DEBUG] switch_ivr.c:540
> sofia/external/hemmeligt at 129.142.224.250 Command Execute
> bridge(sofia/gateway/secretgw/1234)
> EXECUTE sofia/external/hemmeligt at 129.142.224.250
> bridge(sofia/gateway/secretgw/1234)
> 2009-08-26 13:43:29.684236 [NOTICE] switch_channel.c:602 New Channel
> sofia/external/1234 [705ad5d8-9246-11de-ac94-b736da546252]
> 2009-08-26 13:43:29.684236 [DEBUG] mod_sofia.c:2809
> (sofia/external/1234) State Change CS_NEW -> CS_INIT
> 2009-08-26 13:43:29.684236 [DEBUG] switch_core_session.c:932 Send
> signal sofia/external/1234 [BREAK]
> 2009-08-26 13:43:29.684236 [DEBUG] switch_core_state_machine.c:398
> (sofia/external/1234) Running State Change CS_INIT
> 2009-08-26 13:43:29.684236 [DEBUG] switch_core_state_machine.c:481
> (sofia/external/1234) State INIT
> 2009-08-26 13:43:29.684236 [DEBUG] mod_sofia.c:83 sofia/external/1234 SOFIA INIT
> 2009-08-26 13:43:29.684236 [DEBUG] mod_sofia.c:111
> (sofia/external/1234) State Change CS_INIT -> CS_ROUTING
> 2009-08-26 13:43:29.684236 [DEBUG] switch_core_session.c:932 Send
> signal sofia/external/1234 [BREAK]
> 2009-08-26 13:43:29.684236 [DEBUG] sofia.c:3302 Channel
> sofia/external/1234 entering state [calling][0]
> 2009-08-26 13:43:29.684236 [DEBUG] switch_core_state_machine.c:481
> (sofia/external/1234) State INIT going to sleep
> 2009-08-26 13:43:29.684236 [DEBUG] switch_core_state_machine.c:398
> (sofia/external/1234) Running State Change CS_ROUTING
> 2009-08-26 13:43:29.684236 [DEBUG] switch_core_state_machine.c:484
> (sofia/external/1234) State ROUTING
> 2009-08-26 13:43:29.684236 [DEBUG] mod_sofia.c:130 sofia/external/1234
> SOFIA ROUTING
> 2009-08-26 13:43:29.684236 [DEBUG] switch_ivr_originate.c:63
> (sofia/external/1234) State Change CS_ROUTING -> CS_CONSUME_MEDIA
> 2009-08-26 13:43:29.684236 [DEBUG] switch_core_session.c:932 Send
> signal sofia/external/1234 [BREAK]
> 2009-08-26 13:43:29.684236 [DEBUG] switch_core_state_machine.c:484
> (sofia/external/1234) State ROUTING going to sleep
> 2009-08-26 13:43:29.684236 [DEBUG] switch_core_state_machine.c:398
> (sofia/external/1234) Running State Change CS_CONSUME_MEDIA
> 2009-08-26 13:43:29.684236 [DEBUG] switch_core_state_machine.c:503
> (sofia/external/1234) State CONSUME_MEDIA
> 2009-08-26 13:43:29.731221 [DEBUG] sofia.c:3302 Channel
> sofia/external/1234 entering state [calling][0]
> 2009-08-26 13:43:30.660221 [DEBUG] sofia.c:3302 Channel
> sofia/external/1234 entering state [proceeding][183]
> 2009-08-26 13:43:30.660221 [DEBUG] sofia.c:3309 Remote SDP:
> v=0
> o=root 18982 18982 IN IP4 129.142.224.250
> s=session
> c=IN IP4 129.142.224.250
> t=0 0
> m=audio 12480 RTP/AVP 8 101
> a=rtpmap:8 PCMA/8000
> a=rtpmap:101 telephone-event/8000
> a=fmtp:101 0-16
> a=silenceSupp:off - - - -
> a=ptime:20
>
> 2009-08-26 13:43:30.660221 [DEBUG] sofia_glue.c:3132 Audio Codec
> Compare [PCMA:8:8000:20]/[PCMA:8:8000:20]
> 2009-08-26 13:43:30.660221 [DEBUG] sofia_glue.c:2090 Set Codec
> sofia/external/1234 PCMA/8000 20 ms 160 samples
> 2009-08-26 13:43:30.660221 [DEBUG] sofia_glue.c:3092 Set 2833 dtmf
> payload to 101
> 2009-08-26 13:43:30.660221 [DEBUG] sofia_glue.c:2324 AUDIO RTP
> [sofia/external/1234] 10.226.231.225 port 25540 -> 129.142.224.250
> port 12480 codec: 8 ms: 20
> 2009-08-26 13:43:30.660221 [DEBUG] switch_rtp.c:1138 Starting timer
> [soft] 160 bytes per 20ms
> 2009-08-26 13:43:30.661084 [NOTICE] sofia_glue.c:2759 Pre-Answer
> sofia/external/1234!
> 2009-08-26 13:43:30.661084 [DEBUG] switch_channel.c:1778 Send signal
> sofia/external/hemmeligt at 129.142.224.250 [BREAK]
> 2009-08-26 13:43:30.665170 [DEBUG] switch_ivr_originate.c:2061
> Originate Resulted in Success: [sofia/external/1234]
> 2009-08-26 13:43:30.665170 [DEBUG] switch_channel.c:182
> sofia/external/1234 receive message [AUDIO_SYNC]
> 2009-08-26 13:43:30.665170 [DEBUG] switch_channel.c:182
> sofia/external/hemmeligt at 129.142.224.250 receive message [AUDIO_SYNC]
> 2009-08-26 13:43:30.665170 [DEBUG] switch_ivr_bridge.c:889
> sofia/external/1234 receive message [BRIDGE]
> 2009-08-26 13:43:30.665170 [DEBUG] switch_core_session.c:630 Send
> signal sofia/external/1234 [BREAK]
> 2009-08-26 13:43:30.665170 [DEBUG] switch_ivr_bridge.c:896
> sofia/external/hemmeligt at 129.142.224.250 receive message [BRIDGE]
> 2009-08-26 13:43:30.665170 [DEBUG] switch_core_session.c:630 Send
> signal sofia/external/hemmeligt at 129.142.224.250 [BREAK]
> 2009-08-26 13:43:30.665170 [DEBUG] switch_ivr_bridge.c:940
> (sofia/external/1234) State Change CS_CONSUME_MEDIA ->
> CS_EXCHANGE_MEDIA
> 2009-08-26 13:43:30.665170 [DEBUG] switch_core_session.c:932 Send
> signal sofia/external/1234 [BREAK]
> 2009-08-26 13:43:30.705074 [DEBUG] switch_core_state_machine.c:503
> (sofia/external/1234) State CONSUME_MEDIA going to sleep
> 2009-08-26 13:43:30.705074 [DEBUG] switch_core_state_machine.c:398
> (sofia/external/1234) Running State Change CS_EXCHANGE_MEDIA
> 2009-08-26 13:43:30.705074 [DEBUG] switch_core_state_machine.c:494
> (sofia/external/1234) State EXCHANGE_MEDIA
> 2009-08-26 13:43:30.705074 [DEBUG] mod_sofia.c:430 SOFIA LOOPBACK
> 2009-08-26 13:43:36.642173 [DEBUG] sofia.c:3302 Channel
> sofia/external/1234 entering state [ready][200]
> 2009-08-26 13:43:36.642173 [DEBUG] switch_channel.c:1891 Send signal
> sofia/external/hemmeligt at 129.142.224.250 [BREAK]
> 2009-08-26 13:43:36.642173 [NOTICE] sofia.c:3752 Channel
> [sofia/external/1234] has been answered
> 2009-08-26 13:43:36.642173 [DEBUG] switch_channel.c:182
> sofia/external/1234 receive message [AUDIO_SYNC]
> 2009-08-26 13:43:40.309616 [DEBUG] switch_rtp.c:2222 RTP RECV DTMF *:2000
> 2009-08-26 13:43:40.970513 [DEBUG] switch_rtp.c:2222 RTP RECV DTMF 1:2000
> 2009-08-26 13:43:40.970513 [DEBUG] switch_ivr_async.c:1711
> sofia/external/hemmeligt at 129.142.224.250 Processing meta digit '1'
> [bridge::sofia/gateway/secretgw/8888]
> 2009-08-26 13:43:40.970513 [WARNING] switch_ivr_async.c:2310 Channel
> [sofia/external/hemmeligt at 129.142.224.250][bridge::sofia/gateway/secretgw/8888]
> already broadcasting...broadcast aborted
> 2009-08-26 13:43:46.272706 [NOTICE] sofia.c:327 Hangup
> sofia/external/1234 [CS_EXCHANGE_MEDIA] [NORMAL_CLEARING]
> 2009-08-26 13:43:46.272706 [DEBUG] switch_channel.c:1683 Send signal
> sofia/external/1234 [KILL]
> 2009-08-26 13:43:46.272706 [DEBUG] switch_core_session.c:932 Send
> signal sofia/external/1234 [BREAK]
> 2009-08-26 13:43:46.284704 [DEBUG] switch_ivr_bridge.c:371
> sofia/external/1234 ending bridge by request from write function
> 2009-08-26 13:43:46.284704 [DEBUG] switch_ivr_bridge.c:426
> sofia/external/hemmeligt at 129.142.224.250 receive message [UNBRIDGE]
> 2009-08-26 13:43:46.284704 [DEBUG] switch_core_session.c:630 Send
> signal sofia/external/hemmeligt at 129.142.224.250 [BREAK]
> 2009-08-26 13:43:46.284704 [DEBUG] switch_ivr_bridge.c:452 BRIDGE
> THREAD DONE [sofia/external/hemmeligt at 129.142.224.250]
> 2009-08-26 13:43:46.284704 [DEBUG] switch_ivr_bridge.c:454 Send signal
> sofia/external/1234 [BREAK]
> 2009-08-26 13:43:46.284704 [DEBUG] switch_ivr_bridge.c:377
> sofia/external/1234 ending bridge by request from read function
> 2009-08-26 13:43:46.284704 [DEBUG] switch_ivr_bridge.c:452 BRIDGE
> THREAD DONE [sofia/external/1234]
> 2009-08-26 13:43:46.284704 [DEBUG] switch_ivr_bridge.c:454 Send signal
> sofia/external/hemmeligt at 129.142.224.250 [BREAK]
> 2009-08-26 13:43:46.284704 [DEBUG] switch_core_state_machine.c:494
> (sofia/external/1234) State EXCHANGE_MEDIA going to sleep
> 2009-08-26 13:43:46.284704 [DEBUG] switch_core_state_machine.c:398
> (sofia/external/1234) Running State Change CS_HANGUP
> 2009-08-26 13:43:46.284704 [DEBUG] switch_core_state_machine.c:434
> (sofia/external/1234) State HANGUP
> 2009-08-26 13:43:46.284704 [DEBUG] mod_sofia.c:338 Channel
> sofia/external/1234 hanging up, cause: NORMAL_CLEARING
> 2009-08-26 13:43:46.284704 [DEBUG] switch_core_state_machine.c:46
> sofia/external/1234 Standard HANGUP, cause: NORMAL_CLEARING
> 2009-08-26 13:43:46.284704 [DEBUG] switch_core_state_machine.c:434
> (sofia/external/1234) State HANGUP going to sleep
> 2009-08-26 13:43:46.284704 [DEBUG] switch_core_state_machine.c:476
> (sofia/external/1234) State Change CS_HANGUP -> CS_REPORTING
> 2009-08-26 13:43:46.284704 [DEBUG] switch_core_session.c:932 Send
> signal sofia/external/1234 [BREAK]
> 2009-08-26 13:43:46.284704 [DEBUG] switch_core_state_machine.c:398
> (sofia/external/1234) Running State Change CS_REPORTING
> 2009-08-26 13:43:46.284704 [DEBUG] switch_core_state_machine.c:612
> (sofia/external/1234) State REPORTING
> 2009-08-26 13:43:46.284704 [DEBUG] switch_core_state_machine.c:53
> sofia/external/1234 Standard REPORTING, cause: NORMAL_CLEARING
> 2009-08-26 13:43:46.284704 [DEBUG] switch_core_state_machine.c:612
> (sofia/external/1234) State REPORTING going to sleep
> 2009-08-26 13:43:46.284704 [DEBUG] switch_core_state_machine.c:411
> (sofia/external/1234) State Change CS_REPORTING -> CS_DESTROY
> 2009-08-26 13:43:46.284704 [DEBUG] switch_core_session.c:1068 Session
> 5 (sofia/external/1234) Locked, Waiting on external entities
> 2009-08-26 13:43:46.284704 [NOTICE] switch_core_session.c:1086 Session
> 5 (sofia/external/1234) Ended
> 2009-08-26 13:43:46.284704 [NOTICE] switch_core_session.c:1088 Close
> Channel sofia/external/1234 [CS_DESTROY]
> 2009-08-26 13:43:46.284704 [DEBUG] switch_core_state_machine.c:564
> (sofia/external/1234) State DESTROY
> 2009-08-26 13:43:46.284704 [DEBUG] mod_sofia.c:255 sofia/external/1234
> SOFIA DESTROY
> 2009-08-26 13:43:46.284704 [DEBUG] switch_core_state_machine.c:60
> sofia/external/1234 Standard DESTROY
> 2009-08-26 13:43:46.284704 [DEBUG] switch_core_state_machine.c:564
> (sofia/external/1234) State DESTROY going to sleep
> 2009-08-26 13:44:46.746524 [NOTICE] sofia.c:327 Hangup
> sofia/external/hemmeligt at 129.142.224.250 [CS_EXECUTE]
> [NORMAL_CLEARING]
> 2009-08-26 13:44:46.746524 [DEBUG] switch_channel.c:1683 Send signal
> sofia/external/hemmeligt at 129.142.224.250 [KILL]
> 2009-08-26 13:44:46.746524 [DEBUG] switch_core_session.c:932 Send
> signal sofia/external/hemmeligt at 129.142.224.250 [BREAK]
> 2009-08-26 13:44:46.747796 [DEBUG] switch_core_state_machine.c:491
> (sofia/external/hemmeligt at 129.142.224.250) State EXECUTE going to
> sleep
> 2009-08-26 13:44:46.747796 [DEBUG] switch_core_state_machine.c:398
> (sofia/external/hemmeligt at 129.142.224.250) Running State Change
> CS_HANGUP
> 2009-08-26 13:44:46.747796 [DEBUG] switch_core_state_machine.c:434
> (sofia/external/hemmeligt at 129.142.224.250) State HANGUP
> 2009-08-26 13:44:46.747796 [DEBUG] mod_sofia.c:338 Channel
> sofia/external/hemmeligt at 129.142.224.250 hanging up, cause:
> NORMAL_CLEARING
> 2009-08-26 13:44:46.747796 [DEBUG] switch_core_state_machine.c:46
> sofia/external/hemmeligt at 129.142.224.250 Standard HANGUP, cause:
> NORMAL_CLEARING
> 2009-08-26 13:44:46.747796 [DEBUG] switch_core_state_machine.c:434
> (sofia/external/hemmeligt at 129.142.224.250) State HANGUP going to sleep
> 2009-08-26 13:44:46.747796 [DEBUG] switch_core_state_machine.c:476
> (sofia/external/hemmeligt at 129.142.224.250) State Change CS_HANGUP ->
> CS_REPORTING
> 2009-08-26 13:44:46.747796 [DEBUG] switch_core_session.c:932 Send
> signal sofia/external/hemmeligt at 129.142.224.250 [BREAK]
> 2009-08-26 13:44:46.747796 [DEBUG] switch_core_state_machine.c:398
> (sofia/external/hemmeligt at 129.142.224.250) Running State Change
> CS_REPORTING
> 2009-08-26 13:44:46.747796 [DEBUG] switch_core_state_machine.c:612
> (sofia/external/hemmeligt at 129.142.224.250) State REPORTING
> 2009-08-26 13:44:46.747796 [DEBUG] switch_core_state_machine.c:53
> sofia/external/hemmeligt at 129.142.224.250 Standard REPORTING, cause:
> NORMAL_CLEARING
> 2009-08-26 13:44:46.747796 [DEBUG] switch_core_state_machine.c:612
> (sofia/external/hemmeligt at 129.142.224.250) State REPORTING going to
> sleep
> 2009-08-26 13:44:46.747796 [DEBUG] switch_core_state_machine.c:411
> (sofia/external/hemmeligt at 129.142.224.250) State Change CS_REPORTING
> -> CS_DESTROY
> 2009-08-26 13:44:46.747796 [DEBUG] switch_core_session.c:1068 Session
> 4 (sofia/external/hemmeligt at 129.142.224.250) Locked, Waiting on
> external entities
> 2009-08-26 13:44:46.747796 [NOTICE] switch_core_session.c:1086 Session
> 4 (sofia/external/hemmeligt at 129.142.224.250) Ended
> 2009-08-26 13:44:46.747796 [NOTICE] switch_core_session.c:1088 Close
> Channel sofia/external/hemmeligt at 129.142.224.250 [CS_DESTROY]
> 2009-08-26 13:44:46.747796 [DEBUG] switch_core_state_machine.c:564
> (sofia/external/hemmeligt at 129.142.224.250) State DESTROY
> 2009-08-26 13:44:46.747796 [DEBUG] mod_sofia.c:255
> sofia/external/hemmeligt at 129.142.224.250 SOFIA DESTROY
> 2009-08-26 13:44:46.747796 [DEBUG] switch_core_state_machine.c:60
> sofia/external/hemmeligt at 129.142.224.250 Standard DESTROY
> 2009-08-26 13:44:46.747796 [DEBUG] switch_core_state_machine.c:564
> (sofia/external/hemmeligt at 129.142.224.250) State DESTROY going to
> sleep
>
> Of which I mainly find these interesting:
>
> EXECUTE sofia/external/hemmeligt at 129.142.224.250 bind_meta_app(1 b a
> bridge::sofia/gateway/secretgw/8888)
> 2009-08-26 13:43:26.388737 [INFO] switch_ivr_async.c:1795 Bound B-Leg:
> 1 bridge::sofia/gateway/secretgw/8888
> [...]
> 2009-08-26 13:43:40.309616 [DEBUG] switch_rtp.c:2222 RTP RECV DTMF *:2000
> 2009-08-26 13:43:40.970513 [DEBUG] switch_rtp.c:2222 RTP RECV DTMF 1:2000
> 2009-08-26 13:43:40.970513 [DEBUG] switch_ivr_async.c:1711
> sofia/external/hemmeligt at 129.142.224.250 Processing meta digit '1'
> [bridge::sofia/gateway/secretgw/8888]
> 2009-08-26 13:43:40.970513 [WARNING] switch_ivr_async.c:2310 Channel
> [sofia/external/hemmeligt at 129.142.224.250][bridge::sofia/gateway/secretgw/8888]
> already broadcasting...broadcast aborted
>
> Can anybody explain what is going on here? It seems like the
> bind_meta_app is bound perfectly via event socket, but when it comes
> down, it doesn't work.
>
> Best regards,
> Harry
>