SOLVED Inbound Calling

Bifur · Sep 16, 2020

Hello everyone, hope everyone is doing OK.

I am in the process of getting a test system running and I am running into issues with inbound calls. I am running the latest FusionPBX on Debian 10. My sip provider is Telnyx and I am using IP auth to the trunk. I have followed the documentation of FusionPBX (to the best of my ability!) and also a how to from Telnyx (https://telnyx.com/bring-your-own-carrier/telnyx-with-fusionpbx-setup-guide). THe server is on a Vultr cloud instnace with a public IP.

Here is the snippet of a test call:

Code:

freeswitch@FusionPBX>
recv 1185 bytes from udp/[192.76.120.10]:5060 at 00:33:56.531592:
------------------------------------------------------------------------
INVITE sip:176XXXX1441@45.76.XXX.XXX:5080 SIP/2.0
Record-Route: <sip:192.76.120.10;r2=on;lr;ftag=teB84pX9a57Hc>
Record-Route: <sip:10.255.0.1;r2=on;lr;ftag=teB84pX9a57Hc>
Via: SIP/2.0/UDP 192.76.120.10;branch=z9hG4bKe873.9197c487b1c4524ff0463a095a643b90.0
v:SIP/2.0/UDP 10.15.196.4:6000;received=10.15.196.4;rport=6000;branch=z9hG4bKS5tD3vB6S1H2D
Max-Forwards:67
f:"70XX749X7"<sip:70XX749X7@sip.telnyx.com>;tag=teB84pX9a57Hc
t:<sip:176XXXX1441@45.76.XXX.XXX:5080>
i:99bbb169-6c35-4bab-b540-a042870128d8
CSeq:25554426 INVITE
m:<sip:mod_sofia@10.15.196.4:6000>
Allow:INVITE,ACK,BYE,CANCEL,OPTIONS,MESSAGE,INFO,UPDATE,REFER,NOTIFY
k:timer,path,replaces
u:talk,hold,conference,refer
Privacy:none
c:application/sdp
Content-Disposition:session
l:356
P-Asserted-Identity:"70XX749X7"<sip:70XX749X7@sip.telnyx.com>

v=0
o=Telnyx 1600193310 1600193311 IN IP4 64.16.248.120
s=Telnyx
c=IN IP4 64.16.248.120
t=0 0
m=audio 23126 RTP/AVP 9 0 8 18 101
a=rtpmap:9 G722/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=sendrecv
a=rtcp:23127 IN IP4 64.16.248.120
a=ptime:20
2020-09-16 00:33:56.523123 [NOTICE] switch_channel.c:1118 New Channel sofia/external/70XX749X7@sip.telnyx.com [e4389e60-87e9-4dcb-9a6c-f5c92b27f47b]
2020-09-16 00:33:56.523123 [DEBUG] switch_core_state_machine.c:585 (sofia/external/70XX749X7@sip.telnyx.com) Running State Change CS_NEW (Cur 1 Tot 18)
2020-09-16 00:33:56.523123 [DEBUG] sofia.c:10280 sofia/external/70XX749X7@sip.telnyx.com receiving invite from 192.76.120.10:5060 version: 1.10.5 -release-17-25569c1631 64bit
2020-09-16 00:33:56.523123 [DEBUG] sofia.c:10374 verifying acl "domains" for ip/port 192.76.120.10:0.
2020-09-16 00:33:56.523123 [DEBUG] sofia.c:10403 IP 192.76.120.10 Approved by acl "domains[]". Access Granted.
2020-09-16 00:33:56.523123 [DEBUG] sofia.c:7326 Channel sofia/external/70XX749X7@sip.telnyx.com entering state [received][100]
2020-09-16 00:33:56.523123 [DEBUG] sofia.c:7336 Remote SDP:
v=0
o=Telnyx 1600193310 1600193311 IN IP4 64.16.248.120
s=Telnyx
c=IN IP4 64.16.248.120
t=0 0
m=audio 23126 RTP/AVP 9 0 8 18 101
a=rtpmap:9 G722/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=rtcp:23127 IN IP4 64.16.248.120
a=ptime:20

2020-09-16 00:33:56.523123 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [G722:9:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2020-09-16 00:33:56.523123 [DEBUG] switch_core_media.c:5649 Audio Codec Compare [G722:9:8000:20:64000:1] ++++ is saved as a match
2020-09-16 00:33:56.523123 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2020-09-16 00:33:56.523123 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2020-09-16 00:33:56.523123 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2020-09-16 00:33:56.523123 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2020-09-16 00:33:56.523123 [DEBUG] switch_core_media.c:5649 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
2020-09-16 00:33:56.523123 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2020-09-16 00:33:56.523123 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2020-09-16 00:33:56.523123 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2020-09-16 00:33:56.523123 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2020-09-16 00:33:56.523123 [DEBUG] switch_core_media.c:5649 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
2020-09-16 00:33:56.523123 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [G729:18:8000:20:8000:1]/[G722:9:8000:20:64000:1]
2020-09-16 00:33:56.523123 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMU:0:8000:20:64000:1]
2020-09-16 00:33:56.523123 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMA:8:8000:20:64000:1]
2020-09-16 00:33:56.523123 [DEBUG] switch_core_media.c:5510 Set telephone-event payload to 101@8000
2020-09-16 00:33:56.523123 [DEBUG] switch_core_media.c:3839 Set Codec sofia/external/70XX749X7@sip.telnyx.com G722/8000 20 ms 160 samples 64000 bits 1 channels
2020-09-16 00:33:56.523123 [DEBUG] switch_core_codec.c:111 sofia/external/70XX749X7@sip.telnyx.com Original read codec set to G722:9
2020-09-16 00:33:56.523123 [DEBUG] switch_core_media.c:5853 Set telephone-event payload to 101@8000
2020-09-16 00:33:56.523123 [DEBUG] switch_core_media.c:5911 sofia/external/70XX749X7@sip.telnyx.com Set 2833 dtmf send payload to 101 recv payload to 101
2020-09-16 00:33:56.523123 [DEBUG] sofia.c:7760 (sofia/external/70XX749X7@sip.telnyx.com) State Change CS_NEW -> CS_INIT
2020-09-16 00:33:56.523123 [DEBUG] switch_core_state_machine.c:604 (sofia/external/70XX749X7@sip.telnyx.com) State NEW
2020-09-16 00:33:56.523123 [DEBUG] switch_core_state_machine.c:585 (sofia/external/70XX749X7@sip.telnyx.com) Running State Change CS_INIT (Cur 1 Tot 18)
2020-09-16 00:33:56.523123 [DEBUG] switch_core_state_machine.c:628 (sofia/external/70XX749X7@sip.telnyx.com) State INIT
2020-09-16 00:33:56.523123 [DEBUG] mod_sofia.c:93 sofia/external/70XX749X7@sip.telnyx.com SOFIA INIT
2020-09-16 00:33:56.523123 [DEBUG] switch_core_state_machine.c:40 sofia/external/70XX749X7@sip.telnyx.com Standard INIT
2020-09-16 00:33:56.523123 [DEBUG] switch_core_state_machine.c:48 (sofia/external/70XX749X7@sip.telnyx.com) State Change CS_INIT -> CS_ROUTING
2020-09-16 00:33:56.523123 [DEBUG] switch_core_state_machine.c:628 (sofia/external/70XX749X7@sip.telnyx.com) State INIT going to sleep
2020-09-16 00:33:56.523123 [DEBUG] switch_core_state_machine.c:585 (sofia/external/70XX749X7@sip.telnyx.com) Running State Change CS_ROUTING (Cur 1 Tot 18)
2020-09-16 00:33:56.523123 [DEBUG] switch_channel.c:2332 (sofia/external/70XX749X7@sip.telnyx.com) Callstate Change DOWN -> RINGING
2020-09-16 00:33:56.523123 [DEBUG] switch_core_state_machine.c:644 (sofia/external/70XX749X7@sip.telnyx.com) State ROUTING
send 317 bytes to udp/[192.76.120.10]:5060 at 00:33:56.534310:
------------------------------------------------------------------------
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 192.76.120.10;branch=z9hG4bKe873.9197c487b1c4524ff0463a095a643b90.0
f:"70XX749X7"<sip:70XX749X7@sip.telnyx.com>;tag=teB84pX9a57Hc
t:<sip:176XXXX1441@45.76.XXX.XXX:5080>
i:99bbb169-6c35-4bab-b540-a042870128d8
CSeq:25554426 INVITE
User-Agent: FreeSWITCH
Content-Length: 0

