Outbound Calls 403 Forbidden

vgarcia · Aug 6, 2021

My inbound calls work fine, but when I try to dial outbound to an external number, I get the 403 Forbidden Error.

Can someone please help me figure this out? I'm a newbie to FusionPBX, as I've switched from FreePBX.

Logs Below:

2e535b4b-3e95-498d-828a-d06ccfc629bd 2021-08-06 16:37:53.071060 [DEBUG] switch_core_state_machine.c:749 (sofia/internal/500@45.32.192.XXX) State DESTROY going to sleep
2e535b4b-3e95-498d-828a-d06ccfc629bd 2021-08-06 16:37:53.071060 [DEBUG] switch_core_state_machine.c:181 sofia/internal/500@45.32.192.XXX Standard DESTROY
2e535b4b-3e95-498d-828a-d06ccfc629bd 2021-08-06 16:37:53.071060 [DEBUG] mod_sofia.c:364 sofia/internal/500@45.32.192.XXX SOFIA DESTROY
2e535b4b-3e95-498d-828a-d06ccfc629bd 2021-08-06 16:37:53.071060 [DEBUG] switch_core_state_machine.c:749 (sofia/internal/500@45.32.192.XXX) State DESTROY
2e535b4b-3e95-498d-828a-d06ccfc629bd 2021-08-06 16:37:53.071060 [DEBUG] switch_core_state_machine.c:739 (sofia/internal/500@45.32.192.XXX) Running State Change CS_DESTROY (Cur 0 Tot 43)
2e535b4b-3e95-498d-828a-d06ccfc629bd 2021-08-06 16:37:53.071060 [NOTICE] switch_core_session.c:1758 Close Channel sofia/internal/500@45.32.192.XXX [CS_DESTROY]
2e535b4b-3e95-498d-828a-d06ccfc629bd 2021-08-06 16:37:53.071060 [NOTICE] switch_core_session.c:1754 Session 42 (sofia/internal/500@45.32.192.XXX) Ended
2e535b4b-3e95-498d-828a-d06ccfc629bd 2021-08-06 16:37:53.071060 [DEBUG] switch_core_session.c:1736 Session 42 (sofia/internal/500@45.32.192.XXX) Locked, Waiting on external entities
2e535b4b-3e95-498d-828a-d06ccfc629bd 2021-08-06 16:37:53.071060 [DEBUG] switch_core_state_machine.c:611 (sofia/internal/500@45.32.192.XXX) State Change CS_REPORTING -> CS_DESTROY
2e535b4b-3e95-498d-828a-d06ccfc629bd 2021-08-06 16:37:53.071060 [DEBUG] switch_core_state_machine.c:936 (sofia/internal/500@45.32.192.XXX) State REPORTING going to sleep
2e535b4b-3e95-498d-828a-d06ccfc629bd 2021-08-06 16:37:53.071060 [DEBUG] switch_core_state_machine.c:174 sofia/internal/500@45.32.192.XXX Standard REPORTING, cause: NORMAL_CLEARING
4a2c06c0-1026-4edb-826a-868371b105c1 2021-08-06 16:37:52.971048 [DEBUG] switch_core_state_machine.c:749 (sofia/external/XXXXXXXXXX) State DESTROY going to sleep
4a2c06c0-1026-4edb-826a-868371b105c1 2021-08-06 16:37:52.971048 [DEBUG] switch_core_state_machine.c:181 sofia/external/XXXXXXXXXX Standard DESTROY
4a2c06c0-1026-4edb-826a-868371b105c1 2021-08-06 16:37:52.971048 [DEBUG] mod_sofia.c:364 sofia/external/XXXXXXXXXX SOFIA DESTROY
4a2c06c0-1026-4edb-826a-868371b105c1 2021-08-06 16:37:52.971048 [DEBUG] switch_core_state_machine.c:749 (sofia/external/XXXXXXXXXX) State DESTROY
4a2c06c0-1026-4edb-826a-868371b105c1 2021-08-06 16:37:52.971048 [DEBUG] switch_core_state_machine.c:739 (sofia/external/XXXXXXXXXX) Running State Change CS_DESTROY (Cur 1 Tot 43)
4a2c06c0-1026-4edb-826a-868371b105c1 2021-08-06 16:37:52.971048 [NOTICE] switch_core_session.c:1758 Close Channel sofia/external/XXXXXXXXXX [CS_DESTROY]
4a2c06c0-1026-4edb-826a-868371b105c1 2021-08-06 16:37:52.971048 [NOTICE] switch_core_session.c:1754 Session 43 (sofia/external/XXXXXXXXXX) Ended
2e535b4b-3e95-498d-828a-d06ccfc629bd 2021-08-06 16:37:52.971048 [DEBUG] switch_core_state_machine.c:936 (sofia/internal/500@45.32.192.XXX) State REPORTING
2e535b4b-3e95-498d-828a-d06ccfc629bd 2021-08-06 16:37:52.971048 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/500@45.32.192.XXX) Running State Change CS_REPORTING (Cur 2 Tot 43)
2e535b4b-3e95-498d-828a-d06ccfc629bd 2021-08-06 16:37:52.971048 [DEBUG] switch_core_state_machine.c:620 (sofia/internal/500@45.32.192.XXX) State Change CS_HANGUP -> CS_REPORTING
2e535b4b-3e95-498d-828a-d06ccfc629bd 2021-08-06 16:37:52.971048 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/500@45.32.192.XXX) State HANGUP going to sleep
2e535b4b-3e95-498d-828a-d06ccfc629bd 2021-08-06 16:37:52.971048 [DEBUG] switch_core_state_machine.c:60 sofia/internal/500@45.32.192.XXX Standard HANGUP, cause: NORMAL_CLEARING
2e535b4b-3e95-498d-828a-d06ccfc629bd 2021-08-06 16:37:52.971048 [DEBUG] mod_sofia.c:598 Responding to INVITE with: 403
2e535b4b-3e95-498d-828a-d06ccfc629bd 2021-08-06 16:37:52.971048 [DEBUG] mod_sofia.c:453 Channel sofia/internal/500@45.32.192.XXX hanging up, cause: NORMAL_CLEARING
2e535b4b-3e95-498d-828a-d06ccfc629bd 2021-08-06 16:37:52.971048 [DEBUG] mod_sofia.c:447 sofia/internal/500@45.32.192.XXX Overriding SIP cause 480 with 403 from the other leg
2e535b4b-3e95-498d-828a-d06ccfc629bd 2021-08-06 16:37:52.971048 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/500@45.32.192.XXX) State HANGUP
2e535b4b-3e95-498d-828a-d06ccfc629bd 2021-08-06 16:37:52.971048 [DEBUG] switch_core_state_machine.c:848 (sofia/internal/500@45.32.192.XXX) Callstate Change RINGING -> HANGUP
2e535b4b-3e95-498d-828a-d06ccfc629bd 2021-08-06 16:37:52.971048 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/500@45.32.192.XXX) Running State Change CS_HANGUP (Cur 2 Tot 43)
2e535b4b-3e95-498d-828a-d06ccfc629bd 2021-08-06 16:37:52.971048 [DEBUG] switch_core_state_machine.c:651 (sofia/internal/500@45.32.192.XXX) State EXECUTE going to sleep
2e535b4b-3e95-498d-828a-d06ccfc629bd 2021-08-06 16:37:52.971048 [DEBUG] switch_core_session.c:2914 sofia/internal/500@45.32.192.XXX skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
2e535b4b-3e95-498d-828a-d06ccfc629bd 2021-08-06 16:37:52.971048 [NOTICE] switch_channel.c:4942 Hangup sofia/internal/500@45.32.192.XXX [CS_EXECUTE] [NORMAL_CLEARING]
2e535b4b-3e95-498d-828a-d06ccfc629bd 2021-08-06 16:37:52.971048 [INFO] mod_dptools.c:3643 Originate Failed. Cause: NORMAL_CLEARING
2e535b4b-3e95-498d-828a-d06ccfc629bd 2021-08-06 16:37:52.971048 [DEBUG] switch_ivr_originate.c:4026 Originate Resulted in Error Cause: 16 [NORMAL_CLEARING]
4a2c06c0-1026-4edb-826a-868371b105c1 2021-08-06 16:37:52.951092 [DEBUG] switch_core_session.c:1736 Session 43 (sofia/external/XXXXXXXXXX) Locked, Waiting on external entities
4a2c06c0-1026-4edb-826a-868371b105c1 2021-08-06 16:37:52.951092 [DEBUG] switch_core_state_machine.c:611 (sofia/external/XXXXXXXXXX) State Change CS_REPORTING -> CS_DESTROY
4a2c06c0-1026-4edb-826a-868371b105c1 2021-08-06 16:37:52.951092 [DEBUG] switch_core_state_machine.c:936 (sofia/external/XXXXXXXXXX) State REPORTING going to sleep
4a2c06c0-1026-4edb-826a-868371b105c1 2021-08-06 16:37:52.951092 [DEBUG] switch_core_state_machine.c:174 sofia/external/XXXXXXXXXX Standard REPORTING, cause: NORMAL_CLEARING
4a2c06c0-1026-4edb-826a-868371b105c1 2021-08-06 16:37:52.951092 [DEBUG] switch_core_state_machine.c:936 (sofia/external/XXXXXXXXXX) State REPORTING
4a2c06c0-1026-4edb-826a-868371b105c1 2021-08-06 16:37:52.951092 [DEBUG] switch_core_state_machine.c:585 (sofia/external/XXXXXXXXXX) Running State Change CS_REPORTING (Cur 2 Tot 43)
4a2c06c0-1026-4edb-826a-868371b105c1 2021-08-06 16:37:52.951092 [DEBUG] switch_core_state_machine.c:620 (sofia/external/XXXXXXXXXX) State Change CS_HANGUP -> CS_REPORTING
4a2c06c0-1026-4edb-826a-868371b105c1 2021-08-06 16:37:52.951092 [DEBUG] switch_core_state_machine.c:850 (sofia/external/XXXXXXXXXX) State HANGUP going to sleep
4a2c06c0-1026-4edb-826a-868371b105c1 2021-08-06 16:37:52.951092 [DEBUG] switch_core_state_machine.c:60 sofia/external/XXXXXXXXXX Standard HANGUP, cause: NORMAL_CLEARING
4a2c06c0-1026-4edb-826a-868371b105c1 2021-08-06 16:37:52.951092 [DEBUG] mod_sofia.c:453 Channel sofia/external/XXXXXXXXXX hanging up, cause: NORMAL_CLEARING
4a2c06c0-1026-4edb-826a-868371b105c1 2021-08-06 16:37:52.951092 [DEBUG] switch_core_state_machine.c:850 (sofia/external/XXXXXXXXXX) State HANGUP
4a2c06c0-1026-4edb-826a-868371b105c1 2021-08-06 16:37:52.951092 [DEBUG] switch_core_state_machine.c:848 (sofia/external/XXXXXXXXXX) Callstate Change DOWN -> HANGUP
4a2c06c0-1026-4edb-826a-868371b105c1 2021-08-06 16:37:52.951092 [DEBUG] switch_core_state_machine.c:585 (sofia/external/XXXXXXXXXX) Running State Change CS_HANGUP (Cur 2 Tot 43)
4a2c06c0-1026-4edb-826a-868371b105c1 2021-08-06 16:37:52.951092 [NOTICE] sofia.c:8641 Hangup sofia/external/XXXXXXXXXX [CS_CONSUME_MEDIA] [NORMAL_CLEARING]
4a2c06c0-1026-4edb-826a-868371b105c1 2021-08-06 16:37:52.951092 [DEBUG] sofia.c:7406 Channel sofia/external/XXXXXXXXXX entering state [terminated][403]
4a2c06c0-1026-4edb-826a-868371b105c1 2021-08-06 16:37:52.951092 [DEBUG] sofia.c:6576 Remote Reason: 16
4a2c06c0-1026-4edb-826a-868371b105c1 2021-08-06 16:37:52.711054 [DEBUG] sofia.c:7406 Channel sofia/external/XXXXXXXXXX entering state [calling][0]
4a2c06c0-1026-4edb-826a-868371b105c1 2021-08-06 16:37:52.531316 [DEBUG] switch_core_state_machine.c:663 (sofia/external/XXXXXXXXXX) State CONSUME_MEDIA going to sleep
4a2c06c0-1026-4edb-826a-868371b105c1 2021-08-06 16:37:52.531316 [DEBUG] switch_core_state_machine.c:663 (sofia/external/XXXXXXXXXX) State CONSUME_MEDIA
4a2c06c0-1026-4edb-826a-868371b105c1 2021-08-06 16:37:52.531316 [DEBUG] switch_core_state_machine.c:585 (sofia/external/XXXXXXXXXX) Running State Change CS_CONSUME_MEDIA (Cur 2 Tot 43)
4a2c06c0-1026-4edb-826a-868371b105c1 2021-08-06 16:37:52.531316 [DEBUG] switch_core_state_machine.c:644 (sofia/external/XXXXXXXXXX) State ROUTING going to sleep
4a2c06c0-1026-4edb-826a-868371b105c1 2021-08-06 16:37:52.531316 [DEBUG] switch_ivr_originate.c:67 (sofia/external/XXXXXXXXXX) State Change CS_ROUTING -> CS_CONSUME_MEDIA
4a2c06c0-1026-4edb-826a-868371b105c1 2021-08-06 16:37:52.531316 [DEBUG] mod_sofia.c:154 sofia/external/XXXXXXXXXX SOFIA ROUTING
4a2c06c0-1026-4edb-826a-868371b105c1 2021-08-06 16:37:52.531316 [DEBUG] switch_core_state_machine.c:644 (sofia/external/XXXXXXXXXX) State ROUTING
4a2c06c0-1026-4edb-826a-868371b105c1 2021-08-06 16:37:52.531316 [DEBUG] sofia.c:7406 Channel sofia/external/XXXXXXXXXX entering state [calling][0]
4a2c06c0-1026-4edb-826a-868371b105c1 2021-08-06 16:37:52.531316 [DEBUG] switch_core_state_machine.c:585 (sofia/external/XXXXXXXXXX) Running State Change CS_ROUTING (Cur 2 Tot 43)
4a2c06c0-1026-4edb-826a-868371b105c1 2021-08-06 16:37:52.531316 [DEBUG] switch_core_state_machine.c:628 (sofia/external/XXXXXXXXXX) State INIT going to sleep
4a2c06c0-1026-4edb-826a-868371b105c1 2021-08-06 16:37:52.531316 [DEBUG] switch_core_state_machine.c:48 (sofia/external/XXXXXXXXXX) State Change CS_INIT -> CS_ROUTING
4a2c06c0-1026-4edb-826a-868371b105c1 2021-08-06 16:37:52.531316 [DEBUG] switch_core_state_machine.c:40 sofia/external/XXXXXXXXXX Standard INIT
4a2c06c0-1026-4edb-826a-868371b105c1
4a2c06c0-1026-4edb-826a-868371b105c1 a=sendrecv
4a2c06c0-1026-4edb-826a-868371b105c1 a=ptime:20
4a2c06c0-1026-4edb-826a-868371b105c1 a=silenceSuppff - - - -
4a2c06c0-1026-4edb-826a-868371b105c1 a=fmtp:101 0-16
4a2c06c0-1026-4edb-826a-868371b105c1 a=rtpmap:101 telephone-event/8000
4a2c06c0-1026-4edb-826a-868371b105c1 a=rtpmap:0 PCMU/8000
4a2c06c0-1026-4edb-826a-868371b105c1 a=rtpmap:8 PCMA/8000
4a2c06c0-1026-4edb-826a-868371b105c1 m=audio 26690 RTP/AVP 8 0 101
4a2c06c0-1026-4edb-826a-868371b105c1 t=0 0
4a2c06c0-1026-4edb-826a-868371b105c1 c=IN IP4 45.32.192.XXX
4a2c06c0-1026-4edb-826a-868371b105c1 s=FreeSWITCH
4a2c06c0-1026-4edb-826a-868371b105c1 o=FreeSWITCH 1628241182 1628241183 IN IP4 45.32.192.XXX
4a2c06c0-1026-4edb-826a-868371b105c1 v=0
4a2c06c0-1026-4edb-826a-868371b105c1 Local SDP:
4a2c06c0-1026-4edb-826a-868371b105c1 2021-08-06 16:37:52.511046 [DEBUG] sofia_glue.c:1624 sofia/external/XXXXXXXXXX sending invite version: 1.10.6 -release-18-1ff9d0a60e 64bit
4a2c06c0-1026-4edb-826a-868371b105c1 2021-08-06 16:37:52.511046 [INFO] sofia_glue.c:1621 sofia/external/XXXXXXXXXX sending invite call-id: (null)
4a2c06c0-1026-4edb-826a-868371b105c1 2021-08-06 16:37:52.511046 [DEBUG] mod_sofia.c:93 sofia/external/XXXXXXXXXX SOFIA INIT
4a2c06c0-1026-4edb-826a-868371b105c1 2021-08-06 16:37:52.511046 [DEBUG] switch_core_state_machine.c:628 (sofia/external/XXXXXXXXXX) State INIT
4a2c06c0-1026-4edb-826a-868371b105c1 2021-08-06 16:37:52.511046 [DEBUG] switch_core_state_machine.c:585 (sofia/external/XXXXXXXXXX) Running State Change CS_INIT (Cur 2 Tot 43)
4a2c06c0-1026-4edb-826a-868371b105c1 2021-08-06 16:37:52.511046 [DEBUG] mod_sofia.c:5102 (sofia/external/XXXXXXXXXX) State Change CS_NEW -> CS_INIT
4a2c06c0-1026-4edb-826a-868371b105c1 2021-08-06 16:37:52.511046 [NOTICE] switch_channel.c:1118 New Channel sofia/external/XXXXXXXXXX [4a2c06c0-1026-4edb-826a-868371b105c1]
2e535b4b-3e95-498d-828a-d06ccfc629bd 2021-08-06 16:37:52.511046 [DEBUG] switch_ivr_originate.c:2272 Parsing global variables
2e535b4b-3e95-498d-828a-d06ccfc629bd 2021-08-06 16:37:52.511046 [DEBUG] switch_channel.c:1264 sofia/internal/500@45.32.192.XXX EXPORTING[export_vars] [call_direction]=[outbound] to event
2e535b4b-3e95-498d-828a-d06ccfc629bd 2021-08-06 16:37:52.511046 [DEBUG] switch_channel.c:1264 sofia/internal/500@45.32.192.XXX EXPORTING[export_vars] [origination_callee_id_name]=[XXXXXXXXXX] to event
2e535b4b-3e95-498d-828a-d06ccfc629bd 2021-08-06 16:37:52.511046 [DEBUG] switch_channel.c:1264 sofia/internal/500@45.32.192.XXX EXPORTING[export_vars] [call_direction]=[outbound] to event
2e535b4b-3e95-498d-828a-d06ccfc629bd 2021-08-06 16:37:52.511046 [DEBUG] switch_channel.c:1264 sofia/internal/500@45.32.192.XXX EXPORTING[export_vars] [domain_name]=[45.32.192.XXX] to event
2e535b4b-3e95-498d-828a-d06ccfc629bd EXECUTE [depth=0] sofia/internal/500@45.32.192.XXX bridge(sofia/gateway/f443e0e2-cd58-47eb-b8e3-9221d3798875/XXXXXXXXXX)
2e535b4b-3e95-498d-828a-d06ccfc629bd 2021-08-06 16:37:52.511046 [DEBUG] mod_dptools.c:1685 SET sofia/internal/500@45.32.192.XXX [continue_on_fail]=[1,2,3,6,18,21,27,28,31,34,38,41,42,44,58,88,111,403,501,602,607]
2e535b4b-3e95-498d-828a-d06ccfc629bd EXECUTE [depth=0] sofia/internal/500@45.32.192.XXX set(continue_on_fail=1,2,3,6,18,21,27,28,31,34,38,41,42,44,58,88,111,403,501,602,607)
2e535b4b-3e95-498d-828a-d06ccfc629bd 2021-08-06 16:37:52.511046 [DEBUG] mod_dptools.c:1685 SET sofia/internal/500@45.32.192.XXX [callee_id_number]=[XXXXXXXXXX]
2e535b4b-3e95-498d-828a-d06ccfc629bd EXECUTE [depth=0] sofia/internal/500@45.32.192.XXX set(callee_id_number=XXXXXXXXXX)
2e535b4b-3e95-498d-828a-d06ccfc629bd 2021-08-06 16:37:52.511046 [DEBUG] mod_dptools.c:1685 SET sofia/internal/500@45.32.192.XXX [ignore_display_updates]=[true]
2e535b4b-3e95-498d-828a-d06ccfc629bd EXECUTE [depth=0] sofia/internal/500@45.32.192.XXX set(ignore_display_updates=true)
2e535b4b-3e95-498d-828a-d06ccfc629bd 2021-08-06 16:37:52.511046 [DEBUG] mod_dptools.c:1685 SET sofia/internal/500@45.32.192.XXX [inherit_codec]=[true]
2e535b4b-3e95-498d-828a-d06ccfc629bd EXECUTE [depth=0] sofia/internal/500@45.32.192.XXX set(inherit_codec=true)
2e535b4b-3e95-498d-828a-d06ccfc629bd 2021-08-06 16:37:52.511046 [DEBUG] mod_dptools.c:1685 SET sofia/internal/500@45.32.192.XXX [effective_caller_id_number]=[UNDEF]
2e535b4b-3e95-498d-828a-d06ccfc629bd EXECUTE [depth=0] sofia/internal/500@45.32.192.XXX set(effective_caller_id_number=)
2e535b4b-3e95-498d-828a-d06ccfc629bd 2021-08-06 16:37:52.511046 [DEBUG] mod_dptools.c:1685 SET sofia/internal/500@45.32.192.XXX [effective_caller_id_name]=[UNDEF]
2e535b4b-3e95-498d-828a-d06ccfc629bd EXECUTE [depth=0] sofia/internal/500@45.32.192.XXX set(effective_caller_id_name=)
2e535b4b-3e95-498d-828a-d06ccfc629bd 2021-08-06 16:37:52.511046 [DEBUG] mod_dptools.c:1685 SET sofia/internal/500@45.32.192.XXX [hangup_after_bridge]=[true]
2e535b4b-3e95-498d-828a-d06ccfc629bd EXECUTE [depth=0] sofia/internal/500@45.32.192.XXX set(hangup_after_bridge=true)
2e535b4b-3e95-498d-828a-d06ccfc629bd 2021-08-06 16:37:52.511046 [DEBUG] mod_dptools.c:1830 UNSET [call_timeout]
2e535b4b-3e95-498d-828a-d06ccfc629bd EXECUTE [depth=0] sofia/internal/500@45.32.192.XXX unset(call_timeout)
2e535b4b-3e95-498d-828a-d06ccfc629bd 2021-08-06 16:37:52.511046 [DEBUG] switch_channel.c:1310 EXPORT (export_vars) [call_direction]=[outbound]
2e535b4b-3e95-498d-828a-d06ccfc629bd EXECUTE [depth=0] sofia/internal/500@45.32.192.XXX export(call_direction=outbound)
2e535b4b-3e95-498d-828a-d06ccfc629bd 2021-08-06 16:37:52.511046 [DEBUG] mod_dptools.c:1685 SET sofia/internal/500@45.32.192.XXX [sip_h_X-accountcode]=[45.32.192.XXX]
2e535b4b-3e95-498d-828a-d06ccfc629bd EXECUTE [depth=0] sofia/internal/500@45.32.192.XXX set(sip_h_X-accountcode=45.32.192.XXX)
2e535b4b-3e95-498d-828a-d06ccfc629bd EXECUTE [depth=0] sofia/internal/500@45.32.192.XXX hash(insert/45.32.192.XXX-last_dial/500/XXXXXXXXXX)
2e535b4b-3e95-498d-828a-d06ccfc629bd 2021-08-06 16:37:52.511046 [DEBUG] switch_channel.c:1310 EXPORT (export_vars) [origination_callee_id_name]=[XXXXXXXXXX]
2e535b4b-3e95-498d-828a-d06ccfc629bd EXECUTE [depth=0] sofia/internal/500@45.32.192.XXX export(origination_callee_id_name=XXXXXXXXXX)
2e535b4b-3e95-498d-828a-d06ccfc629bd 2021-08-06 16:37:52.511046 [DEBUG] mod_dptools.c:1685 SET sofia/internal/500@45.32.192.XXX [RFC2822_DATE]=[Fri, 06 Aug 2021 16:37:52 +0000]
2e535b4b-3e95-498d-828a-d06ccfc629bd EXECUTE [depth=0] sofia/internal/500@45.32.192.XXX set(RFC2822_DATE=Fri, 06 Aug 2021 16:37:52 +0000)
2e535b4b-3e95-498d-828a-d06ccfc629bd 2021-08-06 16:37:52.511046 [DEBUG] mod_dptools.c:1685 SET sofia/internal/500@45.32.192.XXX [caller_id_number]=[500]
2e535b4b-3e95-498d-828a-d06ccfc629bd EXECUTE [depth=0] sofia/internal/500@45.32.192.XXX set(caller_id_number=500)
2e535b4b-3e95-498d-828a-d06ccfc629bd 2021-08-06 16:37:52.511046 [DEBUG] switch_core_state_machine.c:329 sofia/internal/500@45.32.192.XXX Standard EXECUTE
2e535b4b-3e95-498d-828a-d06ccfc629bd 2021-08-06 16:37:52.511046 [DEBUG] mod_sofia.c:209 sofia/internal/500@45.32.192.XXX SOFIA EXECUTE
2e535b4b-3e95-498d-828a-d06ccfc629bd 2021-08-06 16:37:52.511046 [DEBUG] switch_core_state_machine.c:651 (sofia/internal/500@45.32.192.XXX) State EXECUTE
2e535b4b-3e95-498d-828a-d06ccfc629bd 2021-08-06 16:37:52.511046 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/500@45.32.192.XXX) Running State Change CS_EXECUTE (Cur 1 Tot 42)
2e535b4b-3e95-498d-828a-d06ccfc629bd 2021-08-06 16:37:52.511046 [DEBUG] switch_core_state_machine.c:644 (sofia/internal/500@45.32.192.XXX) State ROUTING going to sleep
2e535b4b-3e95-498d-828a-d06ccfc629bd 2021-08-06 16:37:52.511046 [DEBUG] switch_core_state_machine.c:287 (sofia/internal/500@45.32.192.XXX) State Change CS_ROUTING -> CS_EXECUTE
2e535b4b-3e95-498d-828a-d06ccfc629bd Dialplan: sofia/internal/500@45.32.192.XXX Action bridge(sofia/gateway/f443e0e2-cd58-47eb-b8e3-9221d3798875/XXXXXXXXXX)
2e535b4b-3e95-498d-828a-d06ccfc629bd Dialplan: sofia/internal/500@45.32.192.XXX Action set(continue_on_fail=1,2,3,6,18,21,27,28,31,34,38,41,42,44,58,88,111,403,501,602,607)
2e535b4b-3e95-498d-828a-d06ccfc629bd Dialplan: sofia/internal/500@45.32.192.XXX Action set(callee_id_number=XXXXXXXXXX)
2e535b4b-3e95-498d-828a-d06ccfc629bd Dialplan: sofia/internal/500@45.32.192.XXX Action set(ignore_display_updates=true)
2e535b4b-3e95-498d-828a-d06ccfc629bd Dialplan: sofia/internal/500@45.32.192.XXX Action set(inherit_codec=true)
2e535b4b-3e95-498d-828a-d06ccfc629bd Dialplan: sofia/internal/500@45.32.192.XXX Action set(effective_caller_id_number=${outbound_caller_id_number})
2e535b4b-3e95-498d-828a-d06ccfc629bd Dialplan: sofia/internal/500@45.32.192.XXX Action set(effective_caller_id_name=${outbound_caller_id_name})
2e535b4b-3e95-498d-828a-d06ccfc629bd Dialplan: sofia/internal/500@45.32.192.XXX Action set(hangup_after_bridge=true)
2e535b4b-3e95-498d-828a-d06ccfc629bd Dialplan: sofia/internal/500@45.32.192.XXX Action unset(call_timeout)
2e535b4b-3e95-498d-828a-d06ccfc629bd Dialplan: sofia/internal/500@45.32.192.XXX Action export(call_direction=outbound)
2e535b4b-3e95-498d-828a-d06ccfc629bd Dialplan: sofia/internal/500@45.32.192.XXX Action set(sip_h_X-accountcode=${accountcode})
2e535b4b-3e95-498d-828a-d06ccfc629bd Dialplan: sofia/internal/500@45.32.192.XXX Regex (PASS) [Telnyx.1d10] destination_number(XXXXXXXXXX) =~ /^\+?1?(\d{10})$/ break=on-false
2e535b4b-3e95-498d-828a-d06ccfc629bd Dialplan: sofia/internal/500@45.32.192.XXX Regex (PASS) [Telnyx.1d10] ${user_exists}(false) =~ /false/ break=on-false
2e535b4b-3e95-498d-828a-d06ccfc629bd Dialplan: sofia/internal/500@45.32.192.XXX parsing [45.32.192.XXX->Telnyx.1d10] continue=false
2e535b4b-3e95-498d-828a-d06ccfc629bd Dialplan: sofia/internal/500@45.32.192.XXX Regex (FAIL) [user_hold_music] ${user_exists}(false) =~ /true/ break=on-false
2e535b4b-3e95-498d-828a-d06ccfc629bd Dialplan: sofia/internal/500@45.32.192.XXX Regex (FAIL) [user_hold_music] ${hold_music}(local_stream://default) =~ /^$/ break=never
2e535b4b-3e95-498d-828a-d06ccfc629bd Dialplan: sofia/internal/500@45.32.192.XXX parsing [45.32.192.XXX->user_hold_music] continue=true
2e535b4b-3e95-498d-828a-d06ccfc629bd 2021-08-06 16:37:52.511046 [DEBUG] mod_dptools.c:1685 SET sofia/internal/500@45.32.192.XXX [outbound_caller_id_number]=[UNDEF]
2e535b4b-3e95-498d-828a-d06ccfc629bd EXECUTE [depth=0] sofia/internal/500@45.32.192.XXX set(outbound_caller_id_number=)
2e535b4b-3e95-498d-828a-d06ccfc629bd Dialplan: sofia/internal/500@45.32.192.XXX Action set(outbound_caller_id_number=${default_outbound_caller_id_number}) INLINE
2e535b4b-3e95-498d-828a-d06ccfc629bd Dialplan: sofia/internal/500@45.32.192.XXX Regex (PASS) [default_caller_id] ${outbound_caller_id_number}() =~ /^$/ break=never
2e535b4b-3e95-498d-828a-d06ccfc629bd 2021-08-06 16:37:52.511046 [DEBUG] mod_dptools.c:1685 SET sofia/internal/500@45.32.192.XXX [outbound_caller_id_name]=[UNDEF]
2e535b4b-3e95-498d-828a-d06ccfc629bd EXECUTE [depth=0] sofia/internal/500@45.32.192.XXX set(outbound_caller_id_name=)
2e535b4b-3e95-498d-828a-d06ccfc629bd Dialplan: sofia/internal/500@45.32.192.XXX Action set(outbound_caller_id_name=${default_outbound_caller_id_name}) INLINE
2e535b4b-3e95-498d-828a-d06ccfc629bd Dialplan: sofia/internal/500@45.32.192.XXX Regex (PASS) [default_caller_id] ${outbound_caller_id_name}() =~ /^$/ break=never
2e535b4b-3e95-498d-828a-d06ccfc629bd 2021-08-06 16:37:52.511046 [DEBUG] mod_dptools.c:1685 SET sofia/internal/500@45.32.192.XXX [emergency_caller_id_number]=[UNDEF]
2e535b4b-3e95-498d-828a-d06ccfc629bd EXECUTE [depth=0] sofia/internal/500@45.32.192.XXX set(emergency_caller_id_number=)
2e535b4b-3e95-498d-828a-d06ccfc629bd Dialplan: sofia/internal/500@45.32.192.XXX Action set(emergency_caller_id_number=${default_emergency_caller_id_number}) INLINE
2e535b4b-3e95-498d-828a-d06ccfc629bd Dialplan: sofia/internal/500@45.32.192.XXX Regex (PASS) [default_caller_id] ${emergency_caller_id_number}() =~ /^$/ break=never
2e535b4b-3e95-498d-828a-d06ccfc629bd 2021-08-06 16:37:52.511046 [DEBUG] mod_dptools.c:1685 SET sofia/internal/500@45.32.192.XXX [emergency_caller_id_name]=[UNDEF]
2e535b4b-3e95-498d-828a-d06ccfc629bd EXECUTE [depth=0] sofia/internal/500@45.32.192.XXX set(emergency_caller_id_name=)
2e535b4b-3e95-498d-828a-d06ccfc629bd Dialplan: sofia/internal/500@45.32.192.XXX Action set(emergency_caller_id_name=${default_emergency_caller_id_name}) INLINE
2e535b4b-3e95-498d-828a-d06ccfc629bd Dialplan: sofia/internal/500@45.32.192.XXX Regex (PASS) [default_caller_id] ${emergency_caller_id_name}() =~ /^$/ break=never
2e535b4b-3e95-498d-828a-d06ccfc629bd Dialplan: sofia/internal/500@45.32.192.XXX parsing [45.32.192.XXX->default_caller_id] continue=true
2e535b4b-3e95-498d-828a-d06ccfc629bd Dialplan: sofia/internal/500@45.32.192.XXX Regex (FAIL) [speed_dial] destination_number(XXXXXXXXXX) =~ /^\*0(.*)$/ break=on-false
2e535b4b-3e95-498d-828a-d06ccfc629bd Dialplan: sofia/internal/500@45.32.192.XXX parsing [45.32.192.XXX->speed_dial] continue=false
2e535b4b-3e95-498d-828a-d06ccfc629bd Dialplan: sofia/internal/500@45.32.192.XXX Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number})
2e535b4b-3e95-498d-828a-d06ccfc629bd Dialplan: sofia/internal/500@45.32.192.XXX Regex (PASS) [redial] () =~ // break=never
2e535b4b-3e95-498d-828a-d06ccfc629bd Dialplan: sofia/internal/500@45.32.192.XXX Regex (FAIL) [redial] destination_number(XXXXXXXXXX) =~ /^(redial|\*870)$/ break=on-true
2e535b4b-3e95-498d-828a-d06ccfc629bd Dialplan: sofia/internal/500@45.32.192.XXX parsing [45.32.192.XXX->redial] continue=true
2e535b4b-3e95-498d-828a-d06ccfc629bd Dialplan: sofia/internal/500@45.32.192.XXX Regex (FAIL) [rtp_has_crypto] ${rtp_has_crypto}() =~ /^(AEAD_AES_256_GCM_8|AEAD_AES_128_GCM_8|AES_CM_256_HMAC_SHA1_80|AES_CM_192_HMAC_SHA1_80|AES_CM_128_HMAC_SHA1_80|AES_CM_256_HMAC_SHA1_32|AES_CM_192_HMAC_SHA1_32|AES_CM_128_HMAC_SHA1_32|AES_CM_128_NULL_AUTH)$/ break=on-false
2e535b4b-3e95-498d-828a-d06ccfc629bd Dialplan: sofia/internal/500@45.32.192.XXX parsing [45.32.192.XXX->rtp_has_crypto] continue=true
2e535b4b-3e95-498d-828a-d06ccfc629bd Dialplan: sofia/internal/500@45.32.192.XXX Regex (FAIL) [user_record] ${record_session}() =~ /^true$/ break=on-false
2e535b4b-3e95-498d-828a-d06ccfc629bd Dialplan: sofia/internal/500@45.32.192.XXX Regex (FAIL) [user_record] ${from_user_record}() =~ /^local$/ break=never
2e535b4b-3e95-498d-828a-d06ccfc629bd Dialplan: sofia/internal/500@45.32.192.XXX Regex (PASS) [user_record] ${call_direction}(local) =~ /^local$/ break=never
2e535b4b-3e95-498d-828a-d06ccfc629bd Dialplan: sofia/internal/500@45.32.192.XXX Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never
2e535b4b-3e95-498d-828a-d06ccfc629bd Dialplan: sofia/internal/500@45.32.192.XXX Regex (FAIL) [user_record] ${from_user_record}() =~ /^outbound$/ break=never
2e535b4b-3e95-498d-828a-d06ccfc629bd Dialplan: sofia/internal/500@45.32.192.XXX Regex (FAIL) [user_record] ${call_direction}(local) =~ /^outbound$/ break=never
2e535b4b-3e95-498d-828a-d06ccfc629bd Dialplan: sofia/internal/500@45.32.192.XXX Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never
2e535b4b-3e95-498d-828a-d06ccfc629bd Dialplan: sofia/internal/500@45.32.192.XXX Regex (FAIL) [user_record] ${from_user_record}() =~ /^inbound$/ break=never
2e535b4b-3e95-498d-828a-d06ccfc629bd Dialplan: sofia/internal/500@45.32.192.XXX Regex (FAIL) [user_record] ${call_direction}(local) =~ /^inbound$/ break=never
2e535b4b-3e95-498d-828a-d06ccfc629bd Dialplan: sofia/internal/500@45.32.192.XXX Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never
2e535b4b-3e95-498d-828a-d06ccfc629bd Dialplan: sofia/internal/500@45.32.192.XXX Regex (FAIL) [user_record] ${from_user_record}() =~ /^all$/ break=never
2e535b4b-3e95-498d-828a-d06ccfc629bd Dialplan: sofia/internal/500@45.32.192.XXX Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never
2e535b4b-3e95-498d-828a-d06ccfc629bd 2021-08-06 16:37:52.511046 [DEBUG] mod_dptools.c:1685 SET sofia/internal/500@45.32.192.XXX [from_user_record]=[UNDEF]
2e535b4b-3e95-498d-828a-d06ccfc629bd EXECUTE [depth=0] sofia/internal/500@45.32.192.XXX set(from_user_record=)
2e535b4b-3e95-498d-828a-d06ccfc629bd Dialplan: sofia/internal/500@45.32.192.XXX Action set(from_user_record=${user_data ${sip_from_user}@${sip_from_host} var user_record}) INLINE
2e535b4b-3e95-498d-828a-d06ccfc629bd Dialplan: sofia/internal/500@45.32.192.XXX Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never
2e535b4b-3e95-498d-828a-d06ccfc629bd Dialplan: sofia/internal/500@45.32.192.XXX Regex (FAIL) [user_record] ${user_record}() =~ /^local$/ break=never
2e535b4b-3e95-498d-828a-d06ccfc629bd Dialplan: sofia/internal/500@45.32.192.XXX Regex (PASS) [user_record] ${call_direction}(local) =~ /^local$/ break=never
2e535b4b-3e95-498d-828a-d06ccfc629bd Dialplan: sofia/internal/500@45.32.192.XXX Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never
2e535b4b-3e95-498d-828a-d06ccfc629bd Dialplan: sofia/internal/500@45.32.192.XXX Regex (FAIL) [user_record] ${user_record}() =~ /^outbound$/ break=never
2e535b4b-3e95-498d-828a-d06ccfc629bd Dialplan: sofia/internal/500@45.32.192.XXX Regex (FAIL) [user_record] ${call_direction}(local) =~ /^outbound$/ break=never
2e535b4b-3e95-498d-828a-d06ccfc629bd Dialplan: sofia/internal/500@45.32.192.XXX Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never
2e535b4b-3e95-498d-828a-d06ccfc629bd Dialplan: sofia/internal/500@45.32.192.XXX Regex (FAIL) [user_record] ${user_record}() =~ /^inbound$/ break=never
2e535b4b-3e95-498d-828a-d06ccfc629bd Dialplan: sofia/internal/500@45.32.192.XXX Regex (FAIL) [user_record] ${call_direction}(local) =~ /^inbound$/ break=never
2e535b4b-3e95-498d-828a-d06ccfc629bd Dialplan: sofia/internal/500@45.32.192.XXX Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never
2e535b4b-3e95-498d-828a-d06ccfc629bd Dialplan: sofia/internal/500@45.32.192.XXX Regex (FAIL) [user_record] ${user_record}() =~ /^all$/ break=never
2e535b4b-3e95-498d-828a-d06ccfc629bd Dialplan: sofia/internal/500@45.32.192.XXX Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never
2e535b4b-3e95-498d-828a-d06ccfc629bd Dialplan: sofia/internal/500@45.32.192.XXX parsing [45.32.192.XXX->user_record] continue=true
2e535b4b-3e95-498d-828a-d06ccfc629bd Dialplan: sofia/internal/500@45.32.192.XXX Regex (FAIL) [is_loopback] ${is_follow_me_loopback}() =~ /true/ break=on-false
2e535b4b-3e95-498d-828a-d06ccfc629bd Dialplan: sofia/internal/500@45.32.192.XXX parsing [45.32.192.XXX->is_loopback] continue=true
2e535b4b-3e95-498d-828a-d06ccfc629bd Dialplan: sofia/internal/500@45.32.192.XXX Action export(origination_callee_id_name=${destination_number})
2e535b4b-3e95-498d-828a-d06ccfc629bd Dialplan: sofia/internal/500@45.32.192.XXX Regex (PASS) [domain-variables] () =~ // break=on-false
2e535b4b-3e95-498d-828a-d06ccfc629bd Dialplan: sofia/internal/500@45.32.192.XXX parsing [45.32.192.XXX->domain-variables] continue=true
2e535b4b-3e95-498d-828a-d06ccfc629bd Dialplan: sofia/internal/500@45.32.192.XXX Action set(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
2e535b4b-3e95-498d-828a-d06ccfc629bd Dialplan: sofia/internal/500@45.32.192.XXX Regex (PASS) [global-variables] () =~ // break=on-false
2e535b4b-3e95-498d-828a-d06ccfc629bd Dialplan: sofia/internal/500@45.32.192.XXX parsing [45.32.192.XXX->global-variables] continue=true
2e535b4b-3e95-498d-828a-d06ccfc629bd 2021-08-06 16:37:52.511046 [DEBUG] switch_channel.c:1310 EXPORT (export_vars) [call_direction]=[local]
2e535b4b-3e95-498d-828a-d06ccfc629bd EXECUTE [depth=0] sofia/internal/500@45.32.192.XXX export(call_direction=local)
2e535b4b-3e95-498d-828a-d06ccfc629bd Dialplan: sofia/internal/500@45.32.192.XXX ANTI-Action export(call_direction=local) INLINE
2e535b4b-3e95-498d-828a-d06ccfc629bd Dialplan: sofia/internal/500@45.32.192.XXX Regex (FAIL) [call-direction] ${call_direction}() =~ /^(inbound|outbound|local)$/ break=never
2e535b4b-3e95-498d-828a-d06ccfc629bd Dialplan: sofia/internal/500@45.32.192.XXX parsing [45.32.192.XXX->call-direction] continue=true
2e535b4b-3e95-498d-828a-d06ccfc629bd Dialplan: sofia/internal/500@45.32.192.XXX Action set(caller_id_number=${caller_id_number})
2e535b4b-3e95-498d-828a-d06ccfc629bd 2021-08-06 16:37:52.511046 [DEBUG] mod_dptools.c:1685 SET sofia/internal/500@45.32.192.XXX [caller_id_name]=[500]
2e535b4b-3e95-498d-828a-d06ccfc629bd EXECUTE [depth=0] sofia/internal/500@45.32.192.XXX set(caller_id_name=500)
2e535b4b-3e95-498d-828a-d06ccfc629bd Dialplan: sofia/internal/500@45.32.192.XXX Action set(caller_id_name=${caller_id_name}) INLINE
2e535b4b-3e95-498d-828a-d06ccfc629bd 2021-08-06 16:37:52.511046 [DEBUG] mod_dptools.c:1685 SET sofia/internal/500@45.32.192.XXX [caller_destination]=[XXXXXXXXXX]
2e535b4b-3e95-498d-828a-d06ccfc629bd EXECUTE [depth=0] sofia/internal/500@45.32.192.XXX set(caller_destination=XXXXXXXXXX)
2e535b4b-3e95-498d-828a-d06ccfc629bd Dialplan: sofia/internal/500@45.32.192.XXX Action set(caller_destination=${destination_number}) INLINE
2e535b4b-3e95-498d-828a-d06ccfc629bd Dialplan: sofia/internal/500@45.32.192.XXX Regex (PASS) [caller-details] ${caller_destination}() =~ /^$/ break=never
2e535b4b-3e95-498d-828a-d06ccfc629bd Dialplan: sofia/internal/500@45.32.192.XXX parsing [45.32.192.XXX->caller-details] continue=true
2e535b4b-3e95-498d-828a-d06ccfc629bd Dialplan: sofia/internal/500@45.32.192.XXX Regex (FAIL) [user_exists] ${user_exists}(false) =~ /^true$/ break=on-false
2e535b4b-3e95-498d-828a-d06ccfc629bd 2021-08-06 16:37:52.511046 [DEBUG] mod_dptools.c:1685 SET sofia/internal/500@45.32.192.XXX [from_user_exists]=[true]
2e535b4b-3e95-498d-828a-d06ccfc629bd EXECUTE [depth=0] sofia/internal/500@45.32.192.XXX set(from_user_exists=true)
2e535b4b-3e95-498d-828a-d06ccfc629bd Dialplan: sofia/internal/500@45.32.192.XXX Action set(from_user_exists=${user_exists id ${sip_from_user} ${sip_from_host}}) INLINE
2e535b4b-3e95-498d-828a-d06ccfc629bd 2021-08-06 16:37:52.511046 [DEBUG] mod_dptools.c:1685 SET sofia/internal/500@45.32.192.XXX [user_exists]=[false]
2e535b4b-3e95-498d-828a-d06ccfc629bd EXECUTE [depth=0] sofia/internal/500@45.32.192.XXX set(user_exists=false)
2e535b4b-3e95-498d-828a-d06ccfc629bd Dialplan: sofia/internal/500@45.32.192.XXX Action set(user_exists=${user_exists id ${destination_number} ${domain_name}}) INLINE
2e535b4b-3e95-498d-828a-d06ccfc629bd Dialplan: sofia/internal/500@45.32.192.XXX Regex (PASS) [user_exists] () =~ // break=on-false
eak=never

fusionpbxnoaudio · Aug 6, 2021

in fs_cli set sofia global siptrace on - it will give you SIP messages which may throw some light.

vgarcia · Aug 6, 2021

fusionpbxnoaudio said:
in fs_cli set sofia global siptrace on - it will give you SIP messages which may throw some light.

THank you, I have attached the new log.

2021-08-06 18:05:00.284305 [NOTICE] switch_channel.c:1118 New Channel sofia/internal/500@45.32.XXX.XXX [1334963b-b7a1-4a43-93a8-97f19944dfc5]
2021-08-06 18:05:00.284305 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/500@45.32.XXX.XXX) Running State Change CS_NEW (Cur 1 Tot 10)
2021-08-06 18:05:00.284305 [INFO] sofia.c:10362 sofia/internal/500@45.32.XXX.XXX receiving invite from 97.77.65.74:51330 version: 1.10.6 -release-18-1ff9d0a60e 64bit call-id: vSEVClDloYxT6MyOc69ebA..
2021-08-06 18:05:00.284305 [DEBUG] sofia.c:10456 verifying acl "domains" for ip/port 97.77.65.74:0.
2021-08-06 18:05:00.284305 [DEBUG] sofia.c:2447 detaching session 1334963b-b7a1-4a43-93a8-97f19944dfc5
2021-08-06 18:05:00.284305 [WARNING] sofia_reg.c:1795 SIP auth challenge (INVITE) on sofia profile 'internal' for [XXXXXXXXXX@45.32.XXX.XXX] from ip 97.77.65.74
2021-08-06 18:05:00.284305 [DEBUG] switch_core_state_machine.c:604 (sofia/internal/500@45.32.XXX.XXX) State NEW
2021-08-06 18:05:00.324360 [DEBUG] sofia.c:2562 Re-attaching to session 1334963b-b7a1-4a43-93a8-97f19944dfc5
2021-08-06 18:05:00.324360 [INFO] sofia.c:10362 sofia/internal/500@45.32.XXX.XXX receiving invite from 97.77.65.74:51330 version: 1.10.6 -release-18-1ff9d0a60e 64bit call-id: vSEVClDloYxT6MyOc69ebA..
2021-08-06 18:05:00.324360 [DEBUG] sofia.c:10456 verifying acl "domains" for ip/port 97.77.65.74:0.
2021-08-06 18:05:00.344303 [DEBUG] sofia.c:7406 Channel sofia/internal/500@45.32.XXX.XXX entering state [received][100]
2021-08-06 18:05:00.344303 [DEBUG] sofia.c:7416 Remote SDP:
v=0
o=Z 1628273100762 1 IN IP4 97.77.65.74
s=Z
c=IN IP4 97.77.65.74
t=0 0
m=audio 56704 RTP/AVP 3 101 110 97 8 0
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=rtpmap:110 speex/8000
a=rtpmap:97 iLBC/8000
a=fmtp:97 mode=20

