[Freeswitch-users] No ringback.

Harry Vangberg harry at vangberg.name
Thu Jan 14 15:06:07 PST 2010 

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 at 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 at 129.142.224.250
[c27529c2-015e-11df-8d0d-c7205d2c96c7]
2010-01-14 22:47:14.540747 [DEBUG] sofia.c:3897 Channel
sofia/external/31354228 at 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 at 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 at 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 at 129.142.224.250 [BREAK]
2010-01-14 22:47:14.540747 [DEBUG] switch_core_state_machine.c:314
(sofia/external/31354228 at 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 at 129.142.224.250) State INIT
2010-01-14 22:47:14.540747 [DEBUG] mod_sofia.c:83
sofia/external/31354228 at 129.142.224.250 SOFIA INIT
2010-01-14 22:47:14.540747 [DEBUG] mod_sofia.c:111
(sofia/external/31354228 at 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 at 129.142.224.250 [BREAK]
2010-01-14 22:47:14.540747 [DEBUG] switch_core_state_machine.c:338
(sofia/external/31354228 at 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 at 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 at 129.142.224.250) State ROUTING
2010-01-14 22:47:14.540747 [DEBUG] mod_sofia.c:132
sofia/external/31354228 at 129.142.224.250 SOFIA ROUTING
2010-01-14 22:47:14.540747 [DEBUG] switch_core_state_machine.c:78
sofia/external/31354228 at 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 at 129.142.224.250 parsing
[public->ff-phone-sound-recorder] continue=false
Dialplan: sofia/external/31354228 at 129.142.224.250 Regex (FAIL)
[ff-phone-sound-recorder] destination_number(77344536) =~ /^77348624$/
break=on-false
Dialplan: sofia/external/31354228 at 129.142.224.250 parsing
[public->ff-ivr] continue=false
Dialplan: sofia/external/31354228 at 129.142.224.250 Regex (PASS)
[ff-ivr] destination_number(77344536) =~ /^(\d+)$/ break=on-false
Dialplan: sofia/external/31354228 at 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 at 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 at 129.142.224.250 [BREAK]
2010-01-14 22:47:14.540747 [DEBUG] switch_core_state_machine.c:341
(sofia/external/31354228 at 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 at 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 at 129.142.224.250) State EXECUTE
2010-01-14 22:47:14.540747 [DEBUG] mod_sofia.c:181
sofia/external/31354228 at 129.142.224.250 SOFIA EXECUTE
2010-01-14 22:47:14.540747 [DEBUG] switch_core_state_machine.c:159
sofia/external/31354228 at 129.142.224.250 Standard EXECUTE
EXECUTE sofia/external/31354228 at 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 at 129.142.224.250 Command Execute
set(hangup_after_bridge=true)
EXECUTE sofia/external/31354228 at 129.142.224.250 set(hangup_after_bridge=true)
2010-01-14 22:47:14.792781 [DEBUG] mod_dptools.c:818
sofia/external/31354228 at 129.142.224.250 SET
[hangup_after_bridge]=[true]
2010-01-14 22:47:14.792781 [DEBUG] switch_ivr.c:551
sofia/external/31354228 at 129.142.224.250 Command Execute
set(ignore_early_media=true)
EXECUTE sofia/external/31354228 at 129.142.224.250 set(ignore_early_media=true)
2010-01-14 22:47:14.792781 [DEBUG] mod_dptools.c:818
sofia/external/31354228 at 129.142.224.250 SET
[ignore_early_media]=[true]
2010-01-14 22:47:14.792781 [DEBUG] switch_ivr.c:551
sofia/external/31354228 at 129.142.224.250 Command Execute
set(call_timeout=20)
EXECUTE sofia/external/31354228 at 129.142.224.250 set(call_timeout=20)
2010-01-14 22:47:14.792781 [DEBUG] mod_dptools.c:818
sofia/external/31354228 at 129.142.224.250 SET [call_timeout]=[20]
2010-01-14 22:47:14.792781 [DEBUG] switch_ivr.c:551
sofia/external/31354228 at 129.142.224.250 Command Execute
set(originate_continue_on_timeout=true)
EXECUTE sofia/external/31354228 at 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 at 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 at 129.142.224.250 Command Execute
set(instant_ringback=true)
EXECUTE sofia/external/31354228 at 129.142.224.250 set(instant_ringback=true)
2010-01-14 22:47:14.792781 [DEBUG] mod_dptools.c:818
sofia/external/31354228 at 129.142.224.250 SET [instant_ringback]=[true]
2010-01-14 22:47:14.792781 [DEBUG] switch_ivr.c:551
sofia/external/31354228 at 129.142.224.250 Command Execute
set(ringback=%(2000,4000,440,480))
EXECUTE sofia/external/31354228 at 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 at 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 at 129.142.224.250 Command Execute
set(transfer_ringback=%(2000,4000,440,480))
EXECUTE sofia/external/31354228 at 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 at 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 at 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 at 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 at 129.142.224.250 Command Execute
bind_meta_app(7 b ai transfer::ff-transfer- XML public)
EXECUTE sofia/external/31354228 at 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 at 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 at 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 at 129.142.224.250 Command Execute pre_answer()
EXECUTE sofia/external/31354228 at 129.142.224.250 pre_answer()
2010-01-14 22:47:14.792781 [DEBUG] mod_dptools.c:736
sofia/external/31354228 at 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 at 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 at 129.142.224.250!
2010-01-14 22:47:14.807902 [DEBUG] switch_core_session.c:633 Send
signal sofia/external/31354228 at 129.142.224.250 [BREAK]
2010-01-14 22:47:14.827576 [DEBUG] sofia.c:3892 Channel
sofia/external/31354228 at 129.142.224.250 skipping state [early][183]
2010-01-14 22:47:14.827576 [DEBUG] switch_ivr.c:551
sofia/external/31354228 at 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 at 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 at 8000hz 1 channel 20ms
2010-01-14 22:47:14.876945 [DEBUG] switch_core_codec.c:112
sofia/external/31354228 at 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 at 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 at 129.142.224.250 [BREAK]

-- 
Harry Vangberg  <harry at vangberg.name>  http://harry.vangberg.name

More information about the FreeSWITCH-users mailing list