2020-09-16 00:33:56.523123 [DEBUG] mod_sofia.c:154 sofia/external/70XX749X7@sip.telnyx.com SOFIA ROUTING
2020-09-16 00:33:56.523123 [DEBUG] switch_core_state_machine.c:236 sofia/external/70XX749X7@sip.telnyx.com Standard ROUTING
2020-09-16 00:33:56.523123 [INFO] mod_dialplan_xml.c:637 Processing 70XX749X7 <70XX749X7>->176XXXX1441 in context public
Dialplan: sofia/external/70XX749X7@sip.telnyx.com parsing [public->caller-details] continue=true
Dialplan: sofia/external/70XX749X7@sip.telnyx.com Regex (PASS) [caller-details] () =~ // break=never
Dialplan: sofia/external/70XX749X7@sip.telnyx.com Action export(call_direction=inbound) INLINE
EXECUTE [depth=0] sofia/external/70XX749X7@sip.telnyx.com export(call_direction=inbound)
2020-09-16 00:33:56.563115 [DEBUG] switch_channel.c:1310 EXPORT (export_vars) [call_direction]=[inbound]
Dialplan: sofia/external/70XX749X7@sip.telnyx.com Action set(caller_destination=${sip_to_user}) INLINE
EXECUTE [depth=0] sofia/external/70XX749X7@sip.telnyx.com set(caller_destination=176XXXX1441)
2020-09-16 00:33:56.563115 [DEBUG] mod_dptools.c:1672 SET sofia/external/70XX749X7@sip.telnyx.com [caller_destination]=[176XXXX1441]
Dialplan: sofia/external/70XX749X7@sip.telnyx.com Action set(caller_id_name=${caller_id_name}) INLINE
EXECUTE [depth=0] sofia/external/70XX749X7@sip.telnyx.com set(caller_id_name=70XX749X7)
2020-09-16 00:33:56.563115 [DEBUG] mod_dptools.c:1672 SET sofia/external/70XX749X7@sip.telnyx.com [caller_id_name]=[70XX749X7]
Dialplan: sofia/external/70XX749X7@sip.telnyx.com Action set(caller_id_number=${caller_id_number})
Dialplan: sofia/external/70XX749X7@sip.telnyx.com parsing [public->7623201441] continue=false
Dialplan: sofia/external/70XX749X7@sip.telnyx.com Regex (FAIL) [7623201441] destination_number(176XXXX1441) =~ /^(7623201441)$/ break=on-false
Dialplan: sofia/external/70XX749X7@sip.telnyx.com parsing [public->not-found] continue=false
Dialplan: sofia/external/70XX749X7@sip.telnyx.com Regex (PASS) [not-found] () =~ // break=on-false
Dialplan: sofia/external/70XX749X7@sip.telnyx.com Action export(call_direction=inbound) INLINE
EXECUTE [depth=0] sofia/external/70XX749X7@sip.telnyx.com export(call_direction=inbound)
2020-09-16 00:33:56.563115 [DEBUG] switch_channel.c:1310 EXPORT (export_vars) [call_direction]=[inbound]
Dialplan: sofia/external/70XX749X7@sip.telnyx.com Action set(call_direction=inbound) INLINE
EXECUTE [depth=0] sofia/external/70XX749X7@sip.telnyx.com set(call_direction=inbound)
2020-09-16 00:33:56.563115 [DEBUG] mod_dptools.c:1672 SET sofia/external/70XX749X7@sip.telnyx.com [call_direction]=[inbound]
Dialplan: sofia/external/70XX749X7@sip.telnyx.com Action log(WARNING [inbound routes] 404 not found ${sip_network_ip})
2020-09-16 00:33:56.563115 [DEBUG] switch_core_state_machine.c:287 (sofia/external/70XX749X7@sip.telnyx.com) State Change CS_ROUTING -> CS_EXECUTE
2020-09-16 00:33:56.563115 [DEBUG] switch_core_state_machine.c:644 (sofia/external/70XX749X7@sip.telnyx.com) State ROUTING going to sleep
2020-09-16 00:33:56.563115 [DEBUG] switch_core_state_machine.c:585 (sofia/external/70XX749X7@sip.telnyx.com) Running State Change CS_EXECUTE (Cur 1 Tot 18)
2020-09-16 00:33:56.563115 [DEBUG] switch_core_state_machine.c:651 (sofia/external/70XX749X7@sip.telnyx.com) State EXECUTE
2020-09-16 00:33:56.563115 [DEBUG] mod_sofia.c:209 sofia/external/70XX749X7@sip.telnyx.com SOFIA EXECUTE
2020-09-16 00:33:56.563115 [DEBUG] switch_core_state_machine.c:329 sofia/external/70XX749X7@sip.telnyx.com Standard EXECUTE
EXECUTE [depth=0] sofia/external/70XX749X7@sip.telnyx.com set(caller_id_number=70XX749X7)
2020-09-16 00:33:56.563115 [DEBUG] mod_dptools.c:1672 SET sofia/external/70XX749X7@sip.telnyx.com [caller_id_number]=[70XX749X7]
EXECUTE [depth=0] sofia/external/70XX749X7@sip.telnyx.com log(WARNING [inbound routes] 404 not found 192.76.120.10)
2020-09-16 00:33:56.563115 [WARNING] mod_dptools.c:1866 [inbound routes] 404 not found 192.76.120.10
2020-09-16 00:33:56.563115 [NOTICE] switch_core_state_machine.c:386 sofia/external/70XX749X7@sip.telnyx.com has executed the last dialplan instruction, hanging up.
2020-09-16 00:33:56.563115 [NOTICE] switch_core_state_machine.c:388 Hangup sofia/external/70XX749X7@sip.telnyx.com [CS_EXECUTE] [NORMAL_CLEARING]
2020-09-16 00:33:56.563115 [DEBUG] switch_core_state_machine.c:651 (sofia/external/70XX749X7@sip.telnyx.com) State EXECUTE going to sleep
2020-09-16 00:33:56.563115 [DEBUG] switch_core_state_machine.c:585 (sofia/external/70XX749X7@sip.telnyx.com) Running State Change CS_HANGUP (Cur 1 Tot 18)
2020-09-16 00:33:56.563115 [DEBUG] switch_core_state_machine.c:848 (sofia/external/70XX749X7@sip.telnyx.com) Callstate Change RINGING -> HANGUP
2020-09-16 00:33:56.563115 [DEBUG] switch_core_state_machine.c:850 (sofia/external/70XX749X7@sip.telnyx.com) State HANGUP
2020-09-16 00:33:56.563115 [DEBUG] mod_sofia.c:453 Channel sofia/external/70XX749X7@sip.telnyx.com hanging up, cause: NORMAL_CLEARING
2020-09-16 00:33:56.563115 [DEBUG] mod_sofia.c:598 Responding to INVITE with: 480
send 772 bytes to udp/[192.76.120.10]:5060 at 00:33:56.582096:
------------------------------------------------------------------------
SIP/2.0 480 Temporarily Unavailable
Via: SIP/2.0/UDP 192.76.120.10;branch=z9hG4bKe873.9197c487b1c4524ff0463a095a643b90.0
v:SIP/2.0/UDP 10.15.196.4:6000;received=10.15.196.4;rport=6000;branch=z9hG4bKS5tD3vB6S1H2D
Max-Forwards: 67
f:"70XX749X7"<sip:70XX749X7@sip.telnyx.com>;tag=teB84pX9a57Hc
To: <sip:176XXXX1441@45.76.XXX.XXX:5080>;tag=4gHFB9X8mXSNS
i:99bbb169-6c35-4bab-b540-a042870128d8
CSeq:25554426 INVITE
User-Agent: FreeSWITCH
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
Reason: Q.850;cause=16;text="NORMAL_CLEARING"
Content-Length: 0
P-Asserted-Identity: "176XXXX1441" <sip:176XXXX1441@45.76.XXX.XXX>