2021-08-06 18:05:00.344303 [DEBUG] switch_core_media.c:5601 Audio Codec Compare [GSM:3:8000:20:13200:1]/[G722:9:8000:20:64000:1]
2021-08-06 18:05:00.344303 [DEBUG] switch_core_media.c:5601 Audio Codec Compare [GSM:3:8000:20:13200:1]/[PCMU:0:8000:20:64000:1]
2021-08-06 18:05:00.344303 [DEBUG] switch_core_media.c:5601 Audio Codec Compare [GSM:3:8000:20:13200:1]/[PCMA:8:8000:20:64000:1]
2021-08-06 18:05:00.344303 [DEBUG] switch_core_media.c:5517 Set telephone-event payload to 101@8000
2021-08-06 18:05:00.344303 [DEBUG] switch_core_media.c:5601 Audio Codec Compare [speex:110:8000:20:0:1]/[G722:9:8000:20:64000:1]
2021-08-06 18:05:00.344303 [DEBUG] switch_core_media.c:5601 Audio Codec Compare [speex:110:8000:20:0:1]/[PCMU:0:8000:20:64000:1]
2021-08-06 18:05:00.344303 [DEBUG] switch_core_media.c:5601 Audio Codec Compare [speex:110:8000:20:0:1]/[PCMA:8:8000:20:64000:1]
2021-08-06 18:05:00.344303 [DEBUG] switch_core_media.c:5601 Audio Codec Compare [iLBC:97:8000:30:0:1]/[G722:9:8000:20:64000:1]
2021-08-06 18:05:00.344303 [DEBUG] switch_core_media.c:5601 Audio Codec Compare [iLBC:97:8000:30:0:1]/[PCMU:0:8000:20:64000:1]
2021-08-06 18:05:00.344303 [DEBUG] switch_core_media.c:5601 Audio Codec Compare [iLBC:97:8000:30:0:1]/[PCMA:8:8000:20:64000:1]
2021-08-06 18:05:00.344303 [DEBUG] switch_core_media.c:5601 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2021-08-06 18:05:00.344303 [DEBUG] switch_core_media.c:5601 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2021-08-06 18:05:00.344303 [DEBUG] switch_core_media.c:5601 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2021-08-06 18:05:00.344303 [DEBUG] switch_core_media.c:5656 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
2021-08-06 18:05:00.344303 [DEBUG] switch_core_media.c:5601 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2021-08-06 18:05:00.344303 [DEBUG] switch_core_media.c:5601 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2021-08-06 18:05:00.344303 [DEBUG] switch_core_media.c:5656 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
2021-08-06 18:05:00.344303 [DEBUG] switch_core_media.c:5601 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2021-08-06 18:05:00.344303 [DEBUG] switch_core_media.c:3847 Set Codec sofia/internal/500@45.32.XXX.XXX PCMA/8000 20 ms 160 samples 64000 bits 1 channels
2021-08-06 18:05:00.344303 [DEBUG] switch_core_codec.c:111 sofia/internal/500@45.32.XXX.XXX Original read codec set to PCMA:8
2021-08-06 18:05:00.344303 [DEBUG] switch_core_media.c:5860 Set telephone-event payload to 101@8000
2021-08-06 18:05:00.344303 [DEBUG] switch_core_media.c:5918 sofia/internal/500@45.32.XXX.XXX Set 2833 dtmf send payload to 101 recv payload to 101
2021-08-06 18:05:00.344303 [DEBUG] sofia.c:7840 (sofia/internal/500@45.32.XXX.XXX) State Change CS_NEW -> CS_INIT
2021-08-06 18:05:00.344303 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/500@45.32.XXX.XXX) Running State Change CS_INIT (Cur 1 Tot 10)
2021-08-06 18:05:00.344303 [DEBUG] switch_core_state_machine.c:628 (sofia/internal/500@45.32.XXX.XXX) State INIT
2021-08-06 18:05:00.344303 [DEBUG] mod_sofia.c:93 sofia/internal/500@45.32.XXX.XXX SOFIA INIT
2021-08-06 18:05:00.344303 [DEBUG] switch_core_state_machine.c:40 sofia/internal/500@45.32.XXX.XXX Standard INIT
2021-08-06 18:05:00.344303 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/500@45.32.XXX.XXX) State Change CS_INIT -> CS_ROUTING
2021-08-06 18:05:00.344303 [DEBUG] switch_core_state_machine.c:628 (sofia/internal/500@45.32.XXX.XXX) State INIT going to sleep
2021-08-06 18:05:00.344303 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/500@45.32.XXX.XXX) Running State Change CS_ROUTING (Cur 1 Tot 10)
2021-08-06 18:05:00.344303 [DEBUG] switch_channel.c:2332 (sofia/internal/500@45.32.XXX.XXX) Callstate Change DOWN -> RINGING
2021-08-06 18:05:00.344303 [DEBUG] switch_core_state_machine.c:644 (sofia/internal/500@45.32.XXX.XXX) State ROUTING
2021-08-06 18:05:00.344303 [DEBUG] mod_sofia.c:154 sofia/internal/500@45.32.XXX.XXX SOFIA ROUTING
2021-08-06 18:05:00.344303 [DEBUG] switch_core_state_machine.c:236 sofia/internal/500@45.32.XXX.XXX Standard ROUTING
2021-08-06 18:05:00.344303 [INFO] mod_dialplan_xml.c:637 Processing 500 <500>->XXXXXXXXXX in context 45.32.XXX.XXX
Dialplan: sofia/internal/500@45.32.XXX.XXX parsing [45.32.XXX.XXX->user_exists] continue=true
Dialplan: sofia/internal/500@45.32.XXX.XXX Regex (FAIL) [user_exists] ${loopback_leg}() =~ /^B$/ break=never
Dialplan: sofia/internal/500@45.32.XXX.XXX Regex (PASS) [user_exists] () =~ // break=on-false
Dialplan: sofia/internal/500@45.32.XXX.XXX Action set(user_exists=${user_exists id ${destination_number} ${domain_name}}) INLINE
EXECUTE [depth=0] sofia/internal/500@45.32.XXX.XXX set(user_exists=false)
2021-08-06 18:05:00.384304 [DEBUG] mod_dptools.c:1685 SET sofia/internal/500@45.32.XXX.XXX [user_exists]=[false]
Dialplan: sofia/internal/500@45.32.XXX.XXX Action set(from_user_exists=${user_exists id ${sip_from_user} ${sip_from_host}}) INLINE
EXECUTE [depth=0] sofia/internal/500@45.32.XXX.XXX set(from_user_exists=true)
2021-08-06 18:05:00.384304 [DEBUG] mod_dptools.c:1685 SET sofia/internal/500@45.32.XXX.XXX [from_user_exists]=[true]
Dialplan: sofia/internal/500@45.32.XXX.XXX Regex (FAIL) [user_exists] ${user_exists}(false) =~ /^true$/ break=on-false
Dialplan: sofia/internal/500@45.32.XXX.XXX parsing [45.32.XXX.XXX->caller-details] continue=true
Dialplan: sofia/internal/500@45.32.XXX.XXX Regex (PASS) [caller-details] ${caller_destination}() =~ /^$/ break=never
Dialplan: sofia/internal/500@45.32.XXX.XXX Action set(caller_destination=${destination_number}) INLINE
EXECUTE [depth=0] sofia/internal/500@45.32.XXX.XXX set(caller_destination=XXXXXXXXXX)
2021-08-06 18:05:00.384304 [DEBUG] mod_dptools.c:1685 SET sofia/internal/500@45.32.XXX.XXX [caller_destination]=[XXXXXXXXXX]
Dialplan: sofia/internal/500@45.32.XXX.XXX Action set(caller_id_name=${caller_id_name}) INLINE
EXECUTE [depth=0] sofia/internal/500@45.32.XXX.XXX set(caller_id_name=500)
2021-08-06 18:05:00.384304 [DEBUG] mod_dptools.c:1685 SET sofia/internal/500@45.32.XXX.XXX [caller_id_name]=[500]
Dialplan: sofia/internal/500@45.32.XXX.XXX Action set(caller_id_number=${caller_id_number})
Dialplan: sofia/internal/500@45.32.XXX.XXX parsing [45.32.XXX.XXX->call-direction] continue=true
Dialplan: sofia/internal/500@45.32.XXX.XXX Regex (FAIL) [call-direction] ${call_direction}() =~ /^(inbound|outbound|local)$/ break=never
Dialplan: sofia/internal/500@45.32.XXX.XXX ANTI-Action export(call_direction=local) INLINE
EXECUTE [depth=0] sofia/internal/500@45.32.XXX.XXX export(call_direction=local)
2021-08-06 18:05:00.384304 [DEBUG] switch_channel.c:1310 EXPORT (export_vars) [call_direction]=[local]
Dialplan: sofia/internal/500@45.32.XXX.XXX parsing [45.32.XXX.XXX->global-variables] continue=true
Dialplan: sofia/internal/500@45.32.XXX.XXX Regex (PASS) [global-variables] () =~ // break=on-false
Dialplan: sofia/internal/500@45.32.XXX.XXX Action set(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
Dialplan: sofia/internal/500@45.32.XXX.XXX parsing [45.32.XXX.XXX->domain-variables] continue=true
Dialplan: sofia/internal/500@45.32.XXX.XXX Regex (PASS) [domain-variables] () =~ // break=on-false
Dialplan: sofia/internal/500@45.32.XXX.XXX Action export(origination_callee_id_name=${destination_number})
Dialplan: sofia/internal/500@45.32.XXX.XXX parsing [45.32.XXX.XXX->is_loopback] continue=true
Dialplan: sofia/internal/500@45.32.XXX.XXX Regex (FAIL) [is_loopback] ${is_follow_me_loopback}() =~ /true/ break=on-false
Dialplan: sofia/internal/500@45.32.XXX.XXX parsing [45.32.XXX.XXX->user_record] continue=true
Dialplan: sofia/internal/500@45.32.XXX.XXX Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/500@45.32.XXX.XXX Regex (FAIL) [user_record] ${user_record}() =~ /^all$/ break=never
Dialplan: sofia/internal/500@45.32.XXX.XXX Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/500@45.32.XXX.XXX Regex (FAIL) [user_record] ${call_direction}(local) =~ /^inbound$/ break=never
Dialplan: sofia/internal/500@45.32.XXX.XXX Regex (FAIL) [user_record] ${user_record}() =~ /^inbound$/ break=never
Dialplan: sofia/internal/500@45.32.XXX.XXX Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/500@45.32.XXX.XXX Regex (FAIL) [user_record] ${call_direction}(local) =~ /^outbound$/ break=never
Dialplan: sofia/internal/500@45.32.XXX.XXX Regex (FAIL) [user_record] ${user_record}() =~ /^outbound$/ break=never
Dialplan: sofia/internal/500@45.32.XXX.XXX Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/500@45.32.XXX.XXX Regex (PASS) [user_record] ${call_direction}(local) =~ /^local$/ break=never
Dialplan: sofia/internal/500@45.32.XXX.XXX Regex (FAIL) [user_record] ${user_record}() =~ /^local$/ break=never
Dialplan: sofia/internal/500@45.32.XXX.XXX Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/internal/500@45.32.XXX.XXX Action set(from_user_record=${user_data ${sip_from_user}@${sip_from_host} var user_record}) INLINE
EXECUTE [depth=0] sofia/internal/500@45.32.XXX.XXX set(from_user_record=)
2021-08-06 18:05:00.384304 [DEBUG] mod_dptools.c:1685 SET sofia/internal/500@45.32.XXX.XXX [from_user_record]=[UNDEF]
Dialplan: sofia/internal/500@45.32.XXX.XXX Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/internal/500@45.32.XXX.XXX Regex (FAIL) [user_record] ${from_user_record}() =~ /^all$/ break=never
Dialplan: sofia/internal/500@45.32.XXX.XXX Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/internal/500@45.32.XXX.XXX Regex (FAIL) [user_record] ${call_direction}(local) =~ /^inbound$/ break=never
Dialplan: sofia/internal/500@45.32.XXX.XXX Regex (FAIL) [user_record] ${from_user_record}() =~ /^inbound$/ break=never
Dialplan: sofia/internal/500@45.32.XXX.XXX Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/internal/500@45.32.XXX.XXX Regex (FAIL) [user_record] ${call_direction}(local) =~ /^outbound$/ break=never
Dialplan: sofia/internal/500@45.32.XXX.XXX Regex (FAIL) [user_record] ${from_user_record}() =~ /^outbound$/ break=never
Dialplan: sofia/internal/500@45.32.XXX.XXX Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/internal/500@45.32.XXX.XXX Regex (PASS) [user_record] ${call_direction}(local) =~ /^local$/ break=never
Dialplan: sofia/internal/500@45.32.XXX.XXX Regex (FAIL) [user_record] ${from_user_record}() =~ /^local$/ break=never
Dialplan: sofia/internal/500@45.32.XXX.XXX Regex (FAIL) [user_record] ${record_session}() =~ /^true$/ break=on-false
Dialplan: sofia/internal/500@45.32.XXX.XXX parsing [45.32.XXX.XXX->rtp_has_crypto] continue=true
Dialplan: sofia/internal/500@45.32.XXX.XXX Regex (FAIL) [rtp_has_crypto] ${rtp_has_crypto}() =~ /^(AEAD_AES_256_GCM_8|AEAD_AES_128_GCM_8|AES_CM_256_HMAC_SHA1_80|AES_CM_192_HMAC_SHA1_80|AES_CM_128_HMAC_SHA1_80|AES_CM_256_HMAC_SHA1_32|AES_CM_192_HMAC_SHA1_32|AES_CM_128_HMAC_SHA1_32|AES_CM_128_NULL_AUTH)$/ break=on-false
Dialplan: sofia/internal/500@45.32.XXX.XXX parsing [45.32.XXX.XXX->redial] continue=true
Dialplan: sofia/internal/500@45.32.XXX.XXX Regex (FAIL) [redial] destination_number(XXXXXXXXXX) =~ /^(redial|\*870)$/ break=on-true
Dialplan: sofia/internal/500@45.32.XXX.XXX Regex (PASS) [redial] () =~ // break=never
Dialplan: sofia/internal/500@45.32.XXX.XXX Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number})
Dialplan: sofia/internal/500@45.32.XXX.XXX parsing [45.32.XXX.XXX->speed_dial] continue=false
Dialplan: sofia/internal/500@45.32.XXX.XXX Regex (FAIL) [speed_dial] destination_number(XXXXXXXXXX) =~ /^\*0(.*)$/ break=on-false
Dialplan: sofia/internal/500@45.32.XXX.XXX parsing [45.32.XXX.XXX->default_caller_id] continue=true
Dialplan: sofia/internal/500@45.32.XXX.XXX Regex (PASS) [default_caller_id] ${emergency_caller_id_name}() =~ /^$/ break=never
Dialplan: sofia/internal/500@45.32.XXX.XXX Action set(emergency_caller_id_name=${default_emergency_caller_id_name}) INLINE
EXECUTE [depth=0] sofia/internal/500@45.32.XXX.XXX set(emergency_caller_id_name=)
2021-08-06 18:05:00.384304 [DEBUG] mod_dptools.c:1685 SET sofia/internal/500@45.32.XXX.XXX [emergency_caller_id_name]=[UNDEF]
Dialplan: sofia/internal/500@45.32.XXX.XXX Regex (PASS) [default_caller_id] ${emergency_caller_id_number}() =~ /^$/ break=never
Dialplan: sofia/internal/500@45.32.XXX.XXX Action set(emergency_caller_id_number=${default_emergency_caller_id_number}) INLINE
EXECUTE [depth=0] sofia/internal/500@45.32.XXX.XXX set(emergency_caller_id_number=)
2021-08-06 18:05:00.384304 [DEBUG] mod_dptools.c:1685 SET sofia/internal/500@45.32.XXX.XXX [emergency_caller_id_number]=[UNDEF]
Dialplan: sofia/internal/500@45.32.XXX.XXX Regex (PASS) [default_caller_id] ${outbound_caller_id_name}() =~ /^$/ break=never
Dialplan: sofia/internal/500@45.32.XXX.XXX Action set(outbound_caller_id_name=${default_outbound_caller_id_name}) INLINE
EXECUTE [depth=0] sofia/internal/500@45.32.XXX.XXX set(outbound_caller_id_name=)
2021-08-06 18:05:00.384304 [DEBUG] mod_dptools.c:1685 SET sofia/internal/500@45.32.XXX.XXX [outbound_caller_id_name]=[UNDEF]
Dialplan: sofia/internal/500@45.32.XXX.XXX Regex (PASS) [default_caller_id] ${outbound_caller_id_number}() =~ /^$/ break=never
Dialplan: sofia/internal/500@45.32.XXX.XXX Action set(outbound_caller_id_number=${default_outbound_caller_id_number}) INLINE
EXECUTE [depth=0] sofia/internal/500@45.32.XXX.XXX set(outbound_caller_id_number=)
2021-08-06 18:05:00.384304 [DEBUG] mod_dptools.c:1685 SET sofia/internal/500@45.32.XXX.XXX [outbound_caller_id_number]=[UNDEF]
Dialplan: sofia/internal/500@45.32.XXX.XXX parsing [45.32.XXX.XXX->user_hold_music] continue=true
Dialplan: sofia/internal/500@45.32.XXX.XXX Regex (FAIL) [user_hold_music] ${hold_music}(local_stream://default) =~ /^$/ break=never
Dialplan: sofia/internal/500@45.32.XXX.XXX Regex (FAIL) [user_hold_music] ${user_exists}(false) =~ /true/ break=on-false
Dialplan: sofia/internal/500@45.32.XXX.XXX parsing [45.32.XXX.XXX->Telnyx.1d10] continue=false
Dialplan: sofia/internal/500@45.32.XXX.XXX Regex (PASS) [Telnyx.1d10] ${user_exists}(false) =~ /false/ break=on-false
Dialplan: sofia/internal/500@45.32.XXX.XXX Regex (PASS) [Telnyx.1d10] destination_number(XXXXXXXXXX) =~ /^\+?1?(\d{10})$/ break=on-false
Dialplan: sofia/internal/500@45.32.XXX.XXX Action set(sip_h_X-accountcode=${accountcode})
Dialplan: sofia/internal/500@45.32.XXX.XXX Action export(call_direction=outbound)
Dialplan: sofia/internal/500@45.32.XXX.XXX Action unset(call_timeout)
Dialplan: sofia/internal/500@45.32.XXX.XXX Action set(hangup_after_bridge=true)
Dialplan: sofia/internal/500@45.32.XXX.XXX Action set(effective_caller_id_name=${outbound_caller_id_name})
Dialplan: sofia/internal/500@45.32.XXX.XXX Action set(effective_caller_id_number=${outbound_caller_id_number})
Dialplan: sofia/internal/500@45.32.XXX.XXX Action set(inherit_codec=true)
Dialplan: sofia/internal/500@45.32.XXX.XXX Action set(ignore_display_updates=true)
Dialplan: sofia/internal/500@45.32.XXX.XXX Action set(callee_id_number=XXXXXXXXXX)
Dialplan: sofia/internal/500@45.32.XXX.XXX Action set(continue_on_fail=1,2,3,6,18,21,27,28,31,34,38,41,42,44,58,88,111,403,501,602,607)
Dialplan: sofia/internal/500@45.32.XXX.XXX Action bridge(sofia/gateway/456f43de-01ab-421e-9bb3-c812c5b9e5c3/XXXXXXXXXX)
2021-08-06 18:05:00.384304 [DEBUG] switch_core_state_machine.c:287 (sofia/internal/500@45.32.XXX.XXX) State Change CS_ROUTING -> CS_EXECUTE
2021-08-06 18:05:00.384304 [DEBUG] switch_core_state_machine.c:644 (sofia/internal/500@45.32.XXX.XXX) State ROUTING going to sleep
2021-08-06 18:05:00.384304 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/500@45.32.XXX.XXX) Running State Change CS_EXECUTE (Cur 1 Tot 10)
2021-08-06 18:05:00.384304 [DEBUG] switch_core_state_machine.c:651 (sofia/internal/500@45.32.XXX.XXX) State EXECUTE
2021-08-06 18:05:00.384304 [DEBUG] mod_sofia.c:209 sofia/internal/500@45.32.XXX.XXX SOFIA EXECUTE
2021-08-06 18:05:00.384304 [DEBUG] switch_core_state_machine.c:329 sofia/internal/500@45.32.XXX.XXX Standard EXECUTE
EXECUTE [depth=0] sofia/internal/500@45.32.XXX.XXX set(caller_id_number=500)
2021-08-06 18:05:00.384304 [DEBUG] mod_dptools.c:1685 SET sofia/internal/500@45.32.XXX.XXX [caller_id_number]=[500]
EXECUTE [depth=0] sofia/internal/500@45.32.XXX.XXX set(RFC2822_DATE=Fri, 06 Aug 2021 18:05:00 +0000)
2021-08-06 18:05:00.384304 [DEBUG] mod_dptools.c:1685 SET sofia/internal/500@45.32.XXX.XXX [RFC2822_DATE]=[Fri, 06 Aug 2021 18:05:00 +0000]
EXECUTE [depth=0] sofia/internal/500@45.32.XXX.XXX export(origination_callee_id_name=XXXXXXXXXX)
2021-08-06 18:05:00.384304 [DEBUG] switch_channel.c:1310 EXPORT (export_vars) [origination_callee_id_name]=[XXXXXXXXXX]
EXECUTE [depth=0] sofia/internal/500@45.32.XXX.XXX hash(insert/45.32.XXX.XXX-last_dial/500/XXXXXXXXXX)
EXECUTE [depth=0] sofia/internal/500@45.32.XXX.XXX set(sip_h_X-accountcode=45.32.XXX.XXX)
2021-08-06 18:05:00.384304 [DEBUG] mod_dptools.c:1685 SET sofia/internal/500@45.32.XXX.XXX [sip_h_X-accountcode]=[45.32.XXX.XXX]
EXECUTE [depth=0] sofia/internal/500@45.32.XXX.XXX export(call_direction=outbound)
2021-08-06 18:05:00.384304 [DEBUG] switch_channel.c:1310 EXPORT (export_vars) [call_direction]=[outbound]
EXECUTE [depth=0] sofia/internal/500@45.32.XXX.XXX unset(call_timeout)
2021-08-06 18:05:00.384304 [DEBUG] mod_dptools.c:1830 UNSET [call_timeout]
EXECUTE [depth=0] sofia/internal/500@45.32.XXX.XXX set(hangup_after_bridge=true)
2021-08-06 18:05:00.384304 [DEBUG] mod_dptools.c:1685 SET sofia/internal/500@45.32.XXX.XXX [hangup_after_bridge]=[true]
EXECUTE [depth=0] sofia/internal/500@45.32.XXX.XXX set(effective_caller_id_name=)
2021-08-06 18:05:00.384304 [DEBUG] mod_dptools.c:1685 SET sofia/internal/500@45.32.XXX.XXX [effective_caller_id_name]=[UNDEF]
EXECUTE [depth=0] sofia/internal/500@45.32.XXX.XXX set(effective_caller_id_number=)
2021-08-06 18:05:00.384304 [DEBUG] mod_dptools.c:1685 SET sofia/internal/500@45.32.XXX.XXX [effective_caller_id_number]=[UNDEF]
EXECUTE [depth=0] sofia/internal/500@45.32.XXX.XXX set(inherit_codec=true)
2021-08-06 18:05:00.384304 [DEBUG] mod_dptools.c:1685 SET sofia/internal/500@45.32.XXX.XXX [inherit_codec]=[true]
EXECUTE [depth=0] sofia/internal/500@45.32.XXX.XXX set(ignore_display_updates=true)
2021-08-06 18:05:00.384304 [DEBUG] mod_dptools.c:1685 SET sofia/internal/500@45.32.XXX.XXX [ignore_display_updates]=[true]
EXECUTE [depth=0] sofia/internal/500@45.32.XXX.XXX set(callee_id_number=XXXXXXXXXX)
2021-08-06 18:05:00.384304 [DEBUG] mod_dptools.c:1685 SET sofia/internal/500@45.32.XXX.XXX [callee_id_number]=[XXXXXXXXXX]
EXECUTE [depth=0] sofia/internal/500@45.32.XXX.XXX set(continue_on_fail=1,2,3,6,18,21,27,28,31,34,38,41,42,44,58,88,111,403,501,602,607)
2021-08-06 18:05:00.384304 [DEBUG] mod_dptools.c:1685 SET sofia/internal/500@45.32.XXX.XXX [continue_on_fail]=[1,2,3,6,18,21,27,28,31,34,38,41,42,44,58,88,111,403,501,602,607]
EXECUTE [depth=0] sofia/internal/500@45.32.XXX.XXX bridge(sofia/gateway/456f43de-01ab-421e-9bb3-c812c5b9e5c3/XXXXXXXXXX)
2021-08-06 18:05:00.384304 [DEBUG] switch_channel.c:1264 sofia/internal/500@45.32.XXX.XXX EXPORTING[export_vars] [domain_name]=[45.32.XXX.XXX] to event
2021-08-06 18:05:00.384304 [DEBUG] switch_channel.c:1264 sofia/internal/500@45.32.XXX.XXX EXPORTING[export_vars] [call_direction]=[outbound] to event
2021-08-06 18:05:00.384304 [DEBUG] switch_channel.c:1264 sofia/internal/500@45.32.XXX.XXX EXPORTING[export_vars] [origination_callee_id_name]=[XXXXXXXXXX] to event
2021-08-06 18:05:00.384304 [DEBUG] switch_channel.c:1264 sofia/internal/500@45.32.XXX.XXX EXPORTING[export_vars] [call_direction]=[outbound] to event
2021-08-06 18:05:00.384304 [DEBUG] switch_ivr_originate.c:2272 Parsing global variables
2021-08-06 18:05:00.384304 [NOTICE] switch_channel.c:1118 New Channel sofia/external/XXXXXXXXXX [6fc678ca-576d-4607-8fd9-28a9c54aa149]
2021-08-06 18:05:00.384304 [DEBUG] mod_sofia.c:5102 (sofia/external/XXXXXXXXXX) State Change CS_NEW -> CS_INIT
2021-08-06 18:05:00.384304 [DEBUG] switch_core_state_machine.c:585 (sofia/external/XXXXXXXXXX) Running State Change CS_INIT (Cur 2 Tot 11)
2021-08-06 18:05:00.384304 [DEBUG] switch_core_state_machine.c:628 (sofia/external/XXXXXXXXXX) State INIT
2021-08-06 18:05:00.384304 [DEBUG] mod_sofia.c:93 sofia/external/XXXXXXXXXX SOFIA INIT
2021-08-06 18:05:00.384304 [INFO] sofia_glue.c:1621 sofia/external/XXXXXXXXXX sending invite call-id: (null)
2021-08-06 18:05:00.384304 [DEBUG] sofia_glue.c:1624 sofia/external/XXXXXXXXXX sending invite version: 1.10.6 -release-18-1ff9d0a60e 64bit
Local SDP:
v=0
o=FreeSWITCH 1628246468 1628246469 IN IP4 45.32.XXX.XXX
s=FreeSWITCH
c=IN IP4 45.32.XXX.XXX
t=0 0
m=audio 26632 RTP/AVP 8 0 101
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSuppff - - - -
a=ptime:20
a=sendrecv

