Outbound route not working (no requests leaving PBX)

[todd.justice]

First FusionPBX install, was able to get inbound calls working, phones reged, etc. But for some reason I am fighting this outgoing call issue. I've got a test trunk setup with Voxtelesys. Trunks register, I have followed their documentation to the "T" and still no luck. I've been through almost all the threads on the forum that match the word "outbound" as well. Firewall in front of the FusionPBX shows no traffic when attempting to make a call, so I don't believe it's actually trying to match the dialplan in the outbound route.

Sanitized log below. Can someone let me know what the heck I'm missing?!?


6e32247f-8433-44ce-a21f-b0307beeb302 2024-12-10 12:03:42.371758 85.33% [NOTICE] switch_channel.c:1142 New Channel sofia/external/102@server.domain.tld:5080 [6e32247f-8433-44ce-a21f-b0307beeb302]
6e32247f-8433-44ce-a21f-b0307beeb302 2024-12-10 12:03:42.371758 85.33% [DEBUG] switch_core_state_machine.c:581 (sofia/external/102@server.domain.tld:5080) Running State Change CS_NEW (Cur 1 Tot 450)
6e32247f-8433-44ce-a21f-b0307beeb302 2024-12-10 12:03:42.371758 85.33% [INFO] sofia.c:10459 sofia/external/102@server.domain.tld:5080 receiving invite from 50.xxx.yyy.146:6708 version: 1.10.11 -release 64bit call-id: 17ef9f197d0d0353cd9e6adc57e9b8d6
2024-12-10 12:03:42.371758 85.33% [DEBUG] sofia.c:10553 verifying acl "providers" for ip/port 50.xxx.yyy.146:0.
2024-12-10 12:03:42.371758 85.33% [DEBUG] sofia.c:10582 IP 50.xxx.yyy.146 Approved by acl "providers[]". Access Granted.
6e32247f-8433-44ce-a21f-b0307beeb302 2024-12-10 12:03:42.371758 85.33% [DEBUG] sofia.c:7493 Channel sofia/external/102@server.domain.tld:5080 entering state [received][100]
6e32247f-8433-44ce-a21f-b0307beeb302 2024-12-10 12:03:42.371758 85.33% [DEBUG] sofia.c:7503 Remote SDP:
6e32247f-8433-44ce-a21f-b0307beeb302 v=0
6e32247f-8433-44ce-a21f-b0307beeb302 o=- 1733853823 1733853823 IN IP4 50.xxx.yyy.146
6e32247f-8433-44ce-a21f-b0307beeb302 s=Polycom IP Phone
6e32247f-8433-44ce-a21f-b0307beeb302 c=IN IP4 50.xxx.yyy.146
6e32247f-8433-44ce-a21f-b0307beeb302 t=0 0
6e32247f-8433-44ce-a21f-b0307beeb302 a=sendrecv
6e32247f-8433-44ce-a21f-b0307beeb302 m=audio 5066 RTP/AVP 9 102 0 8 18 127
6e32247f-8433-44ce-a21f-b0307beeb302 a=rtpmap:9 G722/8000
6e32247f-8433-44ce-a21f-b0307beeb302 a=rtpmap:102 G7221/16000
6e32247f-8433-44ce-a21f-b0307beeb302 a=fmtp:102 bitrate=32000
6e32247f-8433-44ce-a21f-b0307beeb302 a=rtpmap:0 PCMU/8000
6e32247f-8433-44ce-a21f-b0307beeb302 a=rtpmap:8 PCMA/8000
6e32247f-8433-44ce-a21f-b0307beeb302 a=rtpmap:18 G729/8000
6e32247f-8433-44ce-a21f-b0307beeb302 a=fmtp:18 annexb=no
6e32247f-8433-44ce-a21f-b0307beeb302 a=rtpmap:127 telephone-event/8000
6e32247f-8433-44ce-a21f-b0307beeb302
6e32247f-8433-44ce-a21f-b0307beeb302 2024-12-10 12:03:42.371758 85.33% [DEBUG] switch_core_media.c:5526 Audio Codec Compare [G722:9:8000:20:64000:1]/[G722:9:8000:20:64000:1]
6e32247f-8433-44ce-a21f-b0307beeb302 2024-12-10 12:03:42.371758 85.33% [DEBUG] switch_core_media.c:5588 Audio Codec Compare [G722:9:8000:20:64000:1] ++++ is saved as a match
6e32247f-8433-44ce-a21f-b0307beeb302 2024-12-10 12:03:42.371758 85.33% [DEBUG] switch_core_media.c:5526 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
6e32247f-8433-44ce-a21f-b0307beeb302 2024-12-10 12:03:42.371758 85.33% [DEBUG] switch_core_media.c:5526 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
6e32247f-8433-44ce-a21f-b0307beeb302 2024-12-10 12:03:42.371758 85.33% [DEBUG] switch_core_media.c:5526 Audio Codec Compare [G7221:102:16000:20:0:1]/[G722:9:8000:20:64000:1]
6e32247f-8433-44ce-a21f-b0307beeb302 2024-12-10 12:03:42.371758 85.33% [DEBUG] switch_core_media.c:5526 Audio Codec Compare [G7221:102:16000:20:0:1]/[PCMU:0:8000:20:64000:1]
6e32247f-8433-44ce-a21f-b0307beeb302 2024-12-10 12:03:42.371758 85.33% [DEBUG] switch_core_media.c:5526 Audio Codec Compare [G7221:102:16000:20:0:1]/[PCMA:8:8000:20:64000:1]
6e32247f-8433-44ce-a21f-b0307beeb302 2024-12-10 12:03:42.371758 85.33% [DEBUG] switch_core_media.c:5526 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1]
6e32247f-8433-44ce-a21f-b0307beeb302 2024-12-10 12:03:42.371758 85.33% [DEBUG] switch_core_media.c:5526 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
6e32247f-8433-44ce-a21f-b0307beeb302 2024-12-10 12:03:42.371758 85.33% [DEBUG] switch_core_media.c:5588 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
6e32247f-8433-44ce-a21f-b0307beeb302 2024-12-10 12:03:42.371758 85.33% [DEBUG] switch_core_media.c:5526 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
6e32247f-8433-44ce-a21f-b0307beeb302 2024-12-10 12:03:42.371758 85.33% [DEBUG] switch_core_media.c:5526 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1]
6e32247f-8433-44ce-a21f-b0307beeb302 2024-12-10 12:03:42.371758 85.33% [DEBUG] switch_core_media.c:5526 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
6e32247f-8433-44ce-a21f-b0307beeb302 2024-12-10 12:03:42.371758 85.33% [DEBUG] switch_core_media.c:5526 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
6e32247f-8433-44ce-a21f-b0307beeb302 2024-12-10 12:03:42.371758 85.33% [DEBUG] switch_core_media.c:5588 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
6e32247f-8433-44ce-a21f-b0307beeb302 2024-12-10 12:03:42.371758 85.33% [DEBUG] switch_core_media.c:5526 Audio Codec Compare [G729:18:8000:20:8000:1]/[G722:9:8000:20:64000:1]
6e32247f-8433-44ce-a21f-b0307beeb302 2024-12-10 12:03:42.371758 85.33% [DEBUG] switch_core_media.c:5526 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMU:0:8000:20:64000:1]
6e32247f-8433-44ce-a21f-b0307beeb302 2024-12-10 12:03:42.371758 85.33% [DEBUG] switch_core_media.c:5526 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMA:8:8000:20:64000:1]
6e32247f-8433-44ce-a21f-b0307beeb302 2024-12-10 12:03:42.371758 85.33% [DEBUG] switch_core_media.c:5438 Set telephone-event payload to 127@8000
6e32247f-8433-44ce-a21f-b0307beeb302 2024-12-10 12:03:42.371758 85.33% [DEBUG] switch_core_media.c:3731 Set Codec sofia/external/102@server.domain.tld:5080 G722/8000 20 ms 160 samples 64000 bits 1 channels
6e32247f-8433-44ce-a21f-b0307beeb302 2024-12-10 12:03:42.371758 85.33% [DEBUG] switch_core_codec.c:111 sofia/external/102@server.domain.tld:5080 Original read codec set to G722:9
6e32247f-8433-44ce-a21f-b0307beeb302 2024-12-10 12:03:42.371758 85.33% [DEBUG] switch_core_media.c:5798 Set telephone-event payload to 127@8000
6e32247f-8433-44ce-a21f-b0307beeb302 2024-12-10 12:03:42.371758 85.33% [DEBUG] switch_core_media.c:5856 sofia/external/102@server.domain.tld:5080 Set 2833 dtmf send payload to 127 recv payload to 127
6e32247f-8433-44ce-a21f-b0307beeb302 2024-12-10 12:03:42.371758 85.33% [DEBUG] sofia.c:7927 (sofia/external/102@server.domain.tld:5080) State Change CS_NEW -> CS_INIT
6e32247f-8433-44ce-a21f-b0307beeb302 2024-12-10 12:03:42.371758 85.33% [DEBUG] switch_core_state_machine.c:600 (sofia/external/102@server.domain.tld:5080) State NEW
6e32247f-8433-44ce-a21f-b0307beeb302 2024-12-10 12:03:42.371758 85.33% [DEBUG] switch_core_state_machine.c:581 (sofia/external/102@server.domain.tld:5080) Running State Change CS_INIT (Cur 1 Tot 450)
6e32247f-8433-44ce-a21f-b0307beeb302 2024-12-10 12:03:42.371758 85.33% [DEBUG] switch_core_state_machine.c:624 (sofia/external/102@server.domain.tld:5080) State INIT
6e32247f-8433-44ce-a21f-b0307beeb302 2024-12-10 12:03:42.371758 85.33% [DEBUG] mod_sofia.c:97 sofia/external/102@server.domain.tld:5080 SOFIA INIT
6e32247f-8433-44ce-a21f-b0307beeb302 2024-12-10 12:03:42.371758 85.33% [DEBUG] switch_core_state_machine.c:40 sofia/external/102@server.domain.tld:5080 Standard INIT
6e32247f-8433-44ce-a21f-b0307beeb302 2024-12-10 12:03:42.371758 85.33% [DEBUG] switch_core_state_machine.c:48 (sofia/external/102@server.domain.tld:5080) State Change CS_INIT -> CS_ROUTING
6e32247f-8433-44ce-a21f-b0307beeb302 2024-12-10 12:03:42.371758 85.33% [DEBUG] switch_core_state_machine.c:624 (sofia/external/102@server.domain.tld:5080) State INIT going to sleep
6e32247f-8433-44ce-a21f-b0307beeb302 2024-12-10 12:03:42.371758 85.33% [DEBUG] switch_core_state_machine.c:581 (sofia/external/102@server.domain.tld:5080) Running State Change CS_ROUTING (Cur 1 Tot 450)
6e32247f-8433-44ce-a21f-b0307beeb302 2024-12-10 12:03:42.371758 85.33% [DEBUG] switch_channel.c:2399 (sofia/external/102@server.domain.tld:5080) Callstate Change DOWN -> RINGING
6e32247f-8433-44ce-a21f-b0307beeb302 2024-12-10 12:03:42.371758 85.33% [DEBUG] switch_core_state_machine.c:640 (sofia/external/102@server.domain.tld:5080) State ROUTING
6e32247f-8433-44ce-a21f-b0307beeb302 2024-12-10 12:03:42.371758 85.33% [DEBUG] mod_sofia.c:158 sofia/external/102@server.domain.tld:5080 SOFIA ROUTING
6e32247f-8433-44ce-a21f-b0307beeb302 2024-12-10 12:03:42.371758 85.33% [DEBUG] switch_core_state_machine.c:230 sofia/external/102@server.domain.tld:5080 Standard ROUTING
6e32247f-8433-44ce-a21f-b0307beeb302 2024-12-10 12:03:42.371758 85.33% [INFO] mod_dialplan_xml.c:639 Processing 102 <102>->41xx609899 in context public
2024-12-10 12:03:42.431760 85.33% [NOTICE] switch_cpp.cpp:1466 [xml_handler] multiple key:dialplanublic
6e32247f-8433-44ce-a21f-b0307beeb302 Dialplan: sofia/external/102@server.domain.tld:5080 parsing [public->caller-details] continue=true
6e32247f-8433-44ce-a21f-b0307beeb302 Dialplan: sofia/external/102@server.domain.tld:5080 Regex (PASS) [caller-details] () =~ // break=never
6e32247f-8433-44ce-a21f-b0307beeb302 Dialplan: sofia/external/102@server.domain.tld:5080 Action export(call_direction=inbound) INLINE
6e32247f-8433-44ce-a21f-b0307beeb302 EXECUTE [depth=0] sofia/external/102@server.domain.tld:5080 export(call_direction=inbound)
6e32247f-8433-44ce-a21f-b0307beeb302 2024-12-10 12:03:42.431760 85.33% [DEBUG] switch_channel.c:1334 EXPORT (export_vars) [call_direction]=[inbound]
6e32247f-8433-44ce-a21f-b0307beeb302 Dialplan: sofia/external/102@server.domain.tld:5080 Action set(caller_destination=${sip_to_user}) INLINE
6e32247f-8433-44ce-a21f-b0307beeb302 EXECUTE [depth=0] sofia/external/102@server.domain.tld:5080 set(caller_destination=41xx609899)
6e32247f-8433-44ce-a21f-b0307beeb302 2024-12-10 12:03:42.431760 85.33% [DEBUG] mod_dptools.c:1671 SET sofia/external/102@server.domain.tld:5080 [caller_destination]=[41xx609899]
6e32247f-8433-44ce-a21f-b0307beeb302 Dialplan: sofia/external/102@server.domain.tld:5080 Action set(caller_id_name=${caller_id_name}) INLINE
6e32247f-8433-44ce-a21f-b0307beeb302 EXECUTE [depth=0] sofia/external/102@server.domain.tld:5080 set(caller_id_name=102)
6e32247f-8433-44ce-a21f-b0307beeb302 2024-12-10 12:03:42.431760 85.33% [DEBUG] mod_dptools.c:1671 SET sofia/external/102@server.domain.tld:5080 [caller_id_name]=[102]
6e32247f-8433-44ce-a21f-b0307beeb302 Dialplan: sofia/external/102@server.domain.tld:5080 Action set(caller_id_number=${caller_id_number})
6e32247f-8433-44ce-a21f-b0307beeb302 Dialplan: sofia/external/102@server.domain.tld:5080 parsing [public->4108966599] continue=false
6e32247f-8433-44ce-a21f-b0307beeb302 Dialplan: sofia/external/102@server.domain.tld:5080 Regex (FAIL) [4108966599] destination_number(41xx609899) =~ /^(4108966599)$/ break=on-false
6e32247f-8433-44ce-a21f-b0307beeb302 Dialplan: sofia/external/102@server.domain.tld:5080 parsing [public->not-found] continue=false
6e32247f-8433-44ce-a21f-b0307beeb302 Dialplan: sofia/external/102@server.domain.tld:5080 Regex (PASS) [not-found] () =~ // break=on-false
6e32247f-8433-44ce-a21f-b0307beeb302 Dialplan: sofia/external/102@server.domain.tld:5080 Action export(call_direction=inbound) INLINE
6e32247f-8433-44ce-a21f-b0307beeb302 EXECUTE [depth=0] sofia/external/102@server.domain.tld:5080 export(call_direction=inbound)
6e32247f-8433-44ce-a21f-b0307beeb302 2024-12-10 12:03:42.431760 85.33% [DEBUG] switch_channel.c:1334 EXPORT (export_vars) [call_direction]=[inbound]
6e32247f-8433-44ce-a21f-b0307beeb302 Dialplan: sofia/external/102@server.domain.tld:5080 Action set(call_direction=inbound) INLINE
6e32247f-8433-44ce-a21f-b0307beeb302 EXECUTE [depth=0] sofia/external/102@server.domain.tld:5080 set(call_direction=inbound)
6e32247f-8433-44ce-a21f-b0307beeb302 2024-12-10 12:03:42.431760 85.33% [DEBUG] mod_dptools.c:1671 SET sofia/external/102@server.domain.tld:5080 [call_direction]=[inbound]
6e32247f-8433-44ce-a21f-b0307beeb302 Dialplan: sofia/external/102@server.domain.tld:5080 Action log(WARNING [inbound routes] 404 not found ${sip_network_ip} destination_number ${destination_number} sip_to_user ${sip_to_user} sip_req_user ${sip_req_user})
6e32247f-8433-44ce-a21f-b0307beeb302 Dialplan: sofia/external/102@server.domain.tld:5080 Action respond(404 Not Found)
6e32247f-8433-44ce-a21f-b0307beeb302 2024-12-10 12:03:42.431760 85.33% [DEBUG] switch_core_state_machine.c:281 (sofia/external/102@server.domain.tld:5080) State Change CS_ROUTING -> CS_EXECUTE
6e32247f-8433-44ce-a21f-b0307beeb302 2024-12-10 12:03:42.431760 85.33% [DEBUG] switch_core_state_machine.c:640 (sofia/external/102@server.domain.tld:5080) State ROUTING going to sleep
6e32247f-8433-44ce-a21f-b0307beeb302 2024-12-10 12:03:42.431760 85.33% [DEBUG] switch_core_state_machine.c:581 (sofia/external/102@server.domain.tld:5080) Running State Change CS_EXECUTE (Cur 1 Tot 450)
6e32247f-8433-44ce-a21f-b0307beeb302 2024-12-10 12:03:42.431760 85.33% [DEBUG] switch_core_state_machine.c:647 (sofia/external/102@server.domain.tld:5080) State EXECUTE
6e32247f-8433-44ce-a21f-b0307beeb302 2024-12-10 12:03:42.431760 85.33% [DEBUG] mod_sofia.c:213 sofia/external/102@server.domain.tld:5080 SOFIA EXECUTE
6e32247f-8433-44ce-a21f-b0307beeb302 2024-12-10 12:03:42.431760 85.33% [DEBUG] switch_core_state_machine.c:323 sofia/external/102@server.domain.tld:5080 Standard EXECUTE
6e32247f-8433-44ce-a21f-b0307beeb302 EXECUTE [depth=0] sofia/external/102@server.domain.tld:5080 set(caller_id_number=102)
6e32247f-8433-44ce-a21f-b0307beeb302 2024-12-10 12:03:42.431760 85.33% [DEBUG] mod_dptools.c:1671 SET sofia/external/102@server.domain.tld:5080 [caller_id_number]=[102]
6e32247f-8433-44ce-a21f-b0307beeb302 EXECUTE [depth=0] sofia/external/102@server.domain.tld:5080 log(WARNING [inbound routes] 404 not found 50.xxx.yyy.146 destination_number 41xx609899 sip_to_user 41xx609899 sip_req_user 41xx609899)
6e32247f-8433-44ce-a21f-b0307beeb302 2024-12-10 12:03:42.431760 85.33% [WARNING] mod_dptools.c:1865 [inbound routes] 404 not found 50.xxx.yyy.146 destination_number 41xx609899 sip_to_user 41xx609899 sip_req_user 41xx609899
6e32247f-8433-44ce-a21f-b0307beeb302 EXECUTE [depth=0] sofia/external/102@server.domain.tld:5080 respond(404 Not Found)
6e32247f-8433-44ce-a21f-b0307beeb302 2024-12-10 12:03:42.431760 85.33% [DEBUG] mod_sofia.c:2350 Responding with 404 [Not Found]
6e32247f-8433-44ce-a21f-b0307beeb302 2024-12-10 12:03:42.431760 85.33% [NOTICE] mod_sofia.c:2416 Hangup sofia/external/102@server.domain.tld:5080 [CS_EXECUTE] [UNALLOCATED_NUMBER]
6e32247f-8433-44ce-a21f-b0307beeb302 2024-12-10 12:03:42.431760 85.33% [DEBUG] switch_core_session.c:2979 sofia/external/102@server.domain.tld:5080 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
6e32247f-8433-44ce-a21f-b0307beeb302 2024-12-10 12:03:42.431760 85.33% [DEBUG] switch_core_state_machine.c:647 (sofia/external/102@server.domain.tld:5080) State EXECUTE going to sleep
6e32247f-8433-44ce-a21f-b0307beeb302 2024-12-10 12:03:42.431760 85.33% [DEBUG] switch_core_state_machine.c:581 (sofia/external/102@server.domain.tld:5080) Running State Change CS_HANGUP (Cur 1 Tot 450)
6e32247f-8433-44ce-a21f-b0307beeb302 2024-12-10 12:03:42.431760 85.33% [DEBUG] switch_core_state_machine.c:844 (sofia/external/102@server.domain.tld:5080) Callstate Change RINGING -> HANGUP
6e32247f-8433-44ce-a21f-b0307beeb302 2024-12-10 12:03:42.431760 85.33% [DEBUG] switch_core_state_machine.c:846 (sofia/external/102@server.domain.tld:5080) State HANGUP
6e32247f-8433-44ce-a21f-b0307beeb302 2024-12-10 12:03:42.431760 85.33% [DEBUG] mod_sofia.c:469 Channel sofia/external/102@server.domain.tld:5080 hanging up, cause: UNALLOCATED_NUMBER
6e32247f-8433-44ce-a21f-b0307beeb302 2024-12-10 12:03:42.431760 85.33% [DEBUG] mod_sofia.c:614 Responding to INVITE with: 404
6e32247f-8433-44ce-a21f-b0307beeb302 2024-12-10 12:03:42.431760 85.33% [DEBUG] switch_core_state_machine.c:59 sofia/external/102@server.domain.tld:5080 Standard HANGUP, cause: UNALLOCATED_NUMBER
6e32247f-8433-44ce-a21f-b0307beeb302 2024-12-10 12:03:42.431760 85.33% [DEBUG] switch_core_state_machine.c:846 (sofia/external/102@server.domain.tld:5080) State HANGUP going to sleep
6e32247f-8433-44ce-a21f-b0307beeb302 2024-12-10 12:03:42.431760 85.33% [DEBUG] switch_core_state_machine.c:616 (sofia/external/102@server.domain.tld:5080) State Change CS_HANGUP -> CS_REPORTING
6e32247f-8433-44ce-a21f-b0307beeb302 2024-12-10 12:03:42.431760 85.33% [DEBUG] switch_core_state_machine.c:581 (sofia/external/102@server.domain.tld:5080) Running State Change CS_REPORTING (Cur 1 Tot 450)
6e32247f-8433-44ce-a21f-b0307beeb302 2024-12-10 12:03:42.431760 85.33% [DEBUG] switch_core_state_machine.c:932 (sofia/external/102@server.domain.tld:5080) State REPORTING
6e32247f-8433-44ce-a21f-b0307beeb302 2024-12-10 12:03:42.431760 85.33% [DEBUG] switch_core_state_machine.c:168 sofia/external/102@server.domain.tld:5080 Standard REPORTING, cause: UNALLOCATED_NUMBER
6e32247f-8433-44ce-a21f-b0307beeb302 2024-12-10 12:03:42.431760 85.33% [DEBUG] switch_core_state_machine.c:932 (sofia/external/102@server.domain.tld:5080) State REPORTING going to sleep
6e32247f-8433-44ce-a21f-b0307beeb302 2024-12-10 12:03:42.431760 85.33% [DEBUG] switch_core_state_machine.c:607 (sofia/external/102@server.domain.tld:5080) State Change CS_REPORTING -> CS_DESTROY
6e32247f-8433-44ce-a21f-b0307beeb302 2024-12-10 12:03:42.431760 85.33% [DEBUG] switch_core_session.c:1744 Session 450 (sofia/external/102@server.domain.tld:5080) Locked, Waiting on external entities
6e32247f-8433-44ce-a21f-b0307beeb302 2024-12-10 12:03:42.431760 85.33% [NOTICE] switch_core_session.c:1762 Session 450 (sofia/external/102@server.domain.tld:5080) Ended
6e32247f-8433-44ce-a21f-b0307beeb302 2024-12-10 12:03:42.431760 85.33% [NOTICE] switch_core_session.c:1766 Close Channel sofia/external/102@server.domain.tld:5080 [CS_DESTROY]
6e32247f-8433-44ce-a21f-b0307beeb302 2024-12-10 12:03:42.431760 85.33% [DEBUG] switch_core_state_machine.c:735 (sofia/external/102@server.domain.tld:5080) Running State Change CS_DESTROY (Cur 0 Tot 450)
6e32247f-8433-44ce-a21f-b0307beeb302 2024-12-10 12:03:42.431760 85.33% [DEBUG] switch_core_state_machine.c:745 (sofia/external/102@server.domain.tld:5080) State DESTROY
6e32247f-8433-44ce-a21f-b0307beeb302 2024-12-10 12:03:42.431760 85.33% [DEBUG] mod_sofia.c:380 sofia/external/102@server.domain.tld:5080 SOFIA DESTROY
6e32247f-8433-44ce-a21f-b0307beeb302 2024-12-10 12:03:42.531756 85.33% [DEBUG] switch_core_state_machine.c:175 sofia/external/102@server.domain.tld:5080 Standard DESTROY
6e32247f-8433-44ce-a21f-b0307beeb302 2024-12-10 12:03:42.531756 85.33% [DEBUG] switch_core_state_machine.c:745 (sofia/external/102@server.domain.tld:5080) State DESTROY going to sleep

 

