bind_meta_app: "already broadcasting..broadcast aborted" if bound via event socket
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@129.142.224.250 [681102bc-9246-11de-ac94-b736da546252] 2009-08-26 13:43:15.778388 [DEBUG] sofia.c:3302 Channel sofia/external/hemmeligt@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@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@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@129.142.224.250 [BREAK] 2009-08-26 13:43:15.778388 [DEBUG] switch_core_state_machine.c:398 (sofia/external/hemmeligt@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@129.142.224.250) State INIT 2009-08-26 13:43:15.778388 [DEBUG] mod_sofia.c:83 sofia/external/hemmeligt@129.142.224.250 SOFIA INIT 2009-08-26 13:43:15.778388 [DEBUG] mod_sofia.c:111 (sofia/external/hemmeligt@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@129.142.224.250 [BREAK] 2009-08-26 13:43:15.778388 [DEBUG] switch_core_state_machine.c:481 (sofia/external/hemmeligt@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@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@129.142.224.250) State ROUTING 2009-08-26 13:43:15.778388 [DEBUG] mod_sofia.c:130 sofia/external/hemmeligt@129.142.224.250 SOFIA ROUTING 2009-08-26 13:43:15.778388 [DEBUG] switch_core_state_machine.c:78 sofia/external/hemmeligt@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@129.142.224.250 parsing [public->ff-ivr] continue=false Dialplan: sofia/external/hemmeligt@129.142.224.250 Regex (PASS) [ff-ivr] destination_number(77344541) =~ /^(.*)$/ break=on-false Dialplan: sofia/external/hemmeligt@129.142.224.250 Action set(bypass_media=false) Dialplan: sofia/external/hemmeligt@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@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@129.142.224.250 [BREAK] 2009-08-26 13:43:15.778388 [DEBUG] switch_core_state_machine.c:484 (sofia/external/hemmeligt@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@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@129.142.224.250) State EXECUTE 2009-08-26 13:43:15.778388 [DEBUG] mod_sofia.c:173 sofia/external/hemmeligt@129.142.224.250 SOFIA EXECUTE 2009-08-26 13:43:15.778388 [DEBUG] switch_core_state_machine.c:151 sofia/external/hemmeligt@129.142.224.250 Standard EXECUTE EXECUTE sofia/external/hemmeligt@129.142.224.250 set(bypass_media=false) 2009-08-26 13:43:15.778388 [DEBUG] mod_dptools.c:748 sofia/external/hemmeligt@129.142.224.250 SET [bypass_media]=[false] EXECUTE sofia/external/hemmeligt@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@129.142.224.250 Command Execute answer() EXECUTE sofia/external/hemmeligt@129.142.224.250 answer() 2009-08-26 13:43:21.701447 [DEBUG] mod_dptools.c:649 sofia/external/hemmeligt@129.142.224.250 receive message [ANSWER] 2009-08-26 13:43:21.701447 [DEBUG] sofia_glue.c:2324 AUDIO RTP [sofia/external/hemmeligt@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@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@129.142.224.250 [BREAK] 2009-08-26 13:43:21.702447 [NOTICE] mod_dptools.c:649 Channel [sofia/external/hemmeligt@129.142.224.250] has been answered 2009-08-26 13:43:21.702447 [DEBUG] switch_channel.c:182 sofia/external/hemmeligt@129.142.224.250 receive message [AUDIO_SYNC] 2009-08-26 13:43:21.702447 [DEBUG] sofia.c:3302 Channel sofia/external/hemmeligt@129.142.224.250 entering state [completed][200] 2009-08-26 13:43:21.782616 [DEBUG] sofia.c:3302 Channel sofia/external/hemmeligt@129.142.224.250 entering state [ready][200] 2009-08-26 13:43:26.388737 [DEBUG] switch_ivr.c:540 sofia/external/hemmeligt@129.142.224.250 Command Execute bind_meta_app(1 b a bridge::sofia/gateway/secretgw/8888) EXECUTE sofia/external/hemmeligt@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@129.142.224.250 Command Execute bridge(sofia/gateway/secretgw/1234) EXECUTE sofia/external/hemmeligt@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@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@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@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@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@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@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@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@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@129.142.224.250 [BREAK] 2009-08-26 13:43:46.284704 [DEBUG] switch_ivr_bridge.c:452 BRIDGE THREAD DONE [sofia/external/hemmeligt@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@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@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@129.142.224.250 [KILL] 2009-08-26 13:44:46.746524 [DEBUG] switch_core_session.c:932 Send signal sofia/external/hemmeligt@129.142.224.250 [BREAK] 2009-08-26 13:44:46.747796 [DEBUG] switch_core_state_machine.c:491 (sofia/external/hemmeligt@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@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@129.142.224.250) State HANGUP 2009-08-26 13:44:46.747796 [DEBUG] mod_sofia.c:338 Channel sofia/external/hemmeligt@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@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@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@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@129.142.224.250 [BREAK] 2009-08-26 13:44:46.747796 [DEBUG] switch_core_state_machine.c:398 (sofia/external/hemmeligt@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@129.142.224.250) State REPORTING 2009-08-26 13:44:46.747796 [DEBUG] switch_core_state_machine.c:53 sofia/external/hemmeligt@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@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@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@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@129.142.224.250) Ended 2009-08-26 13:44:46.747796 [NOTICE] switch_core_session.c:1088 Close Channel sofia/external/hemmeligt@129.142.224.250 [CS_DESTROY] 2009-08-26 13:44:46.747796 [DEBUG] switch_core_state_machine.c:564 (sofia/external/hemmeligt@129.142.224.250) State DESTROY 2009-08-26 13:44:46.747796 [DEBUG] mod_sofia.c:255 sofia/external/hemmeligt@129.142.224.250 SOFIA DESTROY 2009-08-26 13:44:46.747796 [DEBUG] switch_core_state_machine.c:60 sofia/external/hemmeligt@129.142.224.250 Standard DESTROY 2009-08-26 13:44:46.747796 [DEBUG] switch_core_state_machine.c:564 (sofia/external/hemmeligt@129.142.224.250) State DESTROY going to sleep Of which I mainly find these interesting: EXECUTE sofia/external/hemmeligt@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@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@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
For your information, revision 14644 committed by anthm fixes this. Again, thanks! 2009/8/26 Harry Vangberg <harry@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@129.142.224.250 [681102bc-9246-11de-ac94-b736da546252] 2009-08-26 13:43:15.778388 [DEBUG] sofia.c:3302 Channel sofia/external/hemmeligt@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@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@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@129.142.224.250 [BREAK] 2009-08-26 13:43:15.778388 [DEBUG] switch_core_state_machine.c:398 (sofia/external/hemmeligt@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@129.142.224.250) State INIT 2009-08-26 13:43:15.778388 [DEBUG] mod_sofia.c:83 sofia/external/hemmeligt@129.142.224.250 SOFIA INIT 2009-08-26 13:43:15.778388 [DEBUG] mod_sofia.c:111 (sofia/external/hemmeligt@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@129.142.224.250 [BREAK] 2009-08-26 13:43:15.778388 [DEBUG] switch_core_state_machine.c:481 (sofia/external/hemmeligt@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@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@129.142.224.250) State ROUTING 2009-08-26 13:43:15.778388 [DEBUG] mod_sofia.c:130 sofia/external/hemmeligt@129.142.224.250 SOFIA ROUTING 2009-08-26 13:43:15.778388 [DEBUG] switch_core_state_machine.c:78 sofia/external/hemmeligt@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@129.142.224.250 parsing [public->ff-ivr] continue=false Dialplan: sofia/external/hemmeligt@129.142.224.250 Regex (PASS) [ff-ivr] destination_number(77344541) =~ /^(.*)$/ break=on-false Dialplan: sofia/external/hemmeligt@129.142.224.250 Action set(bypass_media=false) Dialplan: sofia/external/hemmeligt@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@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@129.142.224.250 [BREAK] 2009-08-26 13:43:15.778388 [DEBUG] switch_core_state_machine.c:484 (sofia/external/hemmeligt@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@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@129.142.224.250) State EXECUTE 2009-08-26 13:43:15.778388 [DEBUG] mod_sofia.c:173 sofia/external/hemmeligt@129.142.224.250 SOFIA EXECUTE 2009-08-26 13:43:15.778388 [DEBUG] switch_core_state_machine.c:151 sofia/external/hemmeligt@129.142.224.250 Standard EXECUTE EXECUTE sofia/external/hemmeligt@129.142.224.250 set(bypass_media=false) 2009-08-26 13:43:15.778388 [DEBUG] mod_dptools.c:748 sofia/external/hemmeligt@129.142.224.250 SET [bypass_media]=[false] EXECUTE sofia/external/hemmeligt@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@129.142.224.250 Command Execute answer() EXECUTE sofia/external/hemmeligt@129.142.224.250 answer() 2009-08-26 13:43:21.701447 [DEBUG] mod_dptools.c:649 sofia/external/hemmeligt@129.142.224.250 receive message [ANSWER] 2009-08-26 13:43:21.701447 [DEBUG] sofia_glue.c:2324 AUDIO RTP [sofia/external/hemmeligt@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@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@129.142.224.250 [BREAK] 2009-08-26 13:43:21.702447 [NOTICE] mod_dptools.c:649 Channel [sofia/external/hemmeligt@129.142.224.250] has been answered 2009-08-26 13:43:21.702447 [DEBUG] switch_channel.c:182 sofia/external/hemmeligt@129.142.224.250 receive message [AUDIO_SYNC] 2009-08-26 13:43:21.702447 [DEBUG] sofia.c:3302 Channel sofia/external/hemmeligt@129.142.224.250 entering state [completed][200] 2009-08-26 13:43:21.782616 [DEBUG] sofia.c:3302 Channel sofia/external/hemmeligt@129.142.224.250 entering state [ready][200] 2009-08-26 13:43:26.388737 [DEBUG] switch_ivr.c:540 sofia/external/hemmeligt@129.142.224.250 Command Execute bind_meta_app(1 b a bridge::sofia/gateway/secretgw/8888) EXECUTE sofia/external/hemmeligt@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@129.142.224.250 Command Execute bridge(sofia/gateway/secretgw/1234) EXECUTE sofia/external/hemmeligt@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@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@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@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@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@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@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@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@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@129.142.224.250 [BREAK] 2009-08-26 13:43:46.284704 [DEBUG] switch_ivr_bridge.c:452 BRIDGE THREAD DONE [sofia/external/hemmeligt@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@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@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@129.142.224.250 [KILL] 2009-08-26 13:44:46.746524 [DEBUG] switch_core_session.c:932 Send signal sofia/external/hemmeligt@129.142.224.250 [BREAK] 2009-08-26 13:44:46.747796 [DEBUG] switch_core_state_machine.c:491 (sofia/external/hemmeligt@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@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@129.142.224.250) State HANGUP 2009-08-26 13:44:46.747796 [DEBUG] mod_sofia.c:338 Channel sofia/external/hemmeligt@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@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@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@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@129.142.224.250 [BREAK] 2009-08-26 13:44:46.747796 [DEBUG] switch_core_state_machine.c:398 (sofia/external/hemmeligt@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@129.142.224.250) State REPORTING 2009-08-26 13:44:46.747796 [DEBUG] switch_core_state_machine.c:53 sofia/external/hemmeligt@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@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@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@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@129.142.224.250) Ended 2009-08-26 13:44:46.747796 [NOTICE] switch_core_session.c:1088 Close Channel sofia/external/hemmeligt@129.142.224.250 [CS_DESTROY] 2009-08-26 13:44:46.747796 [DEBUG] switch_core_state_machine.c:564 (sofia/external/hemmeligt@129.142.224.250) State DESTROY 2009-08-26 13:44:46.747796 [DEBUG] mod_sofia.c:255 sofia/external/hemmeligt@129.142.224.250 SOFIA DESTROY 2009-08-26 13:44:46.747796 [DEBUG] switch_core_state_machine.c:60 sofia/external/hemmeligt@129.142.224.250 Standard DESTROY 2009-08-26 13:44:46.747796 [DEBUG] switch_core_state_machine.c:564 (sofia/external/hemmeligt@129.142.224.250) State DESTROY going to sleep
Of which I mainly find these interesting:
EXECUTE sofia/external/hemmeligt@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@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@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
participants (1)
-
Harry Vangberg