2021-08-06 18:05:00.384304 [DEBUG] switch_core_state_machine.c:40 sofia/external/XXXXXXXXXX Standard INIT
2021-08-06 18:05:00.384304 [DEBUG] switch_core_state_machine.c:48 (sofia/external/XXXXXXXXXX) State Change CS_INIT -> CS_ROUTING
2021-08-06 18:05:00.384304 [DEBUG] switch_core_state_machine.c:628 (sofia/external/XXXXXXXXXX) State INIT going to sleep
2021-08-06 18:05:00.384304 [DEBUG] switch_core_state_machine.c:585 (sofia/external/XXXXXXXXXX) Running State Change CS_ROUTING (Cur 2 Tot 11)
2021-08-06 18:05:00.384304 [DEBUG] sofia.c:7406 Channel sofia/external/XXXXXXXXXX entering state [calling][0]
2021-08-06 18:05:00.384304 [DEBUG] switch_core_state_machine.c:644 (sofia/external/XXXXXXXXXX) State ROUTING
2021-08-06 18:05:00.384304 [DEBUG] mod_sofia.c:154 sofia/external/XXXXXXXXXX SOFIA ROUTING
2021-08-06 18:05:00.384304 [DEBUG] switch_ivr_originate.c:67 (sofia/external/XXXXXXXXXX) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2021-08-06 18:05:00.384304 [DEBUG] switch_core_state_machine.c:644 (sofia/external/XXXXXXXXXX) State ROUTING going to sleep
2021-08-06 18:05:00.384304 [DEBUG] switch_core_state_machine.c:585 (sofia/external/XXXXXXXXXX) Running State Change CS_CONSUME_MEDIA (Cur 2 Tot 11)
2021-08-06 18:05:00.384304 [DEBUG] switch_core_state_machine.c:663 (sofia/external/XXXXXXXXXX) State CONSUME_MEDIA
2021-08-06 18:05:00.384304 [DEBUG] switch_core_state_machine.c:663 (sofia/external/XXXXXXXXXX) State CONSUME_MEDIA going to sleep
2021-08-06 18:05:00.584318 [DEBUG] sofia.c:7406 Channel sofia/external/XXXXXXXXXX entering state [calling][0]
2021-08-06 18:05:00.824347 [DEBUG] sofia.c:6576 Remote Reason: 21
2021-08-06 18:05:00.824347 [DEBUG] sofia.c:7406 Channel sofia/external/XXXXXXXXXX entering state [terminated][403]
2021-08-06 18:05:00.824347 [NOTICE] sofia.c:8641 Hangup sofia/external/XXXXXXXXXX [CS_CONSUME_MEDIA] [CALL_REJECTED]
2021-08-06 18:05:00.824347 [DEBUG] switch_core_state_machine.c:585 (sofia/external/XXXXXXXXXX) Running State Change CS_HANGUP (Cur 2 Tot 11)
2021-08-06 18:05:00.824347 [DEBUG] switch_core_state_machine.c:848 (sofia/external/XXXXXXXXXX) Callstate Change DOWN -> HANGUP
2021-08-06 18:05:00.824347 [DEBUG] switch_core_state_machine.c:850 (sofia/external/XXXXXXXXXX) State HANGUP
2021-08-06 18:05:00.824347 [DEBUG] mod_sofia.c:453 Channel sofia/external/XXXXXXXXXX hanging up, cause: CALL_REJECTED
2021-08-06 18:05:00.824347 [DEBUG] switch_core_state_machine.c:60 sofia/external/XXXXXXXXXX Standard HANGUP, cause: CALL_REJECTED
2021-08-06 18:05:00.824347 [DEBUG] switch_core_state_machine.c:850 (sofia/external/XXXXXXXXXX) State HANGUP going to sleep
2021-08-06 18:05:00.824347 [DEBUG] switch_core_state_machine.c:620 (sofia/external/XXXXXXXXXX) State Change CS_HANGUP -> CS_REPORTING
2021-08-06 18:05:00.824347 [DEBUG] switch_core_state_machine.c:585 (sofia/external/XXXXXXXXXX) Running State Change CS_REPORTING (Cur 2 Tot 11)
2021-08-06 18:05:00.824347 [DEBUG] switch_core_state_machine.c:936 (sofia/external/XXXXXXXXXX) State REPORTING
2021-08-06 18:05:00.824347 [DEBUG] switch_core_state_machine.c:174 sofia/external/XXXXXXXXXX Standard REPORTING, cause: CALL_REJECTED
2021-08-06 18:05:00.824347 [DEBUG] switch_core_state_machine.c:936 (sofia/external/XXXXXXXXXX) State REPORTING going to sleep
2021-08-06 18:05:00.824347 [DEBUG] switch_core_state_machine.c:611 (sofia/external/XXXXXXXXXX) State Change CS_REPORTING -> CS_DESTROY
2021-08-06 18:05:00.824347 [DEBUG] switch_core_session.c:1736 Session 11 (sofia/external/XXXXXXXXXX) Locked, Waiting on external entities
2021-08-06 18:05:00.844328 [DEBUG] switch_ivr_originate.c:4026 Originate Resulted in Error Cause: 21 [CALL_REJECTED]
2021-08-06 18:05:00.844328 [INFO] mod_dptools.c:3643 Originate Failed. Cause: CALL_REJECTED
2021-08-06 18:05:00.844328 [DEBUG] switch_channel.c:4873 Continue on fail [1,2,3,6,18,21,27,28,31,34,38,41,42,44,58,88,111,403,501,602,607]: Cause: CALL_REJECTED
2021-08-06 18:05:00.844328 [NOTICE] switch_core_state_machine.c:386 sofia/internal/500@45.32.XXX.XXX has executed the last dialplan instruction, hanging up.
2021-08-06 18:05:00.844328 [NOTICE] switch_core_state_machine.c:388 Hangup sofia/internal/500@45.32.XXX.XXX [CS_EXECUTE] [NORMAL_CLEARING]
2021-08-06 18:05:00.844328 [DEBUG] switch_core_state_machine.c:651 (sofia/internal/500@45.32.XXX.XXX) State EXECUTE going to sleep
2021-08-06 18:05:00.844328 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/500@45.32.XXX.XXX) Running State Change CS_HANGUP (Cur 2 Tot 11)
2021-08-06 18:05:00.844328 [DEBUG] switch_core_state_machine.c:848 (sofia/internal/500@45.32.XXX.XXX) Callstate Change RINGING -> HANGUP
2021-08-06 18:05:00.844328 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/500@45.32.XXX.XXX) State HANGUP
2021-08-06 18:05:00.844328 [DEBUG] mod_sofia.c:447 sofia/internal/500@45.32.XXX.XXX Overriding SIP cause 480 with 403 from the other leg
2021-08-06 18:05:00.844328 [DEBUG] mod_sofia.c:453 Channel sofia/internal/500@45.32.XXX.XXX hanging up, cause: NORMAL_CLEARING
2021-08-06 18:05:00.844328 [DEBUG] mod_sofia.c:598 Responding to INVITE with: 403
2021-08-06 18:05:00.844328 [DEBUG] switch_core_state_machine.c:60 sofia/internal/500@45.32.XXX.XXX Standard HANGUP, cause: NORMAL_CLEARING
2021-08-06 18:05:00.844328 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/500@45.32.XXX.XXX) State HANGUP going to sleep
2021-08-06 18:05:00.844328 [DEBUG] switch_core_state_machine.c:620 (sofia/internal/500@45.32.XXX.XXX) State Change CS_HANGUP -> CS_REPORTING
2021-08-06 18:05:00.844328 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/500@45.32.XXX.XXX) Running State Change CS_REPORTING (Cur 2 Tot 11)
2021-08-06 18:05:00.844328 [DEBUG] switch_core_state_machine.c:936 (sofia/internal/500@45.32.XXX.XXX) State REPORTING
2021-08-06 18:05:00.844328 [NOTICE] switch_core_session.c:1754 Session 11 (sofia/external/XXXXXXXXXX) Ended
2021-08-06 18:05:00.844328 [NOTICE] switch_core_session.c:1758 Close Channel sofia/external/XXXXXXXXXX [CS_DESTROY]
2021-08-06 18:05:00.844328 [DEBUG] switch_core_state_machine.c:739 (sofia/external/XXXXXXXXXX) Running State Change CS_DESTROY (Cur 1 Tot 11)
2021-08-06 18:05:00.844328 [DEBUG] switch_core_state_machine.c:749 (sofia/external/XXXXXXXXXX) State DESTROY
2021-08-06 18:05:00.844328 [DEBUG] mod_sofia.c:364 sofia/external/XXXXXXXXXX SOFIA DESTROY
2021-08-06 18:05:00.844328 [DEBUG] switch_core_state_machine.c:181 sofia/external/XXXXXXXXXX Standard DESTROY
2021-08-06 18:05:00.844328 [DEBUG] switch_core_state_machine.c:749 (sofia/external/XXXXXXXXXX) State DESTROY going to sleep
2021-08-06 18:05:00.924317 [DEBUG] switch_core_state_machine.c:174 sofia/internal/500@45.32.XXX.XXX Standard REPORTING, cause: NORMAL_CLEARING
2021-08-06 18:05:00.924317 [DEBUG] switch_core_state_machine.c:936 (sofia/internal/500@45.32.XXX.XXX) State REPORTING going to sleep
2021-08-06 18:05:00.924317 [DEBUG] switch_core_state_machine.c:611 (sofia/internal/500@45.32.XXX.XXX) State Change CS_REPORTING -> CS_DESTROY
2021-08-06 18:05:00.924317 [DEBUG] switch_core_session.c:1736 Session 10 (sofia/internal/500@45.32.XXX.XXX) Locked, Waiting on external entities
2021-08-06 18:05:00.924317 [NOTICE] switch_core_session.c:1754 Session 10 (sofia/internal/500@45.32.XXX.XXX) Ended
2021-08-06 18:05:00.924317 [NOTICE] switch_core_session.c:1758 Close Channel sofia/internal/500@45.32.XXX.XXX [CS_DESTROY]
2021-08-06 18:05:00.924317 [DEBUG] switch_core_state_machine.c:739 (sofia/internal/500@45.32.XXX.XXX) Running State Change CS_DESTROY (Cur 0 Tot 11)
2021-08-06 18:05:00.924317 [DEBUG] switch_core_state_machine.c:749 (sofia/internal/500@45.32.XXX.XXX) State DESTROY
2021-08-06 18:05:00.924317 [DEBUG] mod_sofia.c:364 sofia/internal/500@45.32.XXX.XXX SOFIA DESTROY
2021-08-06 18:05:00.924317 [DEBUG] switch_core_state_machine.c:181 sofia/internal/500@45.32.XXX.XXX Standard DESTROY
2021-08-06 18:05:00.924317 [DEBUG] switch_core_state_machine.c:749 (sofia/internal/500@45.32.XXX.XXX) State DESTROY going to sleep

