early media - no ringback - FreeSWITCH-users

26 Oct 2015

      Hello,

I have encountered strange problem - there is no audible ringback on DID routing. 

Dialplan is simple, on DID call gets transferred to local extension. Local extension is pretty much vanilla.
Log shows that both 183/180 is being fired and ringback activated but no sound coming. Ringing is going ok though, as well as connection afterwords. 
Is that incoming provider's problem or freeswitch?

Regards,
Paul Kazakov

Log:
Dialplan: sofia/external/mobile@provider Action transfer(20 XML default)
2015-10-26 01:39:27.463856 [DEBUG] switch_core_state_machine.c:216 (sofia/external/mobile@provider) State Change CS_ROUTING -> CS_EXECUTE
2015-10-26 01:39:27.463856 [DEBUG] switch_core_session.c:1397 Send signal sofia/external/mobile@provider [BREAK]
2015-10-26 01:39:27.463856 [DEBUG] switch_core_state_machine.c:528 (sofia/external/mobile@provider) State ROUTING going to sleep
2015-10-26 01:39:27.463856 [DEBUG] switch_core_state_machine.c:472 (sofia/external/mobile@provider) Running State Change CS_EXECUTE
2015-10-26 01:39:27.463856 [DEBUG] switch_core_state_machine.c:535 (sofia/external/mobile@provider) State EXECUTE
2015-10-26 01:39:27.463856 [DEBUG] mod_sofia.c:178 sofia/external/mobile@provider SOFIA EXECUTE
2015-10-26 01:39:27.463856 [DEBUG] switch_core_state_machine.c:258 sofia/external/mobile@provider Standard EXECUTE
EXECUTE sofia/external/mobile@provider set(outside_call=true)
2015-10-26 01:39:27.463856 [DEBUG] mod_dptools.c:1477 sofia/external/mobile@provider SET [outside_call]=[true]
EXECUTE sofia/external/mobile@provider export(RFC2822_DATE=Mon, 26 Oct 2015 01:39:27 +0100)
2015-10-26 01:39:27.483860 [DEBUG] switch_channel.c:1267 EXPORT (export_vars) [RFC2822_DATE]=[Mon, 26 Oct 2015 01:39:27 +0100]
EXECUTE sofia/external/mobile@provider set(domain_name=192.168.1.5)
2015-10-26 01:39:27.483860 [DEBUG] mod_dptools.c:1477 sofia/external/mobile@provider SET [domain_name]=[192.168.1.5]
EXECUTE sofia/external/mobile@provider transfer(20 XML default)
2015-10-26 01:39:27.483860 [DEBUG] switch_ivr.c:1856 (sofia/external/mobile@provider) State Change CS_EXECUTE -> CS_ROUTING
2015-10-26 01:39:27.483860 [DEBUG] switch_core_session.c:1397 Send signal sofia/external/mobile@provider [BREAK]
2015-10-26 01:39:27.483860 [DEBUG] switch_core_session.c:913 Send signal sofia/external/mobile@provider [BREAK]
2015-10-26 01:39:27.483860 [NOTICE] switch_ivr.c:1863 Transfer sofia/external/mobile@provider to XML[20@default]
2015-10-26 01:39:27.483860 [DEBUG] switch_core_state_machine.c:535 (sofia/external/mobile@provider) State EXECUTE going to sleep
2015-10-26 01:39:27.483860 [DEBUG] switch_core_state_machine.c:472 (sofia/external/mobile@provider) Running State Change CS_ROUTING
2015-10-26 01:39:27.483860 [DEBUG] switch_core_state_machine.c:528 (sofia/external/mobile@provider) State ROUTING
2015-10-26 01:39:27.483860 [DEBUG] mod_sofia.c:123 sofia/external/mobile@provider SOFIA ROUTING
2015-10-26 01:39:27.483860 [DEBUG] switch_core_state_machine.c:166 sofia/external/mobile@provider Standard ROUTING
2015-10-26 01:39:27.483860 [INFO] mod_dialplan_xml.c:635 Processing mobile <mobile>->20 in context default
Dialplan: sofia/external/mobile@provider parsing [default->unloop] continue=false
Dialplan: sofia/external/mobile@provider Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false
Dialplan: sofia/external/mobile@provider Regex (PASS) [global] ${endpoint_disposition}(DELAYED NEGOTIATION) =~ /^(DELAYED NEGOTIATION)/ break=on-false
Dialplan: sofia/external/mobile@provider Absolute Condition [global]
Dialplan: sofia/external/mobile@provider Action hash(insert/${domain_name}-spymap/${caller_id_number}/${uuid})
Dialplan: sofia/external/mobile@provider Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number})
Dialplan: sofia/external/mobile@provider Action hash(insert/${domain_name}-last_dial/global/${uuid})
Dialplan: sofia/external/mobile@provider Action export(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
Dialplan: sofia/external/mobile@provider parsing [default->Local_Extension] continue=false
Dialplan: sofia/external/mobile@provider Regex (PASS) [Local_Extension] destination_number(20) =~ /^([2-5][0-9])$/ break=on-false
Dialplan: sofia/external/mobile@provider Action export(dialed_extension=20)
Dialplan: sofia/external/mobile@provider Action bind_meta_app(1 b s execute_extension::dx XML features)
Dialplan: sofia/external/mobile@provider Action bind_meta_app(2 b s record_session::/usr/local/freeswitch/recordings/${caller_id_number}.${strftime(%Y-%m-%d-%H-%M-%S)}.wav)
Dialplan: sofia/external/mobile@provider Action bind_meta_app(3 b s execute_extension::cf XML features)
Dialplan: sofia/external/mobile@provider Action bind_meta_app(4 b s execute_extension::att_xfer XML features)
Dialplan: sofia/external/mobile@provider Action set(ringback=%(1000,4000,425))
Dialplan: sofia/external/mobile@provider Action set(transfer_ringback=local_stream://moh)
Dialplan: sofia/external/mobile@provider Action set(call_timeout=30)
Dialplan: sofia/external/mobile@provider Action set(hangup_after_bridge=true)
Dialplan: sofia/external/mobile@provider Action set(continue_on_fail=true)
Dialplan: sofia/external/mobile@provider Action hash(insert/${domain_name}-call_return/${dialed_extension}/${caller_id_number})
Dialplan: sofia/external/mobile@provider Action hash(insert/${domain_name}-last_dial_ext/${dialed_extension}/${uuid})
Dialplan: sofia/external/mobile@provider Action set(called_party_callgroup=${user_data(${dialed_extension}@${domain_name} var callgroup)})
Dialplan: sofia/external/mobile@provider Action hash(insert/${domain_name}-last_dial_ext/${called_party_callgroup}/${uuid})
Dialplan: sofia/external/mobile@provider Action hash(insert/${domain_name}-last_dial_ext/global/${uuid})
Dialplan: sofia/external/mobile@provider Action hash(insert/${domain_name}-last_dial/${called_party_callgroup}/${uuid})
Dialplan: sofia/external/mobile@provider Action bridge(user/${dialed_extension}@${domain_name})
Dialplan: sofia/external/mobile@provider Action answer()
Dialplan: sofia/external/mobile@provider Action sleep(1000)
Dialplan: sofia/external/mobile@provider Action bridge(loopback/app=voicemail:default ${domain_name} ${dialed_extension})
2015-10-26 01:39:27.483860 [DEBUG] switch_core_state_machine.c:216 (sofia/external/mobile@provider) State Change CS_ROUTING -> CS_EXECUTE
2015-10-26 01:39:27.483860 [DEBUG] switch_core_session.c:1397 Send signal sofia/external/mobile@provider [BREAK]
2015-10-26 01:39:27.483860 [DEBUG] switch_core_state_machine.c:528 (sofia/external/mobile@provider) State ROUTING going to sleep
2015-10-26 01:39:27.483860 [DEBUG] switch_core_state_machine.c:472 (sofia/external/mobile@provider) Running State Change CS_EXECUTE
2015-10-26 01:39:27.483860 [DEBUG] switch_core_state_machine.c:535 (sofia/external/mobile@provider) State EXECUTE
2015-10-26 01:39:27.483860 [DEBUG] mod_sofia.c:178 sofia/external/mobile@provider SOFIA EXECUTE
2015-10-26 01:39:27.483860 [DEBUG] switch_core_state_machine.c:258 sofia/external/mobile@provider Standard EXECUTE
EXECUTE sofia/external/mobile@provider hash(insert/192.168.1.5-spymap/mobile/0335befe-7b7a-11e5-a603-cb96e1b49eeb)
EXECUTE sofia/external/mobile@provider hash(insert/192.168.1.5-last_dial/mobile/20)
EXECUTE sofia/external/mobile@provider hash(insert/192.168.1.5-last_dial/global/0335befe-7b7a-11e5-a603-cb96e1b49eeb)
EXECUTE sofia/external/mobile@provider export(RFC2822_DATE=Mon, 26 Oct 2015 01:39:27 +0100)
2015-10-26 01:39:27.483860 [DEBUG] switch_channel.c:1267 EXPORT (export_vars) [RFC2822_DATE]=[Mon, 26 Oct 2015 01:39:27 +0100]
EXECUTE sofia/external/mobile@provider export(dialed_extension=20)
2015-10-26 01:39:27.503879 [DEBUG] switch_channel.c:1267 EXPORT (export_vars) [dialed_extension]=[20]
EXECUTE sofia/external/mobile@provider bind_meta_app(1 b s execute_extension::dx XML features)
2015-10-26 01:39:27.503879 [INFO] switch_ivr_async.c:3932 Bound B-Leg: *1 execute_extension::dx XML features
EXECUTE sofia/external/mobile@provider bind_meta_app(2 b s record_session::/usr/local/freeswitch/recordings/mobile.2015-10-26-01-39-27.wav)
2015-10-26 01:39:27.503879 [INFO] switch_ivr_async.c:3932 Bound B-Leg: *2 record_session::/usr/local/freeswitch/recordings/mobile.2015-10-26-01-39-27.wav
EXECUTE sofia/external/mobile@provider bind_meta_app(3 b s execute_extension::cf XML features)
2015-10-26 01:39:27.503879 [INFO] switch_ivr_async.c:3932 Bound B-Leg: *3 execute_extension::cf XML features
EXECUTE sofia/external/mobile@provider bind_meta_app(4 b s execute_extension::att_xfer XML features)
2015-10-26 01:39:27.503879 [INFO] switch_ivr_async.c:3932 Bound B-Leg: *4 execute_extension::att_xfer XML features
EXECUTE sofia/external/mobile@provider set(ringback=%(1000,4000,425))
2015-10-26 01:39:27.503879 [DEBUG] mod_dptools.c:1477 sofia/external/mobile@provider SET [ringback]=[%(1000,4000,425)]
EXECUTE sofia/external/mobile@provider set(instant_ringback=true)
2015-10-26 01:39:27.503879 [DEBUG] mod_dptools.c:1477 sofia/external/mobile@provider SET [instant_ringback]=[true]
EXECUTE sofia/external/mobile@provider set(transfer_ringback=local_stream://moh)
2015-10-26 01:39:27.503879 [DEBUG] mod_dptools.c:1477 sofia/external/mobile@provider SET [transfer_ringback]=[local_stream://moh]
EXECUTE sofia/external/mobile@provider set(call_timeout=30)
2015-10-26 01:39:27.503879 [DEBUG] mod_dptools.c:1477 sofia/external/mobile@provider SET [call_timeout]=[30]
EXECUTE sofia/external/mobile@provider set(hangup_after_bridge=true)
2015-10-26 01:39:27.503879 [DEBUG] mod_dptools.c:1477 sofia/external/mobile@provider SET [hangup_after_bridge]=[true]
EXECUTE sofia/external/mobile@provider set(continue_on_fail=true)
2015-10-26 01:39:27.523862 [DEBUG] mod_dptools.c:1477 sofia/external/mobile@provider SET [continue_on_fail]=[true]
EXECUTE sofia/external/mobile@provider hash(insert/192.168.1.5-call_return/20/mobile)
EXECUTE sofia/external/mobile@provider hash(insert/192.168.1.5-last_dial_ext/20/0335befe-7b7a-11e5-a603-cb96e1b49eeb)
EXECUTE sofia/external/mobile@provider set(called_party_callgroup=bakery)
2015-10-26 01:39:27.523862 [DEBUG] mod_dptools.c:1477 sofia/external/mobile@provider SET [called_party_callgroup]=[bakery]
EXECUTE sofia/external/mobile@provider hash(insert/192.168.1.5-last_dial_ext/bakery/0335befe-7b7a-11e5-a603-cb96e1b49eeb)
EXECUTE sofia/external/mobile@provider hash(insert/192.168.1.5-last_dial_ext/global/0335befe-7b7a-11e5-a603-cb96e1b49eeb)
EXECUTE sofia/external/mobile@provider hash(insert/192.168.1.5-last_dial/bakery/0335befe-7b7a-11e5-a603-cb96e1b49eeb)
EXECUTE sofia/external/mobile@provider bridge(user/20@192.168.1.5)
2015-10-26 01:39:27.523862 [DEBUG] switch_channel.c:1221 sofia/external/mobile@provider EXPORTING[export_vars] [RFC2822_DATE]=[Mon, 26 Oct 2015 01:39:27 +0100] to event
2015-10-26 01:39:27.523862 [DEBUG] switch_channel.c:1221 sofia/external/mobile@provider EXPORTING[export_vars] [RFC2822_DATE]=[Mon, 26 Oct 2015 01:39:27 +0100] to event
2015-10-26 01:39:27.523862 [DEBUG] switch_channel.c:1221 sofia/external/mobile@provider EXPORTING[export_vars] [dialed_extension]=[20] to event
2015-10-26 01:39:27.523862 [DEBUG] switch_ivr_originate.c:2101 Parsing global variables
2015-10-26 01:39:27.543880 [DEBUG] switch_channel.c:1221 sofia/external/mobile@provider EXPORTING[export_vars] [RFC2822_DATE]=[Mon, 26 Oct 2015 01:39:27 +0100] to event
2015-10-26 01:39:27.543880 [DEBUG] switch_channel.c:1221 sofia/external/mobile@provider EXPORTING[export_vars] [RFC2822_DATE]=[Mon, 26 Oct 2015 01:39:27 +0100] to event
2015-10-26 01:39:27.543880 [DEBUG] switch_channel.c:1221 sofia/external/mobile@provider EXPORTING[export_vars] [dialed_extension]=[20] to event
2015-10-26 01:39:27.543880 [DEBUG] switch_ivr_originate.c:2101 Parsing global variables
2015-10-26 01:39:27.543880 [DEBUG] switch_event.c:1698 Parsing variable [sip_invite_domain]=[192.168.1.5]
2015-10-26 01:39:27.543880 [DEBUG] switch_event.c:1698 Parsing variable [presence_id]=[20@192.168.1.5]
2015-10-26 01:39:27.543880 [NOTICE] switch_channel.c:1075 New Channel sofia/internal/20@192.168.1.13:5060 [034101c4-7b7a-11e5-a624-cb96e1b49eeb]
2015-10-26 01:39:27.543880 [DEBUG] mod_sofia.c:4700 (sofia/internal/20@192.168.1.13:5060) State Change CS_NEW -> CS_INIT
2015-10-26 01:39:27.543880 [DEBUG] switch_core_session.c:1397 Send signal sofia/internal/20@192.168.1.13:5060 [BREAK]
2015-10-26 01:39:27.543880 [DEBUG] switch_core_state_machine.c:472 (sofia/internal/20@192.168.1.13:5060) Running State Change CS_INIT
2015-10-26 01:39:27.543880 [DEBUG] switch_core_state_machine.c:512 (sofia/internal/20@192.168.1.13:5060) State INIT
2015-10-26 01:39:27.543880 [DEBUG] mod_sofia.c:87 sofia/internal/20@192.168.1.13:5060 SOFIA INIT
2015-10-26 01:39:27.543880 [DEBUG] sofia_glue.c:1241 sofia/internal/20@192.168.1.13:5060 sending invite version: 1.4.23 git 1665168 2015-10-01 18:31:59Z 32bit
Local SDP:
v=0
o=FreeSWITCH 1445799433 1445799434 IN IP4 192.168.1.5
s=FreeSWITCH
c=IN IP4 192.168.1.5
t=0 0
m=audio 20534 RTP/AVP 8 101 13
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv

2015-10-26 01:39:27.543880 [DEBUG] switch_core_state_machine.c:40 sofia/internal/20@192.168.1.13:5060 Standard INIT
2015-10-26 01:39:27.543880 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/20@192.168.1.13:5060) State Change CS_INIT -> CS_ROUTING
2015-10-26 01:39:27.543880 [DEBUG] switch_core_session.c:1397 Send signal sofia/internal/20@192.168.1.13:5060 [BREAK]
2015-10-26 01:39:27.543880 [DEBUG] switch_core_state_machine.c:512 (sofia/internal/20@192.168.1.13:5060) State INIT going to sleep
2015-10-26 01:39:27.543880 [INFO] switch_ivr_originate.c:1193 Sending early media
2015-10-26 01:39:27.543880 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[opus:116:48000:20:0:1]
2015-10-26 01:39:27.543880 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2015-10-26 01:39:27.543880 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2015-10-26 01:39:27.543880 [DEBUG] switch_core_media.c:3734 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
2015-10-26 01:39:27.543880 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[GSM:3:8000:20:13200:1]
2015-10-26 01:39:27.543880 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [G729:18:8000:20:8000:1]/[opus:116:48000:20:0:1]
2015-10-26 01:39:27.543880 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [G729:18:8000:20:8000:1]/[G722:9:8000:20:64000:1]
2015-10-26 01:39:27.543880 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMA:8:8000:20:64000:1]
2015-10-26 01:39:27.543880 [DEBUG] switch_core_state_machine.c:472 (sofia/internal/20@192.168.1.13:5060) Running State Change CS_ROUTING
2015-10-26 01:39:27.543880 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [G729:18:8000:20:8000:1]/[GSM:3:8000:20:13200:1]
2015-10-26 01:39:27.543880 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[opus:116:48000:20:0:1]
2015-10-26 01:39:27.543880 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2015-10-26 01:39:27.543880 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2015-10-26 01:39:27.543880 [DEBUG] switch_core_media.c:3679 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[GSM:3:8000:20:13200:1]
2015-10-26 01:39:27.543880 [DEBUG] switch_core_media.c:3595 Set telephone-event payload to 101
2015-10-26 01:39:27.543880 [DEBUG] switch_core_media.c:2506 Set Codec sofia/external/mobile@provider PCMA/8000 20 ms 160 samples 64000 bits 1 channels
2015-10-26 01:39:27.543880 [DEBUG] switch_core_codec.c:111 sofia/external/mobile@provider Original read codec set to PCMA:8

send 1183 bytes to udp/[192.168.1.13]:5060 at 01:39:27.556739:
   ------------------------------------------------------------------------
   INVITE sip:20@192.168.1.13:5060 SIP/2.0
   Via: SIP/2.0/UDP 192.168.1.5;rport;branch=z9hG4bK01mvc388g3F4e
   Max-Forwards: 68
   From: "mobile" <sip:mobile@192.168.1.5>;tag=mX9UByt7H37DQ
   To: <sip:20@192.168.1.13:5060>
   Call-ID: daa0593a-f61c-1233-8791-b827eb32337b
   CSeq: 82573919 INVITE
   Contact: <sip:mod_sofia@192.168.1.5:5060>
   User-Agent: FreeSWITCH-mod_sofia/1.4.23+git~20151001T183159Z~1665168d37~32bit
   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
   Supported: timer, path, replaces
   Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
   Content-Type: application/sdp
   Content-Disposition: session
   Content-Length: 221
   X-Ecan: On
   X-FS-Support: update_display,send_info
   Remote-Party-ID: "mobile" <sip:mobile@192.168.1.5>;party=calling;screen=yes;privacy=off

   v=0
   o=FreeSWITCH 1445799433 1445799434 IN IP4 192.168.1.5
   s=FreeSWITCH
   c=IN IP4 192.168.1.5
   t=0 0
   m=audio 20534 RTP/AVP 8 101 13
   a=rtpmap:8 PCMA/8000
   a=rtpmap:101 telephone-event/8000
   a=fmtp:101 0-16
   a=ptime:20
   ------------------------------------------------------------------------
2015-10-26 01:39:27.543880 [DEBUG] switch_core_state_machine.c:528 (sofia/internal/20@192.168.1.13:5060) State ROUTING
2015-10-26 01:39:27.543880 [DEBUG] mod_sofia.c:123 sofia/internal/20@192.168.1.13:5060 SOFIA ROUTING
2015-10-26 01:39:27.543880 [DEBUG] switch_ivr_originate.c:67 (sofia/internal/20@192.168.1.13:5060) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2015-10-26 01:39:27.543880 [DEBUG] switch_core_session.c:1397 Send signal sofia/internal/20@192.168.1.13:5060 [BREAK]
2015-10-26 01:39:27.543880 [DEBUG] switch_core_state_machine.c:528 (sofia/internal/20@192.168.1.13:5060) State ROUTING going to sleep
2015-10-26 01:39:27.543880 [DEBUG] switch_core_session.c:1062 Send signal sofia/internal/20@192.168.1.13:5060 [BREAK]
2015-10-26 01:39:27.543880 [DEBUG] switch_core_state_machine.c:472 (sofia/internal/20@192.168.1.13:5060) Running State Change CS_CONSUME_MEDIA
2015-10-26 01:39:27.543880 [DEBUG] switch_core_media.c:3942 Set 2833 dtmf send/recv payload to 101
2015-10-26 01:39:27.543880 [INFO] switch_nat.c:588 NAT port mapping disabled
2015-10-26 01:39:27.543880 [DEBUG] switch_core_media.c:5178 AUDIO RTP [sofia/external/mobile@provider] 192.168.1.5 port 29360 -> xx.xx.xx.xx port 59648 codec: 8 ms: 20
2015-10-26 01:39:27.543880 [DEBUG] sofia.c:6658 Channel sofia/internal/20@192.168.1.13:5060 entering state [calling][0]
2015-10-26 01:39:27.543880 [DEBUG] switch_core_state_machine.c:547 (sofia/internal/20@192.168.1.13:5060) State CONSUME_MEDIA
2015-10-26 01:39:27.543880 [DEBUG] switch_core_state_machine.c:547 (sofia/internal/20@192.168.1.13:5060) State CONSUME_MEDIA going to sleep
2015-10-26 01:39:27.543880 [DEBUG] switch_rtp.c:3579 Starting timer [soft] 160 bytes per 20ms
2015-10-26 01:39:27.543880 [DEBUG] switch_core_media.c:5476 Set 2833 dtmf send payload to 101
2015-10-26 01:39:27.543880 [DEBUG] switch_core_media.c:5482 Set 2833 dtmf receive payload to 101
2015-10-26 01:39:27.543880 [DEBUG] switch_core_media.c:5504 sofia/external/mobile@provider Set rtp dtmf delay to 40
2015-10-26 01:39:27.543880 [NOTICE] sofia_media.c:92 Pre-Answer sofia/external/mobile@provider!
2015-10-26 01:39:27.563871 [DEBUG] switch_channel.c:3419 (sofia/external/mobile@provider) Callstate Change RINGING -> EARLY
2015-10-26 01:39:27.563871 [DEBUG] mod_sofia.c:2264 Ring SDP:
v=0
o=FreeSWITCH 1445790607 1445790608 IN IP4 xx.xx.xx.xx
s=FreeSWITCH
c=IN IP4 ext_ip_addr
t=0 0
m=audio 29360 RTP/AVP 8 101
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv

2015-10-26 01:39:27.563871 [DEBUG] switch_core_session.c:913 Send signal sofia/external/mobile@provider [BREAK]
2015-10-26 01:39:27.563871 [DEBUG] switch_ivr_originate.c:1250 Raw Codec Activation Success L16@8000hz 1 channel 20ms
2015-10-26 01:39:27.563871 [DEBUG] switch_core_codec.c:221 sofia/external/mobile@provider Push codec L16:100
2015-10-26 01:39:27.563871 [DEBUG] switch_ivr_originate.c:1318 Play Ringback Tone [%(1000,4000,425)]

send 1067 bytes to udp/[xx.xx.xx.xx]:5060 at 01:39:27.575578:
   ------------------------------------------------------------------------
   SIP/2.0 183 Session Progress
   Via: SIP/2.0/UDP 62.80.209.30:5060;branch=z9hG4bK-524287-1---f0231a59e0656a3a;rport=5060
   From: "mobile"<sip:mobile@provider;user=phone>;tag=b2a8ce1b
   To: "pstn_did" <sip:pstn_did@siptrunk;user=phone>;tag=gmUjH321ep8jF
   Call-ID: pSnT7Y8CK7u_vpaaKgC0bw..
   CSeq: 1 INVITE
   Contact: <sip:pstn_did@ext_ip_addr:5080;transport=udp>
   User-Agent: FreeSWITCH-mod_sofia/1.4.23+git~20151001T183159Z~1665168d37~32bit
   Accept: application/sdp
   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
   Supported: timer, path, replaces
   Allow-Events: talk, hold, conference, refer
   Content-Type: application/sdp
   Content-Disposition: session
   Content-Length: 224
   Remote-Party-ID: "pstn_did" <sip:pstn_did@siptrunk>;party=calling;privacy=off;screen=no

   v=0
   o=FreeSWITCH 1445790607 1445790608 IN IP4 ext_ip_addr
   s=FreeSWITCH
   c=IN IP4 ext_ip_addr
   t=0 0
   m=audio 29360 RTP/AVP 8 101
   a=rtpmap:8 PCMA/8000
   a=rtpmap:101 telephone-event/8000
   a=fmtp:101 0-16
   a=ptime:20
   ------------------------------------------------------------------------
2015-10-26 01:39:27.563871 [DEBUG] switch_core_session.c:1062 Send signal sofia/external/mobile@provider [BREAK]
2015-10-26 01:39:27.583855 [DEBUG] sofia.c:6658 Channel sofia/external/mobile@provider entering state [early][183]
recv 370 bytes from udp/[192.168.1.13]:5060 at 01:39:27.628443:
   ------------------------------------------------------------------------
   SIP/2.0 100 Trying
   Via: SIP/2.0/UDP 192.168.1.5;rport=5060;branch=z9hG4bK01mvc388g3F4e
   From: "mobile" <sip:mobile@192.168.1.5>;tag=mX9UByt7H37DQ
   To: <sip:20@192.168.1.13:5060>;tag=2174874080
   Call-ID: daa0593a-f61c-1233-8791-b827eb32337b
   CSeq: 82573919 INVITE
   Contact: <sip:20@192.168.1.13:5060>
   User-Agent: C530 IP/42.207.00.000.000
   Content-Length: 0

   ------------------------------------------------------------------------
recv 421 bytes from udp/[192.168.1.13]:5060 at 01:39:28.125276:
   ------------------------------------------------------------------------
   SIP/2.0 180 Ringing
   Via: SIP/2.0/UDP 192.168.1.5;rport=5060;branch=z9hG4bK01mvc388g3F4e
   From: "mobile" <sip:mobile@192.168.1.5>;tag=mX9UByt7H37DQ
   To: <sip:20@192.168.1.13:5060>;tag=2174874080
   Call-ID: daa0593a-f61c-1233-8791-b827eb32337b
   CSeq: 82573919 INVITE
   Contact: <sip:20@192.168.1.13:5060>
   Allow-Events: message-summary, refer, ua-profile
   User-Agent: C530 IP/42.207.00.000.000
   Content-Length: 0

   ------------------------------------------------------------------------
2015-10-26 01:39:28.123847 [DEBUG] switch_core_session.c:1062 Send signal sofia/internal/20@192.168.1.13:5060 [BREAK]
2015-10-26 01:39:28.123847 [DEBUG] switch_core_session.c:1062 Send signal sofia/internal/20@192.168.1.13:5060 [BREAK]
2015-10-26 01:39:28.123847 [DEBUG] sofia.c:6658 Channel sofia/internal/20@192.168.1.13:5060 entering state [proceeding][180]
2015-10-26 01:39:28.123847 [NOTICE] sofia.c:6760 Ring-Ready sofia/internal/20@192.168.1.13:5060!
2015-10-26 01:39:28.123847 [DEBUG] switch_channel.c:3297 (sofia/internal/20@192.168.1.13:5060) Callstate Change DOWN -> RINGING

early media - no ringback

Dada P

Brian West

tags

participants (2)