2020-09-16 00:33:56.563115 [DEBUG] switch_core_state_machine.c:60 sofia/external/70XX749X7@sip.telnyx.com Standard HANGUP, cause: NORMAL_CLEARING
2020-09-16 00:33:56.563115 [DEBUG] switch_core_state_machine.c:850 (sofia/external/70XX749X7@sip.telnyx.com) State HANGUP going to sleep
2020-09-16 00:33:56.563115 [DEBUG] switch_core_state_machine.c:620 (sofia/external/70XX749X7@sip.telnyx.com) State Change CS_HANGUP -> CS_REPORTING
2020-09-16 00:33:56.563115 [DEBUG] switch_core_state_machine.c:585 (sofia/external/70XX749X7@sip.telnyx.com) Running State Change CS_REPORTING (Cur 1 Tot 18)
2020-09-16 00:33:56.563115 [DEBUG] switch_core_state_machine.c:936 (sofia/external/70XX749X7@sip.telnyx.com) State REPORTING
recv 341 bytes from udp/[192.76.120.10]:5060 at 00:33:56.627209:
------------------------------------------------------------------------
ACK sip:176XXXX1441@45.76.XXX.XXX:5080 SIP/2.0
Via: SIP/2.0/UDP 192.76.120.10;branch=z9hG4bKe873.9197c487b1c4524ff0463a095a643b90.0
Max-Forwards:67
f:"70XX749X7"<sip:70XX749X7@sip.telnyx.com>;tag=teB84pX9a57Hc
To: <sip:176XXXX1441@45.76.XXX.XXX:5080>;tag=4gHFB9X8mXSNS
i:99bbb169-6c35-4bab-b540-a042870128d8
CSeq:25554426 ACK
l: 0

2020-09-16 00:33:56.663119 [DEBUG] switch_core_state_machine.c:174 sofia/external/70XX749X7@sip.telnyx.com Standard REPORTING, cause: NORMAL_CLEARING
2020-09-16 00:33:56.663119 [DEBUG] switch_core_state_machine.c:936 (sofia/external/70XX749X7@sip.telnyx.com) State REPORTING going to sleep
2020-09-16 00:33:56.663119 [DEBUG] switch_core_state_machine.c:611 (sofia/external/70XX749X7@sip.telnyx.com) State Change CS_REPORTING -> CS_DESTROY
2020-09-16 00:33:56.663119 [DEBUG] switch_core_session.c:1726 Session 18 (sofia/external/70XX749X7@sip.telnyx.com) Locked, Waiting on external entities
2020-09-16 00:33:56.663119 [NOTICE] switch_core_session.c:1744 Session 18 (sofia/external/70XX749X7@sip.telnyx.com) Ended
2020-09-16 00:33:56.663119 [NOTICE] switch_core_session.c:1748 Close Channel sofia/external/70XX749X7@sip.telnyx.com [CS_DESTROY]
2020-09-16 00:33:56.663119 [DEBUG] switch_core_state_machine.c:739 (sofia/external/70XX749X7@sip.telnyx.com) Running State Change CS_DESTROY (Cur 0 Tot 18)
2020-09-16 00:33:56.663119 [DEBUG] switch_core_state_machine.c:749 (sofia/external/70XX749X7@sip.telnyx.com) State DESTROY
2020-09-16 00:33:56.663119 [DEBUG] mod_sofia.c:364 sofia/external/70XX749X7@sip.telnyx.com SOFIA DESTROY
2020-09-16 00:33:56.663119 [DEBUG] switch_core_state_machine.c:181 sofia/external/70XX749X7@sip.telnyx.com Standard DESTROY
2020-09-16 00:33:56.663119 [DEBUG] switch_core_state_machine.c:749 (sofia/external/70XX749X7@sip.telnyx.com) State DESTROY going to sleep
recv 1182 bytes from udp/[192.76.120.10]:5060 at 00:34:01.113986:
------------------------------------------------------------------------
INVITE sip:176XXXX1441@45.76.XXX.XXX:5080 SIP/2.0
Record-Route: <sip:192.76.120.10;r2=on;lr;ftag=ZcvrmKvcZS4Zg>
Record-Route: <sip:10.255.0.1;r2=on;lr;ftag=ZcvrmKvcZS4Zg>
Via: SIP/2.0/UDP 192.76.120.10;branch=z9hG4bK0183.7ca2b06b44e5af8cfb71c85d39977846.0
v:SIP/2.0/UDP 10.15.185.4:6000;received=10.15.185.4;rport=6000;branch=z9hG4bK9jU37pvKg59ye
Max-Forwards:67
f:"70XX749X7"<sip:70XX749X7@sip.telnyx.com>;tag=ZcvrmKvcZS4Zg
t:<sip:176XXXX1441@45.76.XXX.XXX:5080>
i:d29e30e1-edaf-4ea1-b7c6-5e755dea1c25
CSeq:25554428 INVITE
m:<sip:mod_sofia@10.15.185.4:6000>
Allow:INVITE,ACK,BYE,CANCEL,OPTIONS,MESSAGE,INFO,UPDATE,REFER,NOTIFY
k:timer,path,replaces
u:talk,hold,conference,refer
Privacy:none
c:application/sdp
Content-Disposition:session
l:353
P-Asserted-Identity:"70XX749X7"<sip:70XX749X7@sip.telnyx.com>

v=0
o=Telnyx 1600193291 1600193292 IN IP4 64.16.248.73
s=Telnyx
c=IN IP4 64.16.248.73
t=0 0
m=audio 23150 RTP/AVP 9 0 8 18 101
a=rtpmap:9 G722/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=sendrecv
a=rtcp:23151 IN IP4 64.16.248.73
a=ptime:20
2020-09-16 00:34:01.103127 [NOTICE] switch_channel.c:1118 New Channel sofia/external/70XX749X7@sip.telnyx.com [c80a4019-c999-4204-90aa-e1da4c80130d]
2020-09-16 00:34:01.103127 [DEBUG] switch_core_state_machine.c:585 (sofia/external/70XX749X7@sip.telnyx.com) Running State Change CS_NEW (Cur 1 Tot 19)
2020-09-16 00:34:01.103127 [DEBUG] sofia.c:10280 sofia/external/70XX749X7@sip.telnyx.com receiving invite from 192.76.120.10:5060 version: 1.10.5 -release-17-25569c1631 64bit
2020-09-16 00:34:01.103127 [DEBUG] sofia.c:10374 verifying acl "domains" for ip/port 192.76.120.10:0.
2020-09-16 00:34:01.103127 [DEBUG] sofia.c:10403 IP 192.76.120.10 Approved by acl "domains[]". Access Granted.
2020-09-16 00:34:01.103127 [DEBUG] sofia.c:7326 Channel sofia/external/70XX749X7@sip.telnyx.com entering state [received][100]
2020-09-16 00:34:01.103127 [DEBUG] sofia.c:7336 Remote SDP:
v=0
o=Telnyx 1600193291 1600193292 IN IP4 64.16.248.73
s=Telnyx
c=IN IP4 64.16.248.73
t=0 0
m=audio 23150 RTP/AVP 9 0 8 18 101
a=rtpmap:9 G722/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=rtcp:23151 IN IP4 64.16.248.73
a=ptime:20