fusionpbxnoaudio · Aug 7, 2021

21

603

CALL_REJECTED

call rejected [Q.850]

This cause indicates that the equipment sending this cause does not wish to accept this call, although it could have accepted the call because the equipment sending this cause is neither busy nor incompatible. The network may also generate this cause, indicating that the call was cleared due to a supplementary service constraint. The diagnostic field may contain additional information about the supplementary service and reason for rejection.

Your call doesn't event hit the gateway as there is no acknowledgement from the gateway for the invite, is the gateway configured and running?

fusionpbxnoaudio · Aug 7, 2021

Your outbound calls has call-id of null which may be a reason

021-08-06 18:05:00.384304 [DEBUG] switch_core_state_machine.c:628 (sofia/external/XXXXXXXXXX) State INIT
2021-08-06 18:05:00.384304 [DEBUG] mod_sofia.c:93 sofia/external/XXXXXXXXXX SOFIA INIT
2021-08-06 18:05:00.384304 [INFO] sofia_glue.c:1621 sofia/external/XXXXXXXXXX sending invite call-id: (null)
2021-08-06 18:05:00.384304 [DEBUG] sofia_glue.c:1624 sofia/external/XXXXXXXXXX sending invite version: 1.10.6 -release-18-1ff9d0a60e 64bit

