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

Harry Vangberg harry at vangberg.name
Wed Aug 26 06:54:41 PDT 2009 

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

More information about the FreeSWITCH-users mailing list