2020-09-16 00:34:01.103127 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [G722:9:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2020-09-16 00:34:01.103127 [DEBUG] switch_core_media.c:5649 Audio Codec Compare [G722:9:8000:20:64000:1] ++++ is saved as a match
2020-09-16 00:34:01.103127 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2020-09-16 00:34:01.103127 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2020-09-16 00:34:01.103127 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2020-09-16 00:34:01.103127 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2020-09-16 00:34:01.103127 [DEBUG] switch_core_media.c:5649 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
2020-09-16 00:34:01.103127 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2020-09-16 00:34:01.103127 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2020-09-16 00:34:01.103127 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2020-09-16 00:34:01.103127 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2020-09-16 00:34:01.103127 [DEBUG] switch_core_media.c:5649 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
2020-09-16 00:34:01.103127 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [G729:18:8000:20:8000:1]/[G722:9:8000:20:64000:1]
2020-09-16 00:34:01.103127 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMU:0:8000:20:64000:1]
2020-09-16 00:34:01.103127 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMA:8:8000:20:64000:1]
2020-09-16 00:34:01.103127 [DEBUG] switch_core_media.c:5510 Set telephone-event payload to 101@8000
2020-09-16 00:34:01.103127 [DEBUG] switch_core_media.c:3839 Set Codec sofia/external/70XX749X7@sip.telnyx.com G722/8000 20 ms 160 samples 64000 bits 1 channels
2020-09-16 00:34:01.103127 [DEBUG] switch_core_codec.c:111 sofia/external/70XX749X7@sip.telnyx.com Original read codec set to G722:9
2020-09-16 00:34:01.103127 [DEBUG] switch_core_media.c:5853 Set telephone-event payload to 101@8000
2020-09-16 00:34:01.103127 [DEBUG] switch_core_media.c:5911 sofia/external/70XX749X7@sip.telnyx.com Set 2833 dtmf send payload to 101 recv payload to 101
2020-09-16 00:34:01.103127 [DEBUG] sofia.c:7760 (sofia/external/70XX749X7@sip.telnyx.com) State Change CS_NEW -> CS_INIT
2020-09-16 00:34:01.103127 [DEBUG] switch_core_state_machine.c:604 (sofia/external/70XX749X7@sip.telnyx.com) State NEW
2020-09-16 00:34:01.103127 [DEBUG] switch_core_state_machine.c:585 (sofia/external/70XX749X7@sip.telnyx.com) Running State Change CS_INIT (Cur 1 Tot 19)
2020-09-16 00:34:01.103127 [DEBUG] switch_core_state_machine.c:628 (sofia/external/70XX749X7@sip.telnyx.com) State INIT
2020-09-16 00:34:01.103127 [DEBUG] mod_sofia.c:93 sofia/external/70XX749X7@sip.telnyx.com SOFIA INIT
2020-09-16 00:34:01.103127 [DEBUG] switch_core_state_machine.c:40 sofia/external/70XX749X7@sip.telnyx.com Standard INIT
2020-09-16 00:34:01.103127 [DEBUG] switch_core_state_machine.c:48 (sofia/external/70XX749X7@sip.telnyx.com) State Change CS_INIT -> CS_ROUTING
2020-09-16 00:34:01.103127 [DEBUG] switch_core_state_machine.c:628 (sofia/external/70XX749X7@sip.telnyx.com) State INIT going to sleep
2020-09-16 00:34:01.103127 [DEBUG] switch_core_state_machine.c:585 (sofia/external/70XX749X7@sip.telnyx.com) Running State Change CS_ROUTING (Cur 1 Tot 19)
2020-09-16 00:34:01.103127 [DEBUG] switch_channel.c:2332 (sofia/external/70XX749X7@sip.telnyx.com) Callstate Change DOWN -> RINGING
2020-09-16 00:34:01.103127 [DEBUG] switch_core_state_machine.c:644 (sofia/external/70XX749X7@sip.telnyx.com) State ROUTING
send 317 bytes to udp/[192.76.120.10]:5060 at 00:34:01.115540:
------------------------------------------------------------------------
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 192.76.120.10;branch=z9hG4bK0183.7ca2b06b44e5af8cfb71c85d39977846.0
f:"70XX749X7"<sip:70XX749X7@sip.telnyx.com>;tag=ZcvrmKvcZS4Zg
t:<sip:176XXXX1441@45.76.XXX.XXX:5080>
i:d29e30e1-edaf-4ea1-b7c6-5e755dea1c25
CSeq:25554428 INVITE
User-Agent: FreeSWITCH
Content-Length: 0

2020-09-16 00:34:01.103127 [DEBUG] mod_sofia.c:154 sofia/external/70XX749X7@sip.telnyx.com SOFIA ROUTING
2020-09-16 00:34:01.103127 [DEBUG] switch_core_state_machine.c:236 sofia/external/70XX749X7@sip.telnyx.com Standard ROUTING
2020-09-16 00:34:01.103127 [INFO] mod_dialplan_xml.c:637 Processing 70XX749X7 <70XX749X7>->176XXXX1441 in context public
Dialplan: sofia/external/70XX749X7@sip.telnyx.com parsing [public->caller-details] continue=true
Dialplan: sofia/external/70XX749X7@sip.telnyx.com Regex (PASS) [caller-details] () =~ // break=never
Dialplan: sofia/external/70XX749X7@sip.telnyx.com Action export(call_direction=inbound) INLINE
EXECUTE [depth=0] sofia/external/70XX749X7@sip.telnyx.com export(call_direction=inbound)
2020-09-16 00:34:01.103127 [DEBUG] switch_channel.c:1310 EXPORT (export_vars) [call_direction]=[inbound]
Dialplan: sofia/external/70XX749X7@sip.telnyx.com Action set(caller_destination=${sip_to_user}) INLINE
EXECUTE [depth=0] sofia/external/70XX749X7@sip.telnyx.com set(caller_destination=176XXXX1441)
2020-09-16 00:34:01.103127 [DEBUG] mod_dptools.c:1672 SET sofia/external/70XX749X7@sip.telnyx.com [caller_destination]=[176XXXX1441]
Dialplan: sofia/external/70XX749X7@sip.telnyx.com Action set(caller_id_name=${caller_id_name}) INLINE
EXECUTE [depth=0] sofia/external/70XX749X7@sip.telnyx.com set(caller_id_name=70XX749X7)
2020-09-16 00:34:01.103127 [DEBUG] mod_dptools.c:1672 SET sofia/external/70XX749X7@sip.telnyx.com [caller_id_name]=[70XX749X7]
Dialplan: sofia/external/70XX749X7@sip.telnyx.com Action set(caller_id_number=${caller_id_number})
Dialplan: sofia/external/70XX749X7@sip.telnyx.com parsing [public->7623201441] continue=false
Dialplan: sofia/external/70XX749X7@sip.telnyx.com Regex (FAIL) [7623201441] destination_number(176XXXX1441) =~ /^(7623201441)$/ break=on-false
Dialplan: sofia/external/70XX749X7@sip.telnyx.com parsing [public->not-found] continue=false
Dialplan: sofia/external/70XX749X7@sip.telnyx.com Regex (PASS) [not-found] () =~ // break=on-false
Dialplan: sofia/external/70XX749X7@sip.telnyx.com Action export(call_direction=inbound) INLINE
EXECUTE [depth=0] sofia/external/70XX749X7@sip.telnyx.com export(call_direction=inbound)
2020-09-16 00:34:01.103127 [DEBUG] switch_channel.c:1310 EXPORT (export_vars) [call_direction]=[inbound]
Dialplan: sofia/external/70XX749X7@sip.telnyx.com Action set(call_direction=inbound) INLINE
EXECUTE [depth=0] sofia/external/70XX749X7@sip.telnyx.com set(call_direction=inbound)
2020-09-16 00:34:01.103127 [DEBUG] mod_dptools.c:1672 SET sofia/external/70XX749X7@sip.telnyx.com [call_direction]=[inbound]
Dialplan: sofia/external/70XX749X7@sip.telnyx.com Action log(WARNING [inbound routes] 404 not found ${sip_network_ip})
2020-09-16 00:34:01.103127 [DEBUG] switch_core_state_machine.c:287 (sofia/external/70XX749X7@sip.telnyx.com) State Change CS_ROUTING -> CS_EXECUTE
2020-09-16 00:34:01.103127 [DEBUG] switch_core_state_machine.c:644 (sofia/external/70XX749X7@sip.telnyx.com) State ROUTING going to sleep
2020-09-16 00:34:01.103127 [DEBUG] switch_core_state_machine.c:585 (sofia/external/70XX749X7@sip.telnyx.com) Running State Change CS_EXECUTE (Cur 1 Tot 19)
2020-09-16 00:34:01.103127 [DEBUG] switch_core_state_machine.c:651 (sofia/external/70XX749X7@sip.telnyx.com) State EXECUTE
2020-09-16 00:34:01.103127 [DEBUG] mod_sofia.c:209 sofia/external/70XX749X7@sip.telnyx.com SOFIA EXECUTE
2020-09-16 00:34:01.103127 [DEBUG] switch_core_state_machine.c:329 sofia/external/70XX749X7@sip.telnyx.com Standard EXECUTE
EXECUTE [depth=0] sofia/external/70XX749X7@sip.telnyx.com set(caller_id_number=70XX749X7)
2020-09-16 00:34:01.103127 [DEBUG] mod_dptools.c:1672 SET sofia/external/70XX749X7@sip.telnyx.com [caller_id_number]=[70XX749X7]
EXECUTE [depth=0] sofia/external/70XX749X7@sip.telnyx.com log(WARNING [inbound routes] 404 not found 192.76.120.10)
2020-09-16 00:34:01.103127 [WARNING] mod_dptools.c:1866 [inbound routes] 404 not found 192.76.120.10
2020-09-16 00:34:01.103127 [NOTICE] switch_core_state_machine.c:386 sofia/external/70XX749X7@sip.telnyx.com has executed the last dialplan instruction, hanging up.
2020-09-16 00:34:01.103127 [NOTICE] switch_core_state_machine.c:388 Hangup sofia/external/70XX749X7@sip.telnyx.com [CS_EXECUTE] [NORMAL_CLEARING]
2020-09-16 00:34:01.103127 [DEBUG] switch_core_state_machine.c:651 (sofia/external/70XX749X7@sip.telnyx.com) State EXECUTE going to sleep
2020-09-16 00:34:01.103127 [DEBUG] switch_core_state_machine.c:585 (sofia/external/70XX749X7@sip.telnyx.com) Running State Change CS_HANGUP (Cur 1 Tot 19)
2020-09-16 00:34:01.103127 [DEBUG] switch_core_state_machine.c:848 (sofia/external/70XX749X7@sip.telnyx.com) Callstate Change RINGING -> HANGUP
2020-09-16 00:34:01.103127 [DEBUG] switch_core_state_machine.c:850 (sofia/external/70XX749X7@sip.telnyx.com) State HANGUP
2020-09-16 00:34:01.103127 [DEBUG] mod_sofia.c:453 Channel sofia/external/70XX749X7@sip.telnyx.com hanging up, cause: NORMAL_CLEARING
2020-09-16 00:34:01.103127 [DEBUG] mod_sofia.c:598 Responding to INVITE with: 480
send 772 bytes to udp/[192.76.120.10]:5060 at 00:34:01.119360:
------------------------------------------------------------------------
SIP/2.0 480 Temporarily Unavailable
Via: SIP/2.0/UDP 192.76.120.10;branch=z9hG4bK0183.7ca2b06b44e5af8cfb71c85d39977846.0
v:SIP/2.0/UDP 10.15.185.4:6000;received=10.15.185.4;rport=6000;branch=z9hG4bK9jU37pvKg59ye
Max-Forwards: 67
f:"70XX749X7"<sip:70XX749X7@sip.telnyx.com>;tag=ZcvrmKvcZS4Zg
To: <sip:176XXXX1441@45.76.XXX.XXX:5080>;tag=5Sa8c4ecj6F8m
i:d29e30e1-edaf-4ea1-b7c6-5e755dea1c25
CSeq:25554428 INVITE
User-Agent: FreeSWITCH
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
Reason: Q.850;cause=16;text="NORMAL_CLEARING"
Content-Length: 0
P-Asserted-Identity: "176XXXX1441" <sip:176XXXX1441@45.76.XXX.XXX>