vgarcia · Aug 8, 2021

fusionpbxnoaudio said:
Your outbound calls has call-id of null which may be a reason

021-08-06 18:05:00.384304 [DEBUG] switch_core_state_machine.c:628 (sofia/external/XXXXXXXXXX) State INIT 2021-08-06 18:05:00.384304 [DEBUG] mod_sofia.c:93 sofia/external/XXXXXXXXXX SOFIA INIT 2021-08-06 18:05:00.384304 [INFO] sofia_glue.c:1621 sofia/external/XXXXXXXXXX sending invite call-id: (null) 2021-08-06 18:05:00.384304 [DEBUG] sofia_glue.c:1624 sofia/external/XXXXXXXXXX sending invite version: 1.10.6 -release-18-1ff9d0a60e 64bit

How do I go about fixing that?

cp6183 · Aug 8, 2021

I am receiving the same error, however, its a hit or miss. Sometimes I receive 403 and sometimes outbound works. It is intermittently

The from field is the IP address of the phone, not the extension.

vgarcia · Aug 8, 2021

fusionpbxnoaudio said:
21 603 CALL_REJECTED call rejected [Q.850] This cause indicates that the equipment sending this cause does not wish to accept this call, although it could have accepted the call because the equipment sending this cause is neither busy nor incompatible. The network may also generate this cause, indicating that the call was cleared due to a supplementary service constraint. The diagnostic field may contain additional information about the supplementary service and reason for rejection.

