[Freeswitch-users] early media - no ringback

Dada P dada-p at yandex.com
Mon Oct 26 04:18:50 MSK 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 at provider Action transfer(20 XML default)
2015-10-26 01:39:27.463856 [DEBUG] switch_core_state_machine.c:216 (sofia/external/mobile at 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 at provider [BREAK]
2015-10-26 01:39:27.463856 [DEBUG] switch_core_state_machine.c:528 (sofia/external/mobile at provider) State ROUTING going to sleep
2015-10-26 01:39:27.463856 [DEBUG] switch_core_state_machine.c:472 (sofia/external/mobile at provider) Running State Change CS_EXECUTE
2015-10-26 01:39:27.463856 [DEBUG] switch_core_state_machine.c:535 (sofia/external/mobile at provider) State EXECUTE
2015-10-26 01:39:27.463856 [DEBUG] mod_sofia.c:178 sofia/external/mobile at provider SOFIA EXECUTE
2015-10-26 01:39:27.463856 [DEBUG] switch_core_state_machine.c:258 sofia/external/mobile at provider Standard EXECUTE
EXECUTE sofia/external/mobile at provider set(outside_call=true)
2015-10-26 01:39:27.463856 [DEBUG] mod_dptools.c:1477 sofia/external/mobile at provider SET [outside_call]=[true]
EXECUTE sofia/external/mobile at 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 at provider set(domain_name=192.168.1.5)
2015-10-26 01:39:27.483860 [DEBUG] mod_dptools.c:1477 sofia/external/mobile at provider SET [domain_name]=[192.168.1.5]
EXECUTE sofia/external/mobile at provider transfer(20 XML default)
2015-10-26 01:39:27.483860 [DEBUG] switch_ivr.c:1856 (sofia/external/mobile at 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 at provider [BREAK]
2015-10-26 01:39:27.483860 [DEBUG] switch_core_session.c:913 Send signal sofia/external/mobile at provider [BREAK]
2015-10-26 01:39:27.483860 [NOTICE] switch_ivr.c:1863 Transfer sofia/external/mobile at provider to XML[20 at default]
2015-10-26 01:39:27.483860 [DEBUG] switch_core_state_machine.c:535 (sofia/external/mobile at provider) State EXECUTE going to sleep
2015-10-26 01:39:27.483860 [DEBUG] switch_core_state_machine.c:472 (sofia/external/mobile at provider) Running State Change CS_ROUTING
2015-10-26 01:39:27.483860 [DEBUG] switch_core_state_machine.c:528 (sofia/external/mobile at provider) State ROUTING
2015-10-26 01:39:27.483860 [DEBUG] mod_sofia.c:123 sofia/external/mobile at provider SOFIA ROUTING
2015-10-26 01:39:27.483860 [DEBUG] switch_core_state_machine.c:166 sofia/external/mobile at 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 at provider parsing [default->unloop] continue=false
Dialplan: sofia/external/mobile at provider Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false
Dialplan: sofia/external/mobile at provider Regex (PASS) [global] ${endpoint_disposition}(DELAYED NEGOTIATION) =~ /^(DELAYED NEGOTIATION)/ break=on-false
Dialplan: sofia/external/mobile at provider Absolute Condition [global]
Dialplan: sofia/external/mobile at provider Action hash(insert/${domain_name}-spymap/${caller_id_number}/${uuid})
Dialplan: sofia/external/mobile at provider Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number})
Dialplan: sofia/external/mobile at provider Action hash(insert/${domain_name}-last_dial/global/${uuid})
Dialplan: sofia/external/mobile at provider Action export(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
Dialplan: sofia/external/mobile at provider parsing [default->Local_Extension] continue=false
Dialplan: sofia/external/mobile at provider Regex (PASS) [Local_Extension] destination_number(20) =~ /^([2-5][0-9])$/ break=on-false
Dialplan: sofia/external/mobile at provider Action export(dialed_extension=20)
Dialplan: sofia/external/mobile at provider Action bind_meta_app(1 b s execute_extension::dx XML features)
Dialplan: sofia/external/mobile at 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 at provider Action bind_meta_app(3 b s execute_extension::cf XML features)
Dialplan: sofia/external/mobile at provider Action bind_meta_app(4 b s execute_extension::att_xfer XML features)
Dialplan: sofia/external/mobile at provider Action set(ringback=%(1000,4000,425))
Dialplan: sofia/external/mobile at provider Action set(transfer_ringback=local_stream://moh)
Dialplan: sofia/external/mobile at provider Action set(call_timeout=30)
Dialplan: sofia/external/mobile at provider Action set(hangup_after_bridge=true)
Dialplan: sofia/external/mobile at provider Action set(continue_on_fail=true)
Dialplan: sofia/external/mobile at provider Action hash(insert/${domain_name}-call_return/${dialed_extension}/${caller_id_number})
Dialplan: sofia/external/mobile at provider Action hash(insert/${domain_name}-last_dial_ext/${dialed_extension}/${uuid})
Dialplan: sofia/external/mobile at provider Action set(called_party_callgroup=${user_data(${dialed_extension}@${domain_name} var callgroup)})
Dialplan: sofia/external/mobile at provider Action hash(insert/${domain_name}-last_dial_ext/${called_party_callgroup}/${uuid})
Dialplan: sofia/external/mobile at provider Action hash(insert/${domain_name}-last_dial_ext/global/${uuid})
Dialplan: sofia/external/mobile at provider Action hash(insert/${domain_name}-last_dial/${called_party_callgroup}/${uuid})
Dialplan: sofia/external/mobile at provider Action bridge(user/${dialed_extension}@${domain_name})
Dialplan: sofia/external/mobile at provider Action answer()
Dialplan: sofia/external/mobile at provider Action sleep(1000)
Dialplan: sofia/external/mobile at 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 at 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 at provider [BREAK]
2015-10-26 01:39:27.483860 [DEBUG] switch_core_state_machine.c:528 (sofia/external/mobile at provider) State ROUTING going to sleep
2015-10-26 01:39:27.483860 [DEBUG] switch_core_state_machine.c:472 (sofia/external/mobile at provider) Running State Change CS_EXECUTE
2015-10-26 01:39:27.483860 [DEBUG] switch_core_state_machine.c:535 (sofia/external/mobile at provider) State EXECUTE
2015-10-26 01:39:27.483860 [DEBUG] mod_sofia.c:178 sofia/external/mobile at provider SOFIA EXECUTE
2015-10-26 01:39:27.483860 [DEBUG] switch_core_state_machine.c:258 sofia/external/mobile at provider Standard EXECUTE
EXECUTE sofia/external/mobile at provider hash(insert/192.168.1.5-spymap/mobile/0335befe-7b7a-11e5-a603-cb96e1b49eeb)
EXECUTE sofia/external/mobile at provider hash(insert/192.168.1.5-last_dial/mobile/20)
EXECUTE sofia/external/mobile at provider hash(insert/192.168.1.5-last_dial/global/0335befe-7b7a-11e5-a603-cb96e1b49eeb)
EXECUTE sofia/external/mobile at 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 at 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 at 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 at 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 at 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 at 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 at provider set(ringback=%(1000,4000,425))
2015-10-26 01:39:27.503879 [DEBUG] mod_dptools.c:1477 sofia/external/mobile at provider SET [ringback]=[%(1000,4000,425)]
EXECUTE sofia/external/mobile at provider set(instant_ringback=true)
2015-10-26 01:39:27.503879 [DEBUG] mod_dptools.c:1477 sofia/external/mobile at provider SET [instant_ringback]=[true]
EXECUTE sofia/external/mobile at provider set(transfer_ringback=local_stream://moh)
2015-10-26 01:39:27.503879 [DEBUG] mod_dptools.c:1477 sofia/external/mobile at provider SET [transfer_ringback]=[local_stream://moh]
EXECUTE sofia/external/mobile at provider set(call_timeout=30)
2015-10-26 01:39:27.503879 [DEBUG] mod_dptools.c:1477 sofia/external/mobile at provider SET [call_timeout]=[30]
EXECUTE sofia/external/mobile at provider set(hangup_after_bridge=true)
2015-10-26 01:39:27.503879 [DEBUG] mod_dptools.c:1477 sofia/external/mobile at provider SET [hangup_after_bridge]=[true]
EXECUTE sofia/external/mobile at provider set(continue_on_fail=true)
2015-10-26 01:39:27.523862 [DEBUG] mod_dptools.c:1477 sofia/external/mobile at provider SET [continue_on_fail]=[true]
EXECUTE sofia/external/mobile at provider hash(insert/192.168.1.5-call_return/20/mobile)
EXECUTE sofia/external/mobile at provider hash(insert/192.168.1.5-last_dial_ext/20/0335befe-7b7a-11e5-a603-cb96e1b49eeb)
EXECUTE sofia/external/mobile at provider set(called_party_callgroup=bakery)
2015-10-26 01:39:27.523862 [DEBUG] mod_dptools.c:1477 sofia/external/mobile at provider SET [called_party_callgroup]=[bakery]
EXECUTE sofia/external/mobile at provider hash(insert/192.168.1.5-last_dial_ext/bakery/0335befe-7b7a-11e5-a603-cb96e1b49eeb)
EXECUTE sofia/external/mobile at provider hash(insert/192.168.1.5-last_dial_ext/global/0335befe-7b7a-11e5-a603-cb96e1b49eeb)
EXECUTE sofia/external/mobile at provider hash(insert/192.168.1.5-last_dial/bakery/0335befe-7b7a-11e5-a603-cb96e1b49eeb)
EXECUTE sofia/external/mobile at provider bridge(user/20 at 192.168.1.5)
2015-10-26 01:39:27.523862 [DEBUG] switch_channel.c:1221 sofia/external/mobile at 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 at 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 at 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 at 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 at 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 at 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 at 192.168.1.5]
2015-10-26 01:39:27.543880 [NOTICE] switch_channel.c:1075 New Channel sofia/internal/20 at 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 at 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 at 192.168.1.13:5060 [BREAK]
2015-10-26 01:39:27.543880 [DEBUG] switch_core_state_machine.c:472 (sofia/internal/20 at 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 at 192.168.1.13:5060) State INIT
2015-10-26 01:39:27.543880 [DEBUG] mod_sofia.c:87 sofia/internal/20 at 192.168.1.13:5060 SOFIA INIT
2015-10-26 01:39:27.543880 [DEBUG] sofia_glue.c:1241 sofia/internal/20 at 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 at 192.168.1.13:5060 Standard INIT
2015-10-26 01:39:27.543880 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/20 at 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 at 192.168.1.13:5060 [BREAK]
2015-10-26 01:39:27.543880 [DEBUG] switch_core_state_machine.c:512 (sofia/internal/20 at 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 at 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 at 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 at 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 at 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 at 192.168.1.5>;tag=mX9UByt7H37DQ
   To: <sip:20 at 192.168.1.13:5060>
   Call-ID: daa0593a-f61c-1233-8791-b827eb32337b
   CSeq: 82573919 INVITE
   Contact: <sip:mod_sofia at 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 at 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 at 192.168.1.13:5060) State ROUTING
2015-10-26 01:39:27.543880 [DEBUG] mod_sofia.c:123 sofia/internal/20 at 192.168.1.13:5060 SOFIA ROUTING
2015-10-26 01:39:27.543880 [DEBUG] switch_ivr_originate.c:67 (sofia/internal/20 at 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 at 192.168.1.13:5060 [BREAK]
2015-10-26 01:39:27.543880 [DEBUG] switch_core_state_machine.c:528 (sofia/internal/20 at 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 at 192.168.1.13:5060 [BREAK]
2015-10-26 01:39:27.543880 [DEBUG] switch_core_state_machine.c:472 (sofia/internal/20 at 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 at 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 at 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 at 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 at 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 at provider Set rtp dtmf delay to 40
2015-10-26 01:39:27.543880 [NOTICE] sofia_media.c:92 Pre-Answer sofia/external/mobile at provider!
2015-10-26 01:39:27.563871 [DEBUG] switch_channel.c:3419 (sofia/external/mobile at 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 at provider [BREAK]
2015-10-26 01:39:27.563871 [DEBUG] switch_ivr_originate.c:1250 Raw Codec Activation Success L16 at 8000hz 1 channel 20ms
2015-10-26 01:39:27.563871 [DEBUG] switch_core_codec.c:221 sofia/external/mobile at 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 at provider;user=phone>;tag=b2a8ce1b
   To: "pstn_did" <sip:pstn_did at siptrunk;user=phone>;tag=gmUjH321ep8jF
   Call-ID: pSnT7Y8CK7u_vpaaKgC0bw..
   CSeq: 1 INVITE
   Contact: <sip:pstn_did at 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 at 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 at provider [BREAK]
2015-10-26 01:39:27.583855 [DEBUG] sofia.c:6658 Channel sofia/external/mobile at 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 at 192.168.1.5>;tag=mX9UByt7H37DQ
   To: <sip:20 at 192.168.1.13:5060>;tag=2174874080
   Call-ID: daa0593a-f61c-1233-8791-b827eb32337b
   CSeq: 82573919 INVITE
   Contact: <sip:20 at 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 at 192.168.1.5>;tag=mX9UByt7H37DQ
   To: <sip:20 at 192.168.1.13:5060>;tag=2174874080
   Call-ID: daa0593a-f61c-1233-8791-b827eb32337b
   CSeq: 82573919 INVITE
   Contact: <sip:20 at 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 at 192.168.1.13:5060 [BREAK]
2015-10-26 01:39:28.123847 [DEBUG] switch_core_session.c:1062 Send signal sofia/internal/20 at 192.168.1.13:5060 [BREAK]
2015-10-26 01:39:28.123847 [DEBUG] sofia.c:6658 Channel sofia/internal/20 at 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 at 192.168.1.13:5060!
2015-10-26 01:39:28.123847 [DEBUG] switch_channel.c:3297 (sofia/internal/20 at 192.168.1.13:5060) Callstate Change DOWN -> RINGING

Join us at ClueCon 2016 Aug 8-12, 2016
More information about the FreeSWITCH-users mailing list