[todd.justice]

*Update - I have tried 3 different SIP Trunk providers, and am running into the same issue. None of the providers see the request coming from Fusion. I obviously have something misconfigured. I believe it's in the dialplan but could be wrong.

 

[Jonathan Black]

It looks like maybe you have your phones registering on the "external" SIP profile instead of the "internal" one? All phones should be registering on internal profile (usually port 5060). It looks like it's treating the call as inbound, which explains why it fails (you don't have a destination that matches that number) and also why you don't see an attempt to contact your carrier. Check Status->Registrations and on the far right it shows the profile your phone is registering to.

 

[markjcrane]

Looking at the log it says

2024-12-10 12:03:42.371758 85.33% [DEBUG] sofia.c:10553 verifying acl "providers" for ip/port 50.xxx.yyy.146:0.
2024-12-10 12:03:42.371758 85.33% [DEBUG] sofia.c:10582 IP 50.xxx.yyy.146 Approved by acl "providers[]". Access Granted.

So it looks like you put your phone external IP address in the providers access control list. This is a common mistake. I changed the name to make it more obvious not to do that. The providers access control list is only for your VoIP provider / carrier IP addresses. It is not for your Phone or local network IP addresses. What happens is that adddresses that match the providers access control list are put into the public context. That is good for calls from your Carrier but it's very bad for calls from your endpoint phones.

To fix it make sure only VoIP providers are in the access control list. Below is the link to the documentation for access controls. Its a good idea to read the bullet points. Which is a list of important tips.
- https://docs.fusionpbx.com/en/latest/advanced/access_controls.html