2020-09-16 00:34:01.103127 [DEBUG] switch_core_state_machine.c:60 sofia/external/70XX749X7@sip.telnyx.com Standard HANGUP, cause: NORMAL_CLEARING
2020-09-16 00:34:01.103127 [DEBUG] switch_core_state_machine.c:850 (sofia/external/70XX749X7@sip.telnyx.com) State HANGUP going to sleep
2020-09-16 00:34:01.103127 [DEBUG] switch_core_state_machine.c:620 (sofia/external/70XX749X7@sip.telnyx.com) State Change CS_HANGUP -> CS_REPORTING
2020-09-16 00:34:01.103127 [DEBUG] switch_core_state_machine.c:585 (sofia/external/70XX749X7@sip.telnyx.com) Running State Change CS_REPORTING (Cur 1 Tot 19)
2020-09-16 00:34:01.103127 [DEBUG] switch_core_state_machine.c:936 (sofia/external/70XX749X7@sip.telnyx.com) State REPORTING
recv 341 bytes from udp/[192.76.120.10]:5060 at 00:34:01.162967:
------------------------------------------------------------------------
ACK sip:176XXXX1441@45.76.XXX.XXX:5080 SIP/2.0
Via: SIP/2.0/UDP 192.76.120.10;branch=z9hG4bK0183.7ca2b06b44e5af8cfb71c85d39977846.0
Max-Forwards:67
f:"70XX749X7"<sip:70XX749X7@sip.telnyx.com>;tag=ZcvrmKvcZS4Zg
To: <sip:176XXXX1441@45.76.XXX.XXX:5080>;tag=5Sa8c4ecj6F8m
i:d29e30e1-edaf-4ea1-b7c6-5e755dea1c25
CSeq:25554428 ACK
l: 0

2020-09-16 00:34:01.163112 [DEBUG] switch_core_state_machine.c:174 sofia/external/70XX749X7@sip.telnyx.com Standard REPORTING, cause: NORMAL_CLEARING
2020-09-16 00:34:01.163112 [DEBUG] switch_core_state_machine.c:936 (sofia/external/70XX749X7@sip.telnyx.com) State REPORTING going to sleep
2020-09-16 00:34:01.163112 [DEBUG] switch_core_state_machine.c:611 (sofia/external/70XX749X7@sip.telnyx.com) State Change CS_REPORTING -> CS_DESTROY
2020-09-16 00:34:01.163112 [DEBUG] switch_core_session.c:1726 Session 19 (sofia/external/70XX749X7@sip.telnyx.com) Locked, Waiting on external entities
2020-09-16 00:34:01.163112 [NOTICE] switch_core_session.c:1744 Session 19 (sofia/external/70XX749X7@sip.telnyx.com) Ended
2020-09-16 00:34:01.163112 [NOTICE] switch_core_session.c:1748 Close Channel sofia/external/70XX749X7@sip.telnyx.com [CS_DESTROY]
2020-09-16 00:34:01.163112 [DEBUG] switch_core_state_machine.c:739 (sofia/external/70XX749X7@sip.telnyx.com) Running State Change CS_DESTROY (Cur 0 Tot 19)
2020-09-16 00:34:01.163112 [DEBUG] switch_core_state_machine.c:749 (sofia/external/70XX749X7@sip.telnyx.com) State DESTROY
2020-09-16 00:34:01.163112 [DEBUG] mod_sofia.c:364 sofia/external/70XX749X7@sip.telnyx.com SOFIA DESTROY
2020-09-16 00:34:01.163112 [DEBUG] switch_core_state_machine.c:181 sofia/external/70XX749X7@sip.telnyx.com Standard DESTROY
2020-09-16 00:34:01.163112 [DEBUG] switch_core_state_machine.c:749 (sofia/external/70XX749X7@sip.telnyx.com) State DESTROY going to sleep
freeswitch@FusionPBX>

I have tried playing around with the inbound route DID by adding +1, 1, just the 10 digit # but it results in the same. Number format with Telnyx is E164. Any help will be appreciated. If you can shed some light on what I am doing wrong and help me understand the freeswitch way of doing things that would be great!

Thank you!

khanali.paiwandzada · Sep 16, 2020

Hi Dear,
Please check if you have added the IP address of your SIP provider in the access-control of your fusion PBX, if you have not added follow below step.

Go to Advanced
Select Access Controls
Edit the Domains
Another another node
Select the Allow
on CIDR type IP address of your SIP Provider example (103.27.44.54/32)
Save
Reload ACL
FLUSH Cache

If this solved your issue let us know.

Bifur · Sep 16, 2020

Yes, I have added the ip addresses to the ACL. On a side note, I thought I read where if I sent the sup provider to port 5080 then I did not have to worry about ACL. Maybe I misunderstood. However, if you look in my call snippet you will see:

Code:

2020-09-16 00:34:01.103127 [DEBUG] sofia.c:10374 verifying acl "domains" for ip/port 192.76.120.10:0.
2020-09-16 00:34:01.103127 [DEBUG] sofia.c:10403 IP 192.76.120.10 Approved by acl "domains[]". Access Granted.