Your call doesn't event hit the gateway as there is no acknowledgement from the gateway for the invite, is the gateway configured and running?

The gateway is configured, I use Telnyx and the inbound works fine, just can't get outbound working.

I used https://developers.telnyx.com/docs/v2/sip-trunking/bring-your-own-carrier/fusionpbx to configure the gateway.

DavidDec · Aug 9, 2021

We've found our gateways work best when the register is set to false and profile to internal, if you hit advanced and make sure called ID from is set to true. 403 usually turns out to be the SBC rejecting the call due to the PAID headers, Make sure every extension has full caller ID details in external and emergency fields.

Although reading that Telnyx its done very differently to our supplier...

vgarcia · Aug 9, 2021

DavidDec said:
We've found our gateways work best when the register is set to false and profile to internal, if you hit advanced and make sure called ID from is set to true. 403 usually turns out to be the SBC rejecting the call due to the PAID headers, Make sure every extension has full caller ID details in external and emergency fields.

Although reading that Telnyx its done very differently to our supplier...

Hello David, thanks for the recommendation. Unfortunately, this did not work.

DavidDec · Aug 9, 2021

And silly question time but you have an outbound profile created on Telnyx? https://support.telnyx.com/en/articles/4320411-more-about-outbound-voice-profiles

Are the logs still showing Caller ID as null? "[DEBUG] mod_dptools.c:1685 SET sofia/internal/500@45.32.XXX.XXX [outbound_caller_id_number]=[UNDEF]"

vgarcia · Aug 9, 2021

DavidDec said:
And silly question time but you have an outbound profile created on Telnyx? https://support.telnyx.com/en/articles/4320411-more-about-outbound-voice-profiles

Are the logs still showing Caller ID as null? "[DEBUG] mod_dptools.c:1685 SET sofia/internal/500@45.32.XXX.XXX [outbound_caller_id_number]=[UNDEF]"

David! You got me with the outbound profile. stupid me never changed it from my FreePBX one. thanks so much!

cp6183 · Aug 9, 2021

any insight on my issue?

Search

Search

Outbound Calls 403 Forbidden

vgarcia

New Member

fusionpbxnoaudio

Member

vgarcia

New Member

fusionpbxnoaudio

Member

fusionpbxnoaudio

Member

vgarcia

New Member

cp6183

Member

vgarcia

New Member

DavidDec

Member

vgarcia

New Member

DavidDec

Member

vgarcia

New Member

cp6183

Member