[Freeswitch-users] No ringback.

Harry Vangberg harry at vangberg.name
Thu Jan 14 15:44:08 PST 2010 

Oh, damn. I need answer, not pre_answer. Yay.

2010/1/15 Harry Vangberg <harry at vangberg.name>:
> 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
>



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

More information about the FreeSWITCH-users mailing list