There were 2 ips on Telnyx's website that I added.

Thanks for the reply!

falk · Sep 16, 2020

check the destination no

Bifur · Sep 16, 2020

falk said:
check the destination no

That's the part I'm confused on. The Telnyx article stated to use +1 before the did which I did. I also tried just 1 plus did as well as just the 10 digit did. All seem to give me the 480 temporary error.

I searched the forums and saw some people having issues with what the provider was sending as the did but I do not see that in my test example. I'm very new to fusion though so maybe I am missing something.

DigitalDaz · Sep 16, 2020

There is definitely a mismatch in the sent number and the did you have configured.

Regex (FAIL) [7623201441] destination_number(176XXXX1441) =~ /^(7623201441)$/

PS Don't bother trying to obscure the number unless you do it properly

Bifur · Sep 16, 2020

DigitalDaz said:
There is definitely a mismatch in the sent number and the did you have configured.

Regex (FAIL) [7623201441] destination_number(176XXXX1441) =~ /^(7623201441)$/

PS Don't bother trying to obscure the number unless you do it properly

Whoops, glad it's just a test did! So I will have to double check the settings but as I've said earlier, I have tried 17623201441, +17623201441 and just 7623201441. All result in the same 480. That is what I'm confused on.

Can you shed light on what I would have to use using the call example I have provided?

falk · Sep 16, 2020

use all the option
441
then
1441
then
x1441

DigitalDaz · Sep 16, 2020

Bifur said:
Whoops, glad it's just a test did! So I will have to double check the settings but as I've said earlier, I have tried 17623201441, +17623201441 and just 7623201441. All result in the same 480. That is what I'm confused on.

Can you shed light on what I would have to use using the call example I have provided?

In the above example you would want a destination for: 17623201441

If it still fails, then post another log as it will be something different and you should have moved on a bit.

Bifur · Sep 16, 2020

I will try again this evening. I am unable to play with it until then. Thanks everyone for the help so far!

Bifur · Sep 17, 2020

So deleted destination and inbound route, added the 11 digit number and guess what? It rang! I swear I did that already but now I am wondering if I was just editing the inbound route and not the 'destination'? I know when you add a destination it creates the inbound route so does that make sense on why it may not have worked? Just scratching my head.

Thank you all for your help!

DigitalDaz · Sep 17, 2020

In general, you should never need to touch an inbound route.

Its also possible that editing the inbound route directly doesn't update the cache but that is just a theory based on what you have said.

StefanIvanov · Sep 18, 2020

Hi everyone,

