Hello. I am controlling my calls with Freeswitcher via the event socket. When a call comes in I set the following channel variables: hangup_after_bridge=true ignore_early_media=true call_timeout=20 originate_continue_on_timeout=true instant_ringback=true ringback=%(2000,4000,440,480) transfer_ringback=%(2000,4000,440,480) Then I pre_answer and bridge to one or more endpoints. The trouble is, there's no ringback. This is with trunk@16305. For reference, here's excerpt from the log: 2010-01-14 22:47:14.540747 [NOTICE] switch_channel.c:642 New Channel sofia/external/31354228@129.142.224.250 [c27529c2-015e-11df-8d0d-c7205d2c96c7] 2010-01-14 22:47:14.540747 [DEBUG] sofia.c:3897 Channel sofia/external/31354228@129.142.224.250 entering state [received][100] 2010-01-14 22:47:14.540747 [DEBUG] sofia.c:3908 Remote SDP: v=0 o=root 22377 22377 IN IP4 129.142.224.250 s=session c=IN IP4 129.142.224.250 t=0 0 m=audio 14962 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 2010-01-14 22:47:14.540747 [DEBUG] sofia_glue.c:3344 Audio Codec Compare [PCMA:8:8000:20]/[PCMA:8:8000:20] 2010-01-14 22:47:14.540747 [DEBUG] sofia_glue.c:2171 Set Codec sofia/external/31354228@129.142.224.250 PCMA/8000 20 ms 160 samples 2010-01-14 22:47:14.540747 [DEBUG] sofia_glue.c:3300 Set 2833 dtmf payload to 101 2010-01-14 22:47:14.540747 [DEBUG] sofia.c:4056 (sofia/external/31354228@129.142.224.250) State Change CS_NEW -> CS_INIT 2010-01-14 22:47:14.540747 [DEBUG] switch_core_session.c:1012 Send signal sofia/external/31354228@129.142.224.250 [BREAK] 2010-01-14 22:47:14.540747 [DEBUG] switch_core_state_machine.c:314 (sofia/external/31354228@129.142.224.250) Running State Change CS_INIT 2010-01-14 22:47:14.540747 [DEBUG] switch_core_state_machine.c:338 (sofia/external/31354228@129.142.224.250) State INIT 2010-01-14 22:47:14.540747 [DEBUG] mod_sofia.c:83 sofia/external/31354228@129.142.224.250 SOFIA INIT 2010-01-14 22:47:14.540747 [DEBUG] mod_sofia.c:111 (sofia/external/31354228@129.142.224.250) State Change CS_INIT -> CS_ROUTING 2010-01-14 22:47:14.540747 [DEBUG] switch_core_session.c:1012 Send signal sofia/external/31354228@129.142.224.250 [BREAK] 2010-01-14 22:47:14.540747 [DEBUG] switch_core_state_machine.c:338 (sofia/external/31354228@129.142.224.250) State INIT going to sleep 2010-01-14 22:47:14.540747 [DEBUG] switch_core_state_machine.c:314 (sofia/external/31354228@129.142.224.250) Running State Change CS_ROUTING 2010-01-14 22:47:14.540747 [DEBUG] switch_core_state_machine.c:341 (sofia/external/31354228@129.142.224.250) State ROUTING 2010-01-14 22:47:14.540747 [DEBUG] mod_sofia.c:132 sofia/external/31354228@129.142.224.250 SOFIA ROUTING 2010-01-14 22:47:14.540747 [DEBUG] switch_core_state_machine.c:78 sofia/external/31354228@129.142.224.250 Standard ROUTING 2010-01-14 22:47:14.540747 [INFO] mod_dialplan_xml.c:408 Processing 31354228->77344536 in context public Dialplan: sofia/external/31354228@129.142.224.250 parsing [public->ff-phone-sound-recorder] continue=false Dialplan: sofia/external/31354228@129.142.224.250 Regex (FAIL) [ff-phone-sound-recorder] destination_number(77344536) =~ /^77348624$/ break=on-false Dialplan: sofia/external/31354228@129.142.224.250 parsing [public->ff-ivr] continue=false Dialplan: sofia/external/31354228@129.142.224.250 Regex (PASS) [ff-ivr] destination_number(77344536) =~ /^(\d+)$/ break=on-false Dialplan: sofia/external/31354228@129.142.224.250 Action socket(127.0.0.1:8084 full) 2010-01-14 22:47:14.540747 [DEBUG] switch_core_state_machine.c:122 (sofia/external/31354228@129.142.224.250) State Change CS_ROUTING -> CS_EXECUTE 2010-01-14 22:47:14.540747 [DEBUG] switch_core_session.c:1012 Send signal sofia/external/31354228@129.142.224.250 [BREAK] 2010-01-14 22:47:14.540747 [DEBUG] switch_core_state_machine.c:341 (sofia/external/31354228@129.142.224.250) State ROUTING going to sleep 2010-01-14 22:47:14.540747 [DEBUG] switch_core_state_machine.c:314 (sofia/external/31354228@129.142.224.250) Running State Change CS_EXECUTE 2010-01-14 22:47:14.540747 [DEBUG] switch_core_state_machine.c:348 (sofia/external/31354228@129.142.224.250) State EXECUTE 2010-01-14 22:47:14.540747 [DEBUG] mod_sofia.c:181 sofia/external/31354228@129.142.224.250 SOFIA EXECUTE 2010-01-14 22:47:14.540747 [DEBUG] switch_core_state_machine.c:159 sofia/external/31354228@129.142.224.250 Standard EXECUTE EXECUTE sofia/external/31354228@129.142.224.250 socket(127.0.0.1:8084 full) 2010-01-14 22:47:14.792781 [DEBUG] switch_ivr.c:551 sofia/external/31354228@129.142.224.250 Command Execute set(hangup_after_bridge=true) EXECUTE sofia/external/31354228@129.142.224.250 set(hangup_after_bridge=true) 2010-01-14 22:47:14.792781 [DEBUG] mod_dptools.c:818 sofia/external/31354228@129.142.224.250 SET [hangup_after_bridge]=[true] 2010-01-14 22:47:14.792781 [DEBUG] switch_ivr.c:551 sofia/external/31354228@129.142.224.250 Command Execute set(ignore_early_media=true) EXECUTE sofia/external/31354228@129.142.224.250 set(ignore_early_media=true) 2010-01-14 22:47:14.792781 [DEBUG] mod_dptools.c:818 sofia/external/31354228@129.142.224.250 SET [ignore_early_media]=[true] 2010-01-14 22:47:14.792781 [DEBUG] switch_ivr.c:551 sofia/external/31354228@129.142.224.250 Command Execute set(call_timeout=20) EXECUTE sofia/external/31354228@129.142.224.250 set(call_timeout=20) 2010-01-14 22:47:14.792781 [DEBUG] mod_dptools.c:818 sofia/external/31354228@129.142.224.250 SET [call_timeout]=[20] 2010-01-14 22:47:14.792781 [DEBUG] switch_ivr.c:551 sofia/external/31354228@129.142.224.250 Command Execute set(originate_continue_on_timeout=true) EXECUTE sofia/external/31354228@129.142.224.250 set(originate_continue_on_timeout=true) 2010-01-14 22:47:14.792781 [DEBUG] mod_dptools.c:818 sofia/external/31354228@129.142.224.250 SET [originate_continue_on_timeout]=[true] 2010-01-14 22:47:14.792781 [DEBUG] switch_ivr.c:551 sofia/external/31354228@129.142.224.250 Command Execute set(instant_ringback=true) EXECUTE sofia/external/31354228@129.142.224.250 set(instant_ringback=true) 2010-01-14 22:47:14.792781 [DEBUG] mod_dptools.c:818 sofia/external/31354228@129.142.224.250 SET [instant_ringback]=[true] 2010-01-14 22:47:14.792781 [DEBUG] switch_ivr.c:551 sofia/external/31354228@129.142.224.250 Command Execute set(ringback=%(2000,4000,440,480)) EXECUTE sofia/external/31354228@129.142.224.250 set(ringback=%(2000,4000,440,480)) 2010-01-14 22:47:14.792781 [DEBUG] mod_dptools.c:818 sofia/external/31354228@129.142.224.250 SET [ringback]=[%(2000,4000,440,480)] 2010-01-14 22:47:14.792781 [DEBUG] switch_ivr.c:551 sofia/external/31354228@129.142.224.250 Command Execute set(transfer_ringback=%(2000,4000,440,480)) EXECUTE sofia/external/31354228@129.142.224.250 set(transfer_ringback=%(2000,4000,440,480)) 2010-01-14 22:47:14.792781 [DEBUG] mod_dptools.c:818 sofia/external/31354228@129.142.224.250 SET [transfer_ringback]=[%(2000,4000,440,480)] 2010-01-14 22:47:14.792781 [DEBUG] switch_ivr.c:551 sofia/external/31354228@129.142.224.250 Command Execute bind_meta_app(6 b ai transfer::ff-transfer-sofia/gateway/gw1.fonet.dk/004546934488 XML public) EXECUTE sofia/external/31354228@129.142.224.250 bind_meta_app(6 b ai transfer::ff-transfer-sofia/gateway/gw1.fonet.dk/004546934488 XML public) 2010-01-14 22:47:14.792781 [INFO] switch_ivr_async.c:2322 Bound B-Leg: 6 transfer::ff-transfer-sofia/gateway/gw1.fonet.dk/004546934488 XML public 2010-01-14 22:47:14.792781 [DEBUG] switch_ivr.c:551 sofia/external/31354228@129.142.224.250 Command Execute bind_meta_app(7 b ai transfer::ff-transfer- XML public) EXECUTE sofia/external/31354228@129.142.224.250 bind_meta_app(7 b ai transfer::ff-transfer- XML public) 2010-01-14 22:47:14.792781 [INFO] switch_ivr_async.c:2322 Bound B-Leg: 7 transfer::ff-transfer- XML public 2010-01-14 22:47:14.792781 [DEBUG] switch_ivr.c:551 sofia/external/31354228@129.142.224.250 Command Execute bind_meta_app(1 b ai transfer::ff-transfer-sofia/gateway/gw1.fonet.dk/004546934488 XML public) EXECUTE sofia/external/31354228@129.142.224.250 bind_meta_app(1 b ai transfer::ff-transfer-sofia/gateway/gw1.fonet.dk/004546934488 XML public) 2010-01-14 22:47:14.792781 [INFO] switch_ivr_async.c:2322 Bound B-Leg: 1 transfer::ff-transfer-sofia/gateway/gw1.fonet.dk/004546934488 XML public 2010-01-14 22:47:14.792781 [DEBUG] switch_ivr.c:551 sofia/external/31354228@129.142.224.250 Command Execute pre_answer() EXECUTE sofia/external/31354228@129.142.224.250 pre_answer() 2010-01-14 22:47:14.792781 [DEBUG] mod_dptools.c:736 sofia/external/31354228@129.142.224.250 receive message [PROGRESS] 2010-01-14 22:47:14.792781 [INFO] mod_dptools.c:736 Sending early media 2010-01-14 22:47:14.792781 [DEBUG] sofia_glue.c:2409 AUDIO RTP [sofia/external/31354228@129.142.224.250] 10.224.54.102 port 22822 -> 129.142.224.250 port 14962 codec: 8 ms: 20 2010-01-14 22:47:14.792781 [DEBUG] switch_rtp.c:1168 Starting timer [soft] 160 bytes per 20ms 2010-01-14 22:47:14.807902 [INFO] mod_sofia.c:1779 Ring SDP: v=0 o=FreeSWITCH 1263486412 1263486413 IN IP4 79.125.35.134 s=FreeSWITCH c=IN IP4 79.125.35.134 t=0 0 m=audio 22822 RTP/AVP 8 a=rtpmap:8 PCMA/8000 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv 2010-01-14 22:47:14.807902 [NOTICE] mod_sofia.c:1782 Pre-Answer sofia/external/31354228@129.142.224.250! 2010-01-14 22:47:14.807902 [DEBUG] switch_core_session.c:633 Send signal sofia/external/31354228@129.142.224.250 [BREAK] 2010-01-14 22:47:14.827576 [DEBUG] sofia.c:3892 Channel sofia/external/31354228@129.142.224.250 skipping state [early][183] 2010-01-14 22:47:14.827576 [DEBUG] switch_ivr.c:551 sofia/external/31354228@129.142.224.250 Command Execute bridge({sip_cid_type=rpid,origination_caller_id_name=77344536,origination_caller_id_number=77344536}sofia/gateway/gw1.fonet.dk/004546934488|loopback/ff-record-77344536) EXECUTE sofia/external/31354228@129.142.224.250 bridge({sip_cid_type=rpid,origination_caller_id_name=77344536,origination_caller_id_number=77344536}sofia/gateway/gw1.fonet.dk/004546934488|loopback/ff-record-77344536) 2010-01-14 22:47:14.827576 [DEBUG] switch_ivr_originate.c:1738 variable string 0 = [sip_cid_type=rpid] 2010-01-14 22:47:14.827576 [DEBUG] switch_ivr_originate.c:1738 variable string 1 = [origination_caller_id_name=77344536] 2010-01-14 22:47:14.827576 [DEBUG] switch_ivr_originate.c:1738 variable string 2 = [origination_caller_id_number=77344536] 2010-01-14 22:47:14.827576 [NOTICE] switch_channel.c:642 New Channel sofia/external/004546934488 [c2a1095c-015e-11df-8d0e-c7205d2c96c7] 2010-01-14 22:47:14.827576 [DEBUG] mod_sofia.c:3227 (sofia/external/004546934488) State Change CS_NEW -> CS_INIT 2010-01-14 22:47:14.827576 [DEBUG] switch_core_session.c:1012 Send signal sofia/external/004546934488 [BREAK] 2010-01-14 22:47:14.827576 [DEBUG] switch_core_state_machine.c:314 (sofia/external/004546934488) Running State Change CS_INIT 2010-01-14 22:47:14.827576 [DEBUG] switch_core_state_machine.c:338 (sofia/external/004546934488) State INIT 2010-01-14 22:47:14.827576 [DEBUG] mod_sofia.c:83 sofia/external/004546934488 SOFIA INIT 2010-01-14 22:47:14.827576 [DEBUG] mod_sofia.c:111 (sofia/external/004546934488) State Change CS_INIT -> CS_ROUTING 2010-01-14 22:47:14.827576 [DEBUG] switch_core_session.c:1012 Send signal sofia/external/004546934488 [BREAK] 2010-01-14 22:47:14.827576 [DEBUG] sofia.c:3897 Channel sofia/external/004546934488 entering state [calling][0] 2010-01-14 22:47:14.827576 [DEBUG] switch_core_state_machine.c:338 (sofia/external/004546934488) State INIT going to sleep 2010-01-14 22:47:14.827576 [DEBUG] switch_core_state_machine.c:314 (sofia/external/004546934488) Running State Change CS_ROUTING 2010-01-14 22:47:14.827576 [DEBUG] switch_core_state_machine.c:341 (sofia/external/004546934488) State ROUTING 2010-01-14 22:47:14.827576 [DEBUG] mod_sofia.c:132 sofia/external/004546934488 SOFIA ROUTING 2010-01-14 22:47:14.827576 [DEBUG] switch_ivr_originate.c:66 (sofia/external/004546934488) State Change CS_ROUTING -> CS_CONSUME_MEDIA 2010-01-14 22:47:14.827576 [DEBUG] switch_core_session.c:1012 Send signal sofia/external/004546934488 [BREAK] 2010-01-14 22:47:14.827576 [DEBUG] switch_core_state_machine.c:341 (sofia/external/004546934488) State ROUTING going to sleep 2010-01-14 22:47:14.827576 [DEBUG] switch_core_state_machine.c:314 (sofia/external/004546934488) Running State Change CS_CONSUME_MEDIA 2010-01-14 22:47:14.827576 [DEBUG] switch_core_state_machine.c:360 (sofia/external/004546934488) State CONSUME_MEDIA 2010-01-14 22:47:14.827576 [DEBUG] switch_core_state_machine.c:360 (sofia/external/004546934488) State CONSUME_MEDIA going to sleep 2010-01-14 22:47:14.876945 [DEBUG] switch_ivr_originate.c:1057 Raw Codec Activation Success L16@8000hz 1 channel 20ms 2010-01-14 22:47:14.876945 [DEBUG] switch_core_codec.c:112 sofia/external/31354228@129.142.224.250 Push codec L16:10 2010-01-14 22:47:14.876945 [DEBUG] switch_ivr_originate.c:1119 Play Ringback Tone [%(2000,4000,440,480)] 2010-01-14 22:47:14.876945 [DEBUG] switch_core_io.c:652 sofia/external/31354228@129.142.224.250 receive message [TRANSCODING_NECESSARY] 2010-01-14 22:47:14.876945 [DEBUG] sofia.c:3897 Channel sofia/external/004546934488 entering state [calling][0] 2010-01-14 22:47:14.912774 [DEBUG] switch_rtp.c:2022 Correct ip/port confirmed. 2010-01-14 22:47:15.668817 [INFO] sofia.c:514 Update Callee ID to "004546934488" <004546934488> 2010-01-14 22:47:15.668817 [DEBUG] sofia.c:3897 Channel sofia/external/004546934488 entering state [proceeding][180] 2010-01-14 22:47:15.668817 [NOTICE] sofia.c:3967 Ring-Ready sofia/external/004546934488! 2010-01-14 22:47:15.668817 [DEBUG] sofia.c:3897 Channel sofia/external/004546934488 entering state [proceeding][183] 2010-01-14 22:47:15.668817 [DEBUG] sofia.c:3908 Remote SDP: v=0 o=root 22377 22377 IN IP4 129.142.224.250 s=session c=IN IP4 129.142.224.250 t=0 0 m=audio 11676 RTP/AVP 8 a=rtpmap:8 PCMA/8000 a=silenceSupp:off - - - - a=ptime:20 2010-01-14 22:47:15.668817 [DEBUG] sofia_glue.c:3344 Audio Codec Compare [PCMA:8:8000:20]/[PCMA:8:8000:20] 2010-01-14 22:47:15.668817 [DEBUG] sofia_glue.c:2171 Set Codec sofia/external/004546934488 PCMA/8000 20 ms 160 samples 2010-01-14 22:47:15.668817 [DEBUG] sofia_glue.c:2409 AUDIO RTP [sofia/external/004546934488] 10.224.54.102 port 17204 -> 129.142.224.250 port 11676 codec: 8 ms: 20 2010-01-14 22:47:15.668817 [DEBUG] switch_rtp.c:1168 Starting timer [soft] 160 bytes per 20ms 2010-01-14 22:47:15.668817 [NOTICE] sofia_glue.c:2937 Pre-Answer sofia/external/004546934488! 2010-01-14 22:47:15.668817 [DEBUG] switch_channel.c:2053 Send signal sofia/external/31354228@129.142.224.250 [BREAK] -- Harry Vangberg <harry@vangberg.name> http://harry.vangberg.name