I`m making a school project(mini CRM system). I think i have similar problem. When i try to make an inbound call I have an warning "[inbound routes] 404 not found ${sip_network_ip}". Here is the log of test call

Code:

FreeSWITCH Started
Max Sessions [1000]
Session Rate [30]
SQL [Enabled]
2020-09-17 15:20:08.807325 [WARNING] sofia_reg.c:1794 SIP auth challenge (REGISTER) on sofia profile 'internal' for [1011@xxx.xxx.x.118] from ip xxx.xxx.x.165
2020-09-17 15:21:00.367301 [WARNING] sofia_reg.c:1794 SIP auth challenge (REGISTER) on sofia profile 'internal' for [1010@xxx.xxx.x.118] from ip xxx.xxx.x.122
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:12.347326 [NOTICE] switch_channel.c:1118 New Channel sofia/internal/1010@xxx.xxx.x.118 [e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9]
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:12.347326 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/1010@xxx.xxx.x.118) Running State Change CS_NEW (C
ur 1 Tot 1)
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:12.407271 [DEBUG] sofia.c:10280 sofia/internal/1010@xxx.xxx.x.118 receiving invite from xxx.xxx.x.122:52102 version: 1.10.5 -release-17-25569c1631 64bit
2020-09-17 15:21:12.447386 [DEBUG] sofia.c:10374 verifying acl "localnet.auto" for ip/port xxx.xxx.x.122:0.
2020-09-17 15:21:12.447386 [DEBUG] sofia.c:10403 IP xxx.xxx.x.122 Approved by acl "localnet.auto[]". Access Granted.
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:12.507342 [DEBUG] sofia.c:11477 Setting NAT mode based on via received
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:12.507342 [DEBUG] sofia.c:7326 Channel sofia/internal/1010@xxx.xxx.x.118 entering state [received][100]
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:12.507342 [DEBUG] sofia.c:7336 Remote SDP:
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 v=0
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 o=- 6838702468214364159 2 IN IP4 127.0.0.1
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 s=-
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 t=0 0
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 a=group:BUNDLE 0
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 a=msid-semantic: WMS 2bdcc949-4110-4bb5-8109-fd6674d9f389
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 m=audio 57622 UDP/TLS/RTP/SAVPF 111 103 104 9 0 8 106 105 13 110 112 113 126
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 c=IN IP4 37.157.169.84
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 a=rtpmap:111 opus/48000/2
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 a=fmtp:111 minptime=10;useinbandfec=1
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 a=rtpmap:103 ISAC/16000
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 a=rtpmap:104 ISAC/32000
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 a=rtpmap:9 G722/8000
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 a=rtpmap:0 PCMU/8000
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 a=rtpmap:8 PCMA/8000
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 a=rtpmap:106 CN/32000
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 a=rtpmap:105 CN/16000
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 a=rtpmap:13 CN/8000
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 a=rtpmap:110 telephone-event/48000
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 a=rtpmap:112 telephone-event/32000
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 a=rtpmap:113 telephone-event/16000
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 a=rtpmap:126 telephone-event/8000
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 a=rtcp:9 IN IP4 0.0.0.0
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 a=candidate:1668076467 1 udp 2113937151 xxx.xxx.x.122 57622 typ host generation 0 network-cost 999
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 a=candidate:842163049 1 udp 1677729535 37.157.169.84 57622 typ srflx raddr xxx.xxx.x.122 rport 57622 generation 0 network-cost 999
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 a=ice-ufrag:Y1H1
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 a=ice-pwd:bgGkQW2Q+QkKBVEVeJlM9pAv
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 a=ice-options:trickle
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 a=fingerprint:sha-256 DF:C9:FB:E0:B5:DB:9E:D3:74:08:52:95:41:EB:7E:54:57:10:05:0F:0D:44:C3:C3:3B:E8:D4:43:4E:A8:4F:EF
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 a=setup:actpass
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 a=mid:0
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 a=extmap:1 urn:ietf:params:rtp-hdrext:ssrc-audio-level
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 a=extmap:2 http://www.ietf.org/id/draft-holmer-rmcat-transport-wide-cc-extensions-01
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 a=extmap:3 urn:ietf:params:rtp-hdrext:sdes:mid
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 a=extmap:4 urn:ietf:params:rtp-hdrext:sdes:rtp-stream-id
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 a=extmap:5 urn:ietf:params:rtp-hdrext:sdes:repaired-rtp-stream-id
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 a=msid:2bdcc949-4110-4bb5-8109-fd6674d9f389 44d74464-519c-4317-b202-5c9b407c065b
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 a=rtcp-mux
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 a=rtcp-fb:111 transport-cc
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 a=ssrc:732787876 cname:/tqRPKnxJClA9pZO
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 a=ssrc:732787876 msid:2bdcc949-4110-4bb5-8109-fd6674d9f389 44d74464-519c-4317-b202-5c9b407c065b
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 a=ssrc:732787876 mslabel:2bdcc949-4110-4bb5-8109-fd6674d9f389
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 a=ssrc:732787876 label:44d74464-519c-4317-b202-5c9b407c065b
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:12.507342 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [opus:111:48000:20:0:2]/[G722:9:8000:20:64000:1]
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:12.507342 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [opus:111:48000:20:0:2]/[PCMU:0:8000:20:64000:1]
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:12.507342 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [opus:111:48000:20:0:2]/[PCMA:8:8000:20:64000:1]
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:12.507342 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [ISAC:103:16000:30:32000:1]/[G722:9:8000:20:64000:1]
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:12.507342 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [ISAC:103:16000:30:32000:1]/[PCMU:0:8000:20:64000:1]
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:12.507342 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [ISAC:103:16000:30:32000:1]/[PCMA:8:8000:20:64000:1]
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:12.507342 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [ISAC:104:32000:30:32000:1]/[G722:9:8000:20:64000:1]
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:12.507342 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [ISAC:104:32000:30:32000:1]/[PCMU:0:8000:20:64000:1]
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:12.507342 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [ISAC:104:32000:30:32000:1]/[PCMA:8:8000:20:64000:1]
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:12.507342 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [G722:9:8000:20:64000:1]/[G722:9:8000:20:64000:1]
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:12.507342 [DEBUG] switch_core_media.c:5649 Audio Codec Compare [G722:9:8000:20:64000:1] ++++ is saved as a match
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:12.527218 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:12.527218 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:12.527218 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1]
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:12.527218 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:12.527218 [DEBUG] switch_core_media.c:5649 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:12.527218 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:12.527218 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1]
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:12.527218 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:12.527218 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:12.527218 [DEBUG] switch_core_media.c:5649 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:12.527218 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [CN:105:16000:20:0:1]/[G722:9:8000:20:64000:1]
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:12.527218 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [CN:105:16000:20:0:1]/[PCMU:0:8000:20:64000:1]
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:12.527218 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [CN:105:16000:20:0:1]/[PCMA:8:8000:20:64000:1]
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:12.527218 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [CN:13:8000:20:0:1]/[G722:9:8000:20:64000:1]
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:12.527218 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [CN:13:8000:20:0:1]/[PCMU:0:8000:20:64000:1]
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:12.527218 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [CN:13:8000:20:0:1]/[PCMA:8:8000:20:64000:1]
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:12.527218 [DEBUG] switch_core_media.c:5510 Set telephone-event payload to 110@48000
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:12.587258 [DEBUG] switch_core_media.c:3839 Set Codec sofia/internal/1010@xxx.xxx.x.118 G722/8000 20 ms 160 samples 64000 bits 1 channels
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:12.587258 [DEBUG] switch_core_codec.c:111 sofia/internal/1010@xxx.xxx.x.118 Original read codec set to G722:9
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:12.587258 [WARNING] switch_core_media.c:4254 NO candidate ACL defined, Defaulting to wan.auto
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:12.587258 [DEBUG] switch_core_media.c:4284 Save audio Candidate cid: 1 proto: udp type: host addr: xxx.xxx.x.122:57622
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:12.587258 [DEBUG] switch_core_media.c:4284 Save audio Candidate cid: 1 proto: udp type: srflx addr: 37.157.169.84:57622
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:12.707331 [DEBUG] switch_core_media.c:4329 Searching for rtp candidate.
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:12.707331 [DEBUG] switch_core_media.c:4338 Choose rtp candidate, index 1, 37.157.169.84:57622
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:12.707331 [DEBUG] switch_core_media.c:4104 sofia/internal/1010@xxx.xxx.x.118 choosing family v4
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:12.707331 [DEBUG] switch_core_media.c:4349 Choose same candidate, index 0, for rtcp based on rtcp-mux attribute 37.157.169.84:57622
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:12.707331 [DEBUG] switch_core_media.c:4401 setting remote audio ice addr to index 1 37.157.169.84:57622 based on candidate
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:12.707331 [DEBUG] switch_core_media.c:4436 Setting remote rtcp audio addr to 37.157.169.84:57622 based on candidate
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:12.707331 [DEBUG] switch_core_media.c:5853 Set telephone-event payload to 126@8000
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:12.707331 [DEBUG] switch_core_media.c:5911 sofia/internal/1010@xxx.xxx.x.118 Set 2833 dtmf send payload to 126 recv payload to 126
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:12.707331 [DEBUG] sofia.c:7760 (sofia/internal/1010@xxx.xxx.x.118) State Change CS_NEW -> CS_INIT
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:12.707331 [DEBUG] switch_core_state_machine.c:604 (sofia/internal/1010@xxx.xxx.x.118) State NEW
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:12.707331 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/1010@xxx.xxx.x.118) Running State Change CS_INIT (Cur 1 Tot 1)
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:12.707331 [DEBUG] switch_core_state_machine.c:628 (sofia/internal/1010@xxx.xxx.x.118) State INIT
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:12.727249 [DEBUG] mod_sofia.c:93 sofia/internal/1010@xxx.xxx.x.118 SOFIA INIT
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:12.727249 [DEBUG] switch_core_state_machine.c:40 sofia/internal/1010@xxx.xxx.x.118 Standard INIT
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:12.727249 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/1010@xxx.xxx.x.118) State Change CS_INIT -> CS_ROUTING
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:12.727249 [DEBUG] switch_core_state_machine.c:628 (sofia/internal/1010@xxx.xxx.x.118) State INIT going to sleep
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:12.727249 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/1010@xxx.xxx.x.118) Running State Change CS_ROUTING (Cur 1 Tot 1)
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:12.727249 [DEBUG] switch_channel.c:2332 (sofia/internal/1010@xxx.xxx.x.118) Callstate Change DOWN -> RINGING
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:12.727249 [DEBUG] switch_core_state_machine.c:644 (sofia/internal/1010@xxx.xxx.x.118) State ROUTING
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:12.727249 [DEBUG] mod_sofia.c:154 sofia/internal/1010@xxx.xxx.x.118 SOFIA ROUTING
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:12.727249 [DEBUG] switch_core_state_machine.c:236 sofia/internal/1010@xxx.xxx.x.118 Standard ROUTING
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:12.767373 [INFO] mod_dialplan_xml.c:637 Processing Stefan <1010>->1011 in context public
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 Dialplan: sofia/internal/1010@xxx.xxx.x.118 parsing [public->caller-details] continue=true
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 Dialplan: sofia/internal/1010@xxx.xxx.x.118 Regex (PASS) [caller-details] () =~ // break=never
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 Dialplan: sofia/internal/1010@xxx.xxx.x.118 Action export(call_direction=inbound) INLINE
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 EXECUTE [depth=0] sofia/internal/1010@xxx.xxx.x.118 export(call_direction=inbound)
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:13.187281 [DEBUG] switch_channel.c:1310 EXPORT (export_vars) [call_direction]=[inbound]
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 Dialplan: sofia/internal/1010@xxx.xxx.x.118 Action set(caller_destination=${sip_to_user}) INLINE
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 EXECUTE [depth=0] sofia/internal/1010@xxx.xxx.x.118 set(caller_destination=1011)
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:13.187281 [DEBUG] mod_dptools.c:1672 SET sofia/internal/1010@xxx.xxx.x.118 [caller_destination]=[1011]
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 Dialplan: sofia/internal/1010@xxx.xxx.x.118 Action set(caller_id_name=${caller_id_name}) INLINE
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 EXECUTE [depth=0] sofia/internal/1010@xxx.xxx.x.118 set(caller_id_name=Stefan)
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:13.187281 [DEBUG] mod_dptools.c:1672 SET sofia/internal/1010@xxx.xxx.x.118 [caller_id_name]=[Stefan]
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 Dialplan: sofia/internal/1010@xxx.xxx.x.118 Action set(caller_id_number=${caller_id_number})
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 Dialplan: sofia/internal/1010@xxx.xxx.x.118 parsing [public->not-found] continue=false
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 Dialplan: sofia/internal/1010@xxx.xxx.x.118 Regex (PASS) [not-found] () =~ // break=on-false
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 Dialplan: sofia/internal/1010@xxx.xxx.x.118 Action export(call_direction=inbound) INLINE
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 EXECUTE [depth=0] sofia/internal/1010@xxx.xxx.x.118 export(call_direction=inbound)
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:13.187281 [DEBUG] switch_channel.c:1310 EXPORT (export_vars) [call_direction]=[inbound]
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 Dialplan: sofia/internal/1010@xxx.xxx.x.118 Action set(call_direction=inbound) INLINE
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 EXECUTE [depth=0] sofia/internal/1010@xxx.xxx.x.118 set(call_direction=inbound)
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:13.187281 [DEBUG] mod_dptools.c:1672 SET sofia/internal/1010@xxx.xxx.x.118 [call_direction]=[inbound]
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 Dialplan: sofia/internal/1010@xxx.xxx.x.118 Action log(WARNING [inbound routes] 404 not found ${sip_network_ip})
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:13.187281 [DEBUG] switch_core_state_machine.c:287 (sofia/internal/1010@xxx.xxx.x.118) State Change CS_ROUTING -> CS_EXECUTE
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:13.187281 [DEBUG] switch_core_state_machine.c:644 (sofia/internal/1010@xxx.xxx.x.118) State ROUTING going to sleep
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:13.187281 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/1010@xxx.xxx.x.118) Running State Change CS_EXECUTE (Cur 1 Tot 1)
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:13.187281 [DEBUG] switch_core_state_machine.c:651 (sofia/internal/1010@xxx.xxx.x.118) State EXECUTE
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:13.187281 [DEBUG] mod_sofia.c:209 sofia/internal/1010@xxx.xxx.x.118 SOFIA EXECUTE
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:13.187281 [DEBUG] switch_core_state_machine.c:329 sofia/internal/1010@xxx.xxx.x.118 Standard EXECUTE
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 EXECUTE [depth=0] sofia/internal/1010@xxx.xxx.x.118 set(caller_id_number=1010)
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:13.187281 [DEBUG] mod_dptools.c:1672 SET sofia/internal/1010@xxx.xxx.x.118 [caller_id_number]=[1010]
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 EXECUTE [depth=0] sofia/internal/1010@xxx.xxx.x.118 log(WARNING [inbound routes] 404 not found xxx.xxx.x.122)
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:13.187281 [WARNING] mod_dptools.c:1866 [inbound routes] 404 not found xxx.xxx.x.122
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:13.187281 [NOTICE] switch_core_state_machine.c:386 sofia/internal/1010@xxx.xxx.x.118 has executed the last dialplan instruction, hanging up.
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:13.187281 [NOTICE] switch_core_state_machine.c:388 Hangup sofia/internal/1010@xxx.xxx.x.118 [CS_EXECUTE] [NORMAL_CLEARING]
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:13.187281 [DEBUG] switch_core_state_machine.c:651 (sofia/internal/1010@xxx.xxx.x.118) State EXECUTE going to sleep
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:13.187281 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/1010@xxx.xxx.x.118) Running State Change CS_HANGUP (Cur 1 Tot 1)
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:13.187281 [DEBUG] switch_core_state_machine.c:848 (sofia/internal/1010@xxx.xxx.x.118) Callstate Change RINGING -> HANGUP
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:13.187281 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/1010@xxx.xxx.x.118) State HANGUP
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:13.187281 [DEBUG] mod_sofia.c:453 Channel sofia/internal/1010@xxx.xxx.x.118 hanging up, cause: NORMAL_CLEARING
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:13.247345 [DEBUG] mod_sofia.c:598 Responding to INVITE with: 480
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:13.267334 [DEBUG] switch_core_state_machine.c:60 sofia/internal/1010@xxx.xxx.x.118 Standard HANGUP, cause: NORMAL_CLEARING
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:13.267334 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/1010@xxx.xxx.x.118) State HANGUP going to sleep
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:13.267334 [DEBUG] switch_core_state_machine.c:620 (sofia/internal/1010@xxx.xxx.x.118) State Change CS_HANGUP -> CS_REPORTING
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:13.267334 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/1010@xxx.xxx.x.118) Running State Change CS_REPORTING (Cur 1 Tot 1)
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:13.267334 [DEBUG] switch_core_state_machine.c:936 (sofia/internal/1010@xxx.xxx.x.118) State REPORTING
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:13.867284 [DEBUG] switch_core_state_machine.c:174 sofia/internal/1010@xxx.xxx.x.118 Standard REPORTING, cause: NORMAL_CLEARING
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:13.867284 [DEBUG] switch_core_state_machine.c:936 (sofia/internal/1010@xxx.xxx.x.118) State REPORTING going to sleep
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:13.867284 [DEBUG] switch_core_state_machine.c:611 (sofia/internal/1010@xxx.xxx.x.118) State Change CS_REPORTING -> CS_DESTROY
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:13.867284 [DEBUG] switch_core_session.c:1726 Session 1 (sofia/internal/1010@xxx.xxx.x.118) Locked, Waiting on external entities
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:13.867284 [NOTICE] switch_core_session.c:1744 Session 1 (sofia/internal/1010@xxx.xxx.x.118) Ended
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:13.867284 [NOTICE] switch_core_session.c:1748 Close Channel sofia/internal/1010@xxx.xxx.x.118 [CS_DESTROY]
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:13.867284 [DEBUG] switch_core_state_machine.c:739 (sofia/internal/1010@xxx.xxx.x.118) Running State Change CS_DESTROY (Cur 0 Tot 1)
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:13.867284 [DEBUG] switch_core_state_machine.c:749 (sofia/internal/1010@xxx.xxx.x.118) State DESTROY
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:13.867284 [DEBUG] mod_sofia.c:364 sofia/internal/1010@xxx.xxx.x.118 SOFIA DESTROY
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:13.867284 [DEBUG] switch_core_state_machine.c:181 sofia/internal/1010@xxx.xxx.x.118 Standard DESTROY
e08e2acb-b4d6-44f7-9516-fc3d9ed73fa9 2020-09-17 15:21:13.867284 [DEBUG] switch_core_state_machine.c:749 (sofia/internal/1010@xxx.xxx.x.118) State DESTROY going to sleep
2020-09-17 15:25:49.727281 [WARNING] switch_scheduler.c:117 Task was executed late by 2 seconds 1 heartbeat (core)
2020-09-17 15:25:49.747259 [WARNING] switch_scheduler.c:117 Task was executed late by 2 seconds 2 check_ip (core)
2020-09-17 15:30:07.707281 [WARNING] sofia_reg.c:1794 SIP auth challenge (REGISTER) on sofia profile 'internal' for [1011@xxx.xxx.x.118] from ip xxx.xxx.x.165
2020-09-17 15:30:57.547337 [WARNING] sofia_reg.c:1794 SIP auth challenge (REGISTER) on sofia profile 'internal' for [1010@xxx.xxx.x.118] from ip xxx.xxx.x.122
2020-09-17 15:34:42.507227 [WARNING] switch_core_db.c:92 SQLite is BUSY, sane=299 [select call_id,sip_user,sip_host,contact,status,rpid,expires,user_agent,server_user,server_host,profile_name from sip_registrations where force_ping=1 and hostname='debian' and profile_name='internal' and orig_hostname='debian' and ping_expires > 0 and ping_expires <= 1600353282]

Thank you in advance

Bifur · Sep 18, 2020

Who is your sip provider? I do not see a DID in the logs that is being sent from your trunk provider. What do you have for your inbound destination for DID?

If you search for: 404 not found ${sip_network_ip}) you will see people with similar issues and it's related to how the provider is sending the number.

Disclaimer: I'm new to Fusion, much more experienced people here than me!

StefanIvanov · Sep 18, 2020

Bifur said:
Who is your sip provider? I do not see a DID in the logs that is being sent from your trunk provider. What do you have for your inbound destination for DID?

If you search for: 404 not found ${sip_network_ip}) you will see people with similar issues and it's related to how the provider is sending the number.

Disclaimer: I'm new to Fusion, much more experienced people here than me!

I read these topics, but it didn't help me with the problem. Currently testing without a provider but I don't think there should be a difference in performance

Bifur · Sep 18, 2020

I guess I don't understand. What are you dialing to make the inbound call? Are you calling from another extension or using a cell phone?

StefanIvanov · Sep 18, 2020

Bifur said:
I guess I don't understand. What are you dialing to make the inbound call? Are you calling from another extension or using a cell phone?

I try to make a call from one extension to another. I`m using sipjs to make the connection between clients and the server

Bifur · Sep 18, 2020

StefanIvanov said:
I try to make a call from one extension to another. I`m using sipjs to make the connection between clients and the server

I'm sorry this is over my head right now. Maybe someone else can chime in that knows more about that setup.

StefanIvanov · Sep 18, 2020

Нo problems. Thank you for the help though. Maybe I'll create a new topic because I didn't find one.

SOLVED Inbound Calling

Member

New Member

Member

Member

Member

Administrator

Member

Member

Administrator

Member

Member

Administrator

New Member

Member

New Member

Member

New Member

Member

New Member