Hi all,
I seem to be really struggling with my current fusionpbx install. I am running Debian 13 and Fusionpbx 5.5.13, no matter what I try I cannot get outbound calls to work. My incoming and internal work without hassle. When I try to make a call it last for exactly 32 seconds and then times out. It seems when the call is initiated my sip provider requests auth for the gateway and when fusion sends it there is dead silence and the call times out. I have tried with a different sip providers details as well and the exact same thing happens. I have tested my sip details directly on a softphone and the calls route out. I have build a few fusion systems and have never ran into such a problem. Any help would really be appreciated.
+OK log level [7]
2026-08-24 20:03:57.900243 97.97% [NOTICE] switch_channel.c:1143 New Channel sofia/internal/1003@aitivopabx.aitivo.co.za [3cc5e362-ff60-4aea-ad9d-e83d6a678de7]
2026-08-24 20:03:57.900243 97.97% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/1003@aitivopabx.aitivo.co.za) Running State Change CS_NEW (Cur 1 Tot 64)
2026-08-24 20:03:57.900243 97.97% [INFO] sofia.c:10472 sofia/internal/1003@aitivopabx.aitivo.co.za receiving invite from 165.73.39.93:64280 version: 1.11.2-release git 3f13ad1 2026-08-09 16:23:10Z 64bit call-id: 7d96abb28487474b838f446d9eae409d
2026-08-24 20:03:57.900243 97.97% [DEBUG] sofia.c:10566 verifying acl "providers" for ip/port 165.73.39.93:0.
2026-08-24 20:03:57.900243 97.97% [DEBUG] switch_core_state_machine.c:600 (sofia/internal/1003@aitivopabx.aitivo.co.za) State NEW
2026-08-24 20:03:57.900243 97.97% [DEBUG] sofia.c:2408 detaching session 3cc5e362-ff60-4aea-ad9d-e83d6a678de7
2026-08-24 20:03:57.940230 97.97% [DEBUG] sofia.c:2523 Re-attaching to session 3cc5e362-ff60-4aea-ad9d-e83d6a678de7
2026-08-24 20:03:57.960243 97.97% [INFO] sofia.c:10472 sofia/internal/1003@aitivopabx.aitivo.co.za receiving invite from 165.73.39.93:64280 version: 1.11.2-release git 3f13ad1 2026-08-09 16:23:10Z 64bit call-id: 7d96abb28487474b838f446d9eae409d
2026-08-24 20:03:57.960243 97.97% [DEBUG] sofia.c:10566 verifying acl "providers" for ip/port 165.73.39.93:0.
2026-08-24 20:03:57.960243 97.97% [DEBUG] sofia.c:11687 Setting NAT mode based on nat.auto
2026-08-24 20:03:57.960243 97.97% [DEBUG] sofia.c:7505 Channel sofia/internal/1003@aitivopabx.aitivo.co.za entering state [received][100]
2026-08-24 20:03:57.960243 97.97% [DEBUG] sofia.c:7515 Remote SDP:
v=0
o=- 3996590637 3996590637 IN IP4 192.168.26.132
s=pjmedia
b=AS:84
t=0 0
a=X-nat:0
m=audio 4052 RTP/AVP 0 18 101
c=IN IP4 192.168.26.132
b=TIAS:64000
a=rtpmap:0 PCMU/8000
a=rtpmap:18 G729/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=rtcp:4053 IN IP4 192.168.26.132
a=ssrc:143477049 cname:7aae4e0d32e070c4
2026-08-24 20:03:57.960243 97.97% [DEBUG] switch_core_media.c:5548 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2026-08-24 20:03:57.960243 97.97% [DEBUG] switch_core_media.c:5548 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2026-08-24 20:03:57.960243 97.97% [DEBUG] switch_core_media.c:5610 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
2026-08-24 20:03:57.960243 97.97% [DEBUG] switch_core_media.c:5548 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2026-08-24 20:03:57.960243 97.97% [DEBUG] switch_core_media.c:5548 Audio Codec Compare [G729:18:8000:20:8000:1]/[G722:9:8000:20:64000:1]
2026-08-24 20:03:57.960243 97.97% [DEBUG] switch_core_media.c:5548 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMU:0:8000:20:64000:1]
2026-08-24 20:03:57.960243 97.97% [DEBUG] switch_core_media.c:5548 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMA:8:8000:20:64000:1]
2026-08-24 20:03:57.960243 97.97% [DEBUG] switch_core_media.c:5460 Set telephone-event payload to 101@8000
2026-08-24 20:03:57.960243 97.97% [DEBUG] switch_core_media.c:3745 Set Codec sofia/internal/1003@aitivopabx.aitivo.co.za PCMU/8000 20 ms 160 samples 64000 bits 1 channels
2026-08-24 20:03:57.960243 97.97% [DEBUG] switch_core_codec.c:132 sofia/internal/1003@aitivopabx.aitivo.co.za Original read codec set to PCMU:0
2026-08-24 20:03:57.960243 97.97% [DEBUG] switch_core_media.c:5820 Set telephone-event payload to 101@8000
2026-08-24 20:03:57.960243 97.97% [DEBUG] switch_core_media.c:5878 sofia/internal/1003@aitivopabx.aitivo.co.za Set 2833 dtmf send payload to 101 recv payload to 101
2026-08-24 20:03:57.960243 97.97% [DEBUG] sofia.c:7939 (sofia/internal/1003@aitivopabx.aitivo.co.za) State Change CS_NEW -> CS_INIT
2026-08-24 20:03:57.960243 97.97% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/1003@aitivopabx.aitivo.co.za) Running State Change CS_INIT (Cur 1 Tot 64)
2026-08-24 20:03:57.960243 97.97% [DEBUG] switch_core_state_machine.c:624 (sofia/internal/1003@aitivopabx.aitivo.co.za) State INIT
2026-08-24 20:03:57.960243 97.97% [DEBUG] mod_sofia.c:97 sofia/internal/1003@aitivopabx.aitivo.co.za SOFIA INIT
2026-08-24 20:03:57.960243 97.97% [DEBUG] switch_core_state_machine.c:40 sofia/internal/1003@aitivopabx.aitivo.co.za Standard INIT
2026-08-24 20:03:57.960243 97.97% [DEBUG] switch_core_state_machine.c:48 (sofia/internal/1003@aitivopabx.aitivo.co.za) State Change CS_INIT -> CS_ROUTING
2026-08-24 20:03:57.960243 97.97% [DEBUG] switch_core_state_machine.c:624 (sofia/internal/1003@aitivopabx.aitivo.co.za) State INIT going to sleep
2026-08-24 20:03:57.960243 97.97% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/1003@aitivopabx.aitivo.co.za) Running State Change CS_ROUTING (Cur 1 Tot 64)
2026-08-24 20:03:57.960243 97.97% [DEBUG] switch_channel.c:2400 (sofia/internal/1003@aitivopabx.aitivo.co.za) Callstate Change DOWN -> RINGING
2026-08-24 20:03:57.960243 97.97% [DEBUG] switch_core_state_machine.c:640 (sofia/internal/1003@aitivopabx.aitivo.co.za) State ROUTING
2026-08-24 20:03:57.960243 97.97% [DEBUG] mod_sofia.c:158 sofia/internal/1003@aitivopabx.aitivo.co.za SOFIA ROUTING
2026-08-24 20:03:57.960243 97.97% [DEBUG] switch_core_state_machine.c:230 sofia/internal/1003@aitivopabx.aitivo.co.za Standard ROUTING
2026-08-24 20:03:57.960243 97.97% [INFO] mod_dialplan_xml.c:648 Processing Dean <1003>->27836282655 in context aitivopabx.aitivo.co.za
2026-08-24 20:03:57.980233 97.97% [NOTICE] switch_cpp.cpp:1466 [xml_handler] single key:dialplan:aitivopabx.aitivo.co.za
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za parsing [aitivopabx.aitivo.co.za->user_exists] continue=1
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (FAIL) [user_exists] ${loopback_leg}() =~ /^B$/ break=never
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (PASS) [user_exists] () =~ // break=on-false
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Action set(user_exists=${user_exists id ${destination_number} ${domain_name}}) INLINE
EXECUTE [depth=0] sofia/internal/1003@aitivopabx.aitivo.co.za set(user_exists=false)
2026-08-24 20:03:58.000228 97.97% [DEBUG] mod_dptools.c:1671 SET sofia/internal/1003@aitivopabx.aitivo.co.za [user_exists]=[false]
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Action set(from_user_exists=${user_exists id ${sip_from_user} ${sip_from_host}}) INLINE
EXECUTE [depth=0] sofia/internal/1003@aitivopabx.aitivo.co.za set(from_user_exists=true)
2026-08-24 20:03:58.000228 97.97% [DEBUG] mod_dptools.c:1671 SET sofia/internal/1003@aitivopabx.aitivo.co.za [from_user_exists]=[true]
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (FAIL) [user_exists] ${user_exists}(false) =~ /^true$/ break=on-false
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za parsing [aitivopabx.aitivo.co.za->caller-details] continue=1
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (PASS) [caller-details] ${caller_destination}() =~ /^$/ break=never
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Action set(caller_destination=${destination_number}) INLINE
EXECUTE [depth=0] sofia/internal/1003@aitivopabx.aitivo.co.za set(caller_destination=27836282655)
2026-08-24 20:03:58.000228 97.97% [DEBUG] mod_dptools.c:1671 SET sofia/internal/1003@aitivopabx.aitivo.co.za [caller_destination]=[27836282655]
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Action set(caller_id_name=${caller_id_name}) INLINE
EXECUTE [depth=0] sofia/internal/1003@aitivopabx.aitivo.co.za set(caller_id_name=1003)
2026-08-24 20:03:58.000228 97.97% [DEBUG] mod_dptools.c:1671 SET sofia/internal/1003@aitivopabx.aitivo.co.za [caller_id_name]=[1003]
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Action set(caller_id_number=${caller_id_number})
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za parsing [aitivopabx.aitivo.co.za->global-variables] continue=1
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (PASS) [global-variables] () =~ // break=on-false
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Action set(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Action set(record_ext=mp3) INLINE
EXECUTE [depth=0] sofia/internal/1003@aitivopabx.aitivo.co.za set(record_ext=mp3)
2026-08-24 20:03:58.000228 97.97% [DEBUG] mod_dptools.c:1671 SET sofia/internal/1003@aitivopabx.aitivo.co.za [record_ext]=[mp3]
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za parsing [aitivopabx.aitivo.co.za->domain-variables] continue=1
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (PASS) [domain-variables] () =~ // break=on-false
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Action export(origination_callee_id_name=${caller_destination})
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Action set(operator=1000) INLINE
EXECUTE [depth=0] sofia/internal/1003@aitivopabx.aitivo.co.za set(operator=1000)
2026-08-24 20:03:58.000228 97.97% [DEBUG] mod_dptools.c:1671 SET sofia/internal/1003@aitivopabx.aitivo.co.za [operator]=[1000]
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za parsing [aitivopabx.aitivo.co.za->call_direction-outbound.d420] continue=1
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (PASS) [call_direction-outbound.d420] ${user_exists}(false) =~ /false/ break=on-false
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (PASS) [call_direction-outbound.d420] ${call_direction}() =~ /^$/ break=on-false
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (PASS) [call_direction-outbound.d420] destination_number(27836282655) =~ /^\+?(\d{4,20})$/ break=on-false
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Action export(call_direction=outbound) INLINE
EXECUTE [depth=0] sofia/internal/1003@aitivopabx.aitivo.co.za export(call_direction=outbound)
2026-08-24 20:03:58.000228 97.97% [DEBUG] switch_channel.c:1335 EXPORT (export_vars) [call_direction]=[outbound]
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za parsing [aitivopabx.aitivo.co.za->clear_sip_auto_answer] continue=1
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (FAIL) [clear_sip_auto_answer] ${click_to_call}() =~ /true/ break=on-false
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za parsing [aitivopabx.aitivo.co.za->call-direction] continue=1
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (FAIL) [call-direction] ${call_direction}(outbound) =~ /^$/ break=never
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za parsing [aitivopabx.aitivo.co.za->user_record] continue=1
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (FAIL) [user_record] ${user_record}() =~ /^all$/ break=never
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (FAIL) [user_record] ${call_direction}(outbound) =~ /^inbound$/ break=never
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (FAIL) [user_record] ${user_record}() =~ /^inbound$/ break=never
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (PASS) [user_record] ${call_direction}(outbound) =~ /^outbound$/ break=never
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (FAIL) [user_record] ${user_record}() =~ /^outbound$/ break=never
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (FAIL) [user_record] ${call_direction}(outbound) =~ /^local$/ break=never
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (FAIL) [user_record] ${user_record}() =~ /^local$/ break=never
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Action set(from_user_record=${user_data ${sip_from_user}@${sip_from_host} var user_record}) INLINE
EXECUTE [depth=0] sofia/internal/1003@aitivopabx.aitivo.co.za set(from_user_record=)
2026-08-24 20:03:58.000228 97.97% [DEBUG] mod_dptools.c:1671 SET sofia/internal/1003@aitivopabx.aitivo.co.za [from_user_record]=[UNDEF]
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (FAIL) [user_record] ${from_user_record}() =~ /^all$/ break=never
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (FAIL) [user_record] ${call_direction}(outbound) =~ /^inbound$/ break=never
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (FAIL) [user_record] ${from_user_record}() =~ /^inbound$/ break=never
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (PASS) [user_record] ${call_direction}(outbound) =~ /^outbound$/ break=never
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (FAIL) [user_record] ${from_user_record}() =~ /^outbound$/ break=never
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (FAIL) [user_record] ${call_direction}(outbound) =~ /^local$/ break=never
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (FAIL) [user_record] ${from_user_record}() =~ /^local$/ break=never
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (FAIL) [user_record] ${record_session}() =~ /^true$/ break=on-false
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za parsing [aitivopabx.aitivo.co.za->rtp_has_crypto] continue=1
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za 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/1003@aitivopabx.aitivo.co.za parsing [aitivopabx.aitivo.co.za->redial] continue=1
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (FAIL) [redial] destination_number(27836282655) =~ /^(redial|\*870)$/ break=on-true
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (PASS) [redial] () =~ // break=never
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number})
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za parsing [aitivopabx.aitivo.co.za->emergency_recent_calls] continue=
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (FAIL) [emergency_recent_calls] destination_number(27836282655) =~ /^\*9411$/ break=on-true
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za parsing [aitivopabx.aitivo.co.za->speed_dial] continue=
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (FAIL) [speed_dial] destination_number(27836282655) =~ /^\*0(.*)$/ break=on-false
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za parsing [aitivopabx.aitivo.co.za->default_caller_id] continue=1
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (PASS) [default_caller_id] ${call_direction}(outbound) =~ /outbound/ break=on-false
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (PASS) [default_caller_id] ${emergency_caller_id_name}() =~ /^$/ break=never
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Action set(emergency_caller_id_name=${default_emergency_caller_id_name}) INLINE
EXECUTE [depth=0] sofia/internal/1003@aitivopabx.aitivo.co.za set(emergency_caller_id_name=)
2026-08-24 20:03:58.000228 97.97% [DEBUG] mod_dptools.c:1671 SET sofia/internal/1003@aitivopabx.aitivo.co.za [emergency_caller_id_name]=[UNDEF]
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (PASS) [default_caller_id] ${call_direction}(outbound) =~ /outbound/ break=on-false
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (PASS) [default_caller_id] ${emergency_caller_id_number}() =~ /^$/ break=never
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Action set(emergency_caller_id_number=${default_emergency_caller_id_number}) INLINE
EXECUTE [depth=0] sofia/internal/1003@aitivopabx.aitivo.co.za set(emergency_caller_id_number=)
2026-08-24 20:03:58.000228 97.97% [DEBUG] mod_dptools.c:1671 SET sofia/internal/1003@aitivopabx.aitivo.co.za [emergency_caller_id_number]=[UNDEF]
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (PASS) [default_caller_id] ${call_direction}(outbound) =~ /outbound/ break=on-false
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (PASS) [default_caller_id] ${loopback_leg}() =~ /^$/ break=on-false
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (PASS) [default_caller_id] ${outbound_caller_id_name}() =~ /^$/ break=never
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Action set(outbound_caller_id_name=${default_outbound_caller_id_name}) INLINE
EXECUTE [depth=0] sofia/internal/1003@aitivopabx.aitivo.co.za set(outbound_caller_id_name=)
2026-08-24 20:03:58.000228 97.97% [DEBUG] mod_dptools.c:1671 SET sofia/internal/1003@aitivopabx.aitivo.co.za [outbound_caller_id_name]=[UNDEF]
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (PASS) [default_caller_id] ${call_direction}(outbound) =~ /outbound/ break=on-false
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (PASS) [default_caller_id] ${loopback_leg}() =~ /^$/ break=on-false
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (FAIL) [default_caller_id] ${outbound_caller_id_number}(27101098291) =~ /^$/ break=never
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za parsing [aitivopabx.aitivo.co.za->user_hold_music] continue=1
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (FAIL) [user_hold_music] ${user_exists}(false) =~ /true/ break=on-false
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za parsing [aitivopabx.aitivo.co.za->default_hold_music] continue=1
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (FAIL) [default_hold_music] ${hold_music}(local_stream://default) =~ /^$/ break=on-false
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za parsing [aitivopabx.aitivo.co.za->sessiontelecoms.d420] continue=
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (PASS) [sessiontelecoms.d420] ${user_exists}(false) =~ /false/ break=on-false
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (PASS) [sessiontelecoms.d420] destination_number(27836282655) =~ /^\+?(\d{4,20})$/ break=on-false
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Action export(call_direction=outbound) INLINE
EXECUTE [depth=0] sofia/internal/1003@aitivopabx.aitivo.co.za export(call_direction=outbound)
2026-08-24 20:03:58.000228 97.97% [DEBUG] switch_channel.c:1335 EXPORT (export_vars) [call_direction]=[outbound]
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Action unset(call_timeout)
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Action set(hangup_after_bridge=true)
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Action set(effective_caller_id_name=${outbound_caller_id_name})
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Action set(effective_caller_id_number=${outbound_caller_id_number})
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Action set(inherit_codec=true)
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Action set(ignore_display_updates=true)
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Action set(callee_id_number=27836282655)
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za 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,809)
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Action bridge(sofia/gateway/d363b3f7-f46c-46b5-9ea3-e2a38b6f8546/27836282655)
2026-08-24 20:03:58.000228 97.97% [DEBUG] switch_core_state_machine.c:281 (sofia/internal/1003@aitivopabx.aitivo.co.za) State Change CS_ROUTING -> CS_EXECUTE
2026-08-24 20:03:58.000228 97.97% [DEBUG] switch_core_state_machine.c:640 (sofia/internal/1003@aitivopabx.aitivo.co.za) State ROUTING going to sleep
2026-08-24 20:03:58.000228 97.97% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/1003@aitivopabx.aitivo.co.za) Running State Change CS_EXECUTE (Cur 1 Tot 64)
2026-08-24 20:03:58.000228 97.97% [DEBUG] switch_core_state_machine.c:647 (sofia/internal/1003@aitivopabx.aitivo.co.za) State EXECUTE
2026-08-24 20:03:58.000228 97.97% [DEBUG] mod_sofia.c:213 sofia/internal/1003@aitivopabx.aitivo.co.za SOFIA EXECUTE
2026-08-24 20:03:58.000228 97.97% [DEBUG] switch_core_state_machine.c:323 sofia/internal/1003@aitivopabx.aitivo.co.za Standard EXECUTE
EXECUTE [depth=0] sofia/internal/1003@aitivopabx.aitivo.co.za set(caller_id_number=1003)
2026-08-24 20:03:58.000228 97.97% [DEBUG] mod_dptools.c:1671 SET sofia/internal/1003@aitivopabx.aitivo.co.za [caller_id_number]=[1003]
EXECUTE [depth=0] sofia/internal/1003@aitivopabx.aitivo.co.za set(RFC2822_DATE=Mon, 24 Aug 2026 20:03:58 +0200)
2026-08-24 20:03:58.000228 97.97% [DEBUG] mod_dptools.c:1671 SET sofia/internal/1003@aitivopabx.aitivo.co.za [RFC2822_DATE]=[Mon, 24 Aug 2026 20:03:58 +0200]
EXECUTE [depth=0] sofia/internal/1003@aitivopabx.aitivo.co.za export(origination_callee_id_name=27836282655)
2026-08-24 20:03:58.000228 97.97% [DEBUG] switch_channel.c:1335 EXPORT (export_vars) [origination_callee_id_name]=[27836282655]
EXECUTE [depth=0] sofia/internal/1003@aitivopabx.aitivo.co.za hash(insert/aitivopabx.aitivo.co.za-last_dial/1003/27836282655)
EXECUTE [depth=0] sofia/internal/1003@aitivopabx.aitivo.co.za unset(call_timeout)
2026-08-24 20:03:58.000228 97.97% [DEBUG] mod_dptools.c:1816 UNSET [call_timeout]
EXECUTE [depth=0] sofia/internal/1003@aitivopabx.aitivo.co.za set(hangup_after_bridge=true)
2026-08-24 20:03:58.000228 97.97% [DEBUG] mod_dptools.c:1671 SET sofia/internal/1003@aitivopabx.aitivo.co.za [hangup_after_bridge]=[true]
EXECUTE [depth=0] sofia/internal/1003@aitivopabx.aitivo.co.za set(effective_caller_id_name=)
2026-08-24 20:03:58.000228 97.97% [DEBUG] mod_dptools.c:1671 SET sofia/internal/1003@aitivopabx.aitivo.co.za [effective_caller_id_name]=[UNDEF]
EXECUTE [depth=0] sofia/internal/1003@aitivopabx.aitivo.co.za set(effective_caller_id_number=27101098291)
2026-08-24 20:03:58.020211 97.97% [DEBUG] mod_dptools.c:1671 SET sofia/internal/1003@aitivopabx.aitivo.co.za [effective_caller_id_number]=[27101098291]
EXECUTE [depth=0] sofia/internal/1003@aitivopabx.aitivo.co.za set(inherit_codec=true)
2026-08-24 20:03:58.020211 97.97% [DEBUG] mod_dptools.c:1671 SET sofia/internal/1003@aitivopabx.aitivo.co.za [inherit_codec]=[true]
EXECUTE [depth=0] sofia/internal/1003@aitivopabx.aitivo.co.za set(ignore_display_updates=true)
2026-08-24 20:03:58.020211 97.97% [DEBUG] mod_dptools.c:1671 SET sofia/internal/1003@aitivopabx.aitivo.co.za [ignore_display_updates]=[true]
EXECUTE [depth=0] sofia/internal/1003@aitivopabx.aitivo.co.za set(callee_id_number=27836282655)
2026-08-24 20:03:58.020211 97.97% [DEBUG] mod_dptools.c:1671 SET sofia/internal/1003@aitivopabx.aitivo.co.za [callee_id_number]=[27836282655]
EXECUTE [depth=0] sofia/internal/1003@aitivopabx.aitivo.co.za 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,809)
2026-08-24 20:03:58.020211 97.97% [DEBUG] mod_dptools.c:1671 SET sofia/internal/1003@aitivopabx.aitivo.co.za [continue_on_fail]=[1,2,3,6,18,21,27,28,31,34,38,41,42,44,58,88,111,403,501,602,607,809]
EXECUTE [depth=0] sofia/internal/1003@aitivopabx.aitivo.co.za bridge(sofia/gateway/d363b3f7-f46c-46b5-9ea3-e2a38b6f8546/27836282655)
2026-08-24 20:03:58.020211 97.97% [DEBUG] switch_channel.c:1289 sofia/internal/1003@aitivopabx.aitivo.co.za EXPORTING[export_vars] [domain_name]=[aitivopabx.aitivo.co.za] to event
2026-08-24 20:03:58.020211 97.97% [DEBUG] switch_channel.c:1289 sofia/internal/1003@aitivopabx.aitivo.co.za EXPORTING[export_vars] [domain_uuid]=[9261725e-bdc6-4c59-9db5-d111b7310214] to event
2026-08-24 20:03:58.020211 97.97% [DEBUG] switch_channel.c:1289 sofia/internal/1003@aitivopabx.aitivo.co.za EXPORTING[export_vars] [call_direction]=[outbound] to event
2026-08-24 20:03:58.020211 97.97% [DEBUG] switch_channel.c:1289 sofia/internal/1003@aitivopabx.aitivo.co.za EXPORTING[export_vars] [call_direction]=[outbound] to event
2026-08-24 20:03:58.020211 97.97% [DEBUG] switch_channel.c:1289 sofia/internal/1003@aitivopabx.aitivo.co.za EXPORTING[export_vars] [origination_callee_id_name]=[27836282655] to event
2026-08-24 20:03:58.020211 97.97% [DEBUG] switch_ivr_originate.c:2301 Parsing global variables
2026-08-24 20:03:58.020211 97.97% [NOTICE] switch_channel.c:1143 New Channel sofia/external/27836282655 [55b92fa5-0afb-4484-94fa-01d188bfca5a]
2026-08-24 20:03:58.020211 97.97% [DEBUG] mod_sofia.c:5146 (sofia/external/27836282655) State Change CS_NEW -> CS_INIT
2026-08-24 20:03:58.020211 97.97% [DEBUG] switch_core_state_machine.c:581 (sofia/external/27836282655) Running State Change CS_INIT (Cur 2 Tot 65)
2026-08-24 20:03:58.020211 97.97% [DEBUG] switch_core_state_machine.c:624 (sofia/external/27836282655) State INIT
2026-08-24 20:03:58.020211 97.97% [DEBUG] mod_sofia.c:97 sofia/external/27836282655 SOFIA INIT
2026-08-24 20:03:58.020211 97.97% [INFO] sofia_glue.c:1656 sofia/external/27836282655 sending invite call-id: (null)
2026-08-24 20:03:58.020211 97.97% [DEBUG] sofia_glue.c:1659 sofia/external/27836282655 sending invite version: 1.11.2-release git 3f13ad1 2026-08-09 16:23:10Z 64bit
Local SDP:
v=0
o=FreeSWITCH 1787564444 1787564445 IN IP4 102.206.117.233
s=FreeSWITCH
c=IN IP4 102.206.117.233
t=0 0
m=audio 30194 RTP/AVP 0 8 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=silenceSupp
ff - - - -
a=ptime:20
a=sendrecv
2026-08-24 20:03:58.020211 97.97% [DEBUG] switch_core_state_machine.c:40 sofia/external/27836282655 Standard INIT
2026-08-24 20:03:58.020211 97.97% [DEBUG] switch_core_state_machine.c:48 (sofia/external/27836282655) State Change CS_INIT -> CS_ROUTING
2026-08-24 20:03:58.020211 97.97% [DEBUG] switch_core_state_machine.c:624 (sofia/external/27836282655) State INIT going to sleep
2026-08-24 20:03:58.020211 97.97% [DEBUG] switch_core_state_machine.c:581 (sofia/external/27836282655) Running State Change CS_ROUTING (Cur 2 Tot 65)
2026-08-24 20:03:58.020211 97.97% [DEBUG] switch_core_state_machine.c:640 (sofia/external/27836282655) State ROUTING
2026-08-24 20:03:58.020211 97.97% [DEBUG] mod_sofia.c:158 sofia/external/27836282655 SOFIA ROUTING
2026-08-24 20:03:58.020211 97.97% [DEBUG] switch_ivr_originate.c:67 (sofia/external/27836282655) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2026-08-24 20:03:58.020211 97.97% [DEBUG] switch_core_state_machine.c:640 (sofia/external/27836282655) State ROUTING going to sleep
2026-08-24 20:03:58.020211 97.97% [DEBUG] switch_core_state_machine.c:581 (sofia/external/27836282655) Running State Change CS_CONSUME_MEDIA (Cur 2 Tot 65)
2026-08-24 20:03:58.020211 97.97% [DEBUG] switch_core_state_machine.c:659 (sofia/external/27836282655) State CONSUME_MEDIA
2026-08-24 20:03:58.020211 97.97% [DEBUG] switch_core_state_machine.c:659 (sofia/external/27836282655) State CONSUME_MEDIA going to sleep
2026-08-24 20:03:58.020211 97.97% [DEBUG] sofia.c:7505 Channel sofia/external/27836282655 entering state [calling][0]
2026-08-24 20:03:58.020211 97.97% [DEBUG] sofia.c:7505 Channel sofia/external/27836282655 entering state [calling][0]
2026-08-24 20:04:30.020282 97.93% [DEBUG] sofia.c:7505 Channel sofia/external/27836282655 entering state [terminated][408]
2026-08-24 20:04:30.020282 97.93% [NOTICE] sofia.c:8748 Hangup sofia/external/27836282655 [CS_CONSUME_MEDIA] [RECOVERY_ON_TIMER_EXPIRE]
2026-08-24 20:04:30.040214 97.93% [DEBUG] switch_core_state_machine.c:581 (sofia/external/27836282655) Running State Change CS_HANGUP (Cur 2 Tot 65)
2026-08-24 20:04:30.040214 97.93% [DEBUG] switch_core_state_machine.c:844 (sofia/external/27836282655) Callstate Change DOWN -> HANGUP
2026-08-24 20:04:30.040214 97.93% [DEBUG] switch_core_state_machine.c:846 (sofia/external/27836282655) State HANGUP
2026-08-24 20:04:30.040214 97.93% [DEBUG] mod_sofia.c:469 Channel sofia/external/27836282655 hanging up, cause: RECOVERY_ON_TIMER_EXPIRE
2026-08-24 20:04:30.040214 97.93% [DEBUG] switch_core_state_machine.c:59 sofia/external/27836282655 Standard HANGUP, cause: RECOVERY_ON_TIMER_EXPIRE
2026-08-24 20:04:30.040214 97.93% [DEBUG] switch_core_state_machine.c:846 (sofia/external/27836282655) State HANGUP going to sleep
2026-08-24 20:04:30.040214 97.93% [DEBUG] switch_core_state_machine.c:616 (sofia/external/27836282655) State Change CS_HANGUP -> CS_REPORTING
2026-08-24 20:04:30.040214 97.93% [DEBUG] switch_core_state_machine.c:581 (sofia/external/27836282655) Running State Change CS_REPORTING (Cur 2 Tot 65)
2026-08-24 20:04:30.040214 97.93% [DEBUG] switch_core_state_machine.c:932 (sofia/external/27836282655) State REPORTING
2026-08-24 20:04:30.040214 97.93% [DEBUG] switch_core_state_machine.c:168 sofia/external/27836282655 Standard REPORTING, cause: RECOVERY_ON_TIMER_EXPIRE
2026-08-24 20:04:30.040214 97.93% [DEBUG] switch_core_state_machine.c:932 (sofia/external/27836282655) State REPORTING going to sleep
2026-08-24 20:04:30.040214 97.93% [DEBUG] switch_core_state_machine.c:607 (sofia/external/27836282655) State Change CS_REPORTING -> CS_DESTROY
2026-08-24 20:04:30.040214 97.93% [DEBUG] switch_core_session.c:1748 Session 65 (sofia/external/27836282655) Locked, Waiting on external entities
2026-08-24 20:04:30.040214 97.93% [DEBUG] switch_ivr_originate.c:4056 Originate Resulted in Error Cause: 102 [RECOVERY_ON_TIMER_EXPIRE]
2026-08-24 20:04:30.040214 97.93% [NOTICE] switch_core_session.c:1766 Session 65 (sofia/external/27836282655) Ended
2026-08-24 20:04:30.040214 97.93% [NOTICE] switch_core_session.c:1770 Close Channel sofia/external/27836282655 [CS_DESTROY]
2026-08-24 20:04:30.040214 97.93% [DEBUG] switch_core_state_machine.c:735 (sofia/external/27836282655) Running State Change CS_DESTROY (Cur 1 Tot 65)
2026-08-24 20:04:30.040214 97.93% [DEBUG] switch_core_state_machine.c:745 (sofia/external/27836282655) State DESTROY
2026-08-24 20:04:30.040214 97.93% [DEBUG] mod_sofia.c:380 sofia/external/27836282655 SOFIA DESTROY
2026-08-24 20:04:30.040214 97.93% [DEBUG] switch_core_state_machine.c:175 sofia/external/27836282655 Standard DESTROY
2026-08-24 20:04:30.040214 97.93% [DEBUG] switch_core_state_machine.c:745 (sofia/external/27836282655) State DESTROY going to sleep
2026-08-24 20:04:30.040214 97.93% [INFO] mod_dptools.c:3637 Originate Failed. Cause: RECOVERY_ON_TIMER_EXPIRE
2026-08-24 20:04:30.040214 97.93% [NOTICE] switch_channel.c:5016 Hangup sofia/internal/1003@aitivopabx.aitivo.co.za [CS_EXECUTE] [RECOVERY_ON_TIMER_EXPIRE]
2026-08-24 20:04:30.040214 97.93% [DEBUG] switch_core_session.c:2984 sofia/internal/1003@aitivopabx.aitivo.co.za skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
2026-08-24 20:04:30.040214 97.93% [DEBUG] switch_core_state_machine.c:647 (sofia/internal/1003@aitivopabx.aitivo.co.za) State EXECUTE going to sleep
2026-08-24 20:04:30.040214 97.93% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/1003@aitivopabx.aitivo.co.za) Running State Change CS_HANGUP (Cur 1 Tot 65)
2026-08-24 20:04:30.040214 97.93% [DEBUG] switch_core_state_machine.c:844 (sofia/internal/1003@aitivopabx.aitivo.co.za) Callstate Change RINGING -> HANGUP
2026-08-24 20:04:30.040214 97.93% [DEBUG] switch_core_state_machine.c:846 (sofia/internal/1003@aitivopabx.aitivo.co.za) State HANGUP
2026-08-24 20:04:30.040214 97.93% [DEBUG] mod_sofia.c:463 sofia/internal/1003@aitivopabx.aitivo.co.za Overriding SIP cause 504 with 408 from the other leg
2026-08-24 20:04:30.040214 97.93% [DEBUG] mod_sofia.c:469 Channel sofia/internal/1003@aitivopabx.aitivo.co.za hanging up, cause: RECOVERY_ON_TIMER_EXPIRE
2026-08-24 20:04:30.040214 97.93% [DEBUG] mod_sofia.c:637 Responding to INVITE with: 408
2026-08-24 20:04:30.040214 97.93% [DEBUG] switch_core_state_machine.c:59 sofia/internal/1003@aitivopabx.aitivo.co.za Standard HANGUP, cause: RECOVERY_ON_TIMER_EXPIRE
2026-08-24 20:04:30.040214 97.93% [DEBUG] switch_core_state_machine.c:846 (sofia/internal/1003@aitivopabx.aitivo.co.za) State HANGUP going to sleep
2026-08-24 20:04:30.040214 97.93% [DEBUG] switch_core_state_machine.c:616 (sofia/internal/1003@aitivopabx.aitivo.co.za) State Change CS_HANGUP -> CS_REPORTING
2026-08-24 20:04:30.040214 97.93% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/1003@aitivopabx.aitivo.co.za) Running State Change CS_REPORTING (Cur 1 Tot 65)
2026-08-24 20:04:30.040214 97.93% [DEBUG] switch_core_state_machine.c:932 (sofia/internal/1003@aitivopabx.aitivo.co.za) State REPORTING
2026-08-24 20:04:30.040214 97.93% [DEBUG] switch_core_state_machine.c:168 sofia/internal/1003@aitivopabx.aitivo.co.za Standard REPORTING, cause: RECOVERY_ON_TIMER_EXPIRE
2026-08-24 20:04:30.040214 97.93% [DEBUG] switch_core_state_machine.c:932 (sofia/internal/1003@aitivopabx.aitivo.co.za) State REPORTING going to sleep
2026-08-24 20:04:30.040214 97.93% [DEBUG] switch_core_state_machine.c:607 (sofia/internal/1003@aitivopabx.aitivo.co.za) State Change CS_REPORTING -> CS_DESTROY
2026-08-24 20:04:30.040214 97.93% [DEBUG] switch_core_session.c:1748 Session 64 (sofia/internal/1003@aitivopabx.aitivo.co.za) Locked, Waiting on external entities
2026-08-24 20:04:30.040214 97.93% [NOTICE] switch_core_session.c:1766 Session 64 (sofia/internal/1003@aitivopabx.aitivo.co.za) Ended
2026-08-24 20:04:30.040214 97.93% [NOTICE] switch_core_session.c:1770 Close Channel sofia/internal/1003@aitivopabx.aitivo.co.za [CS_DESTROY]
2026-08-24 20:04:30.040214 97.93% [DEBUG] switch_core_state_machine.c:735 (sofia/internal/1003@aitivopabx.aitivo.co.za) Running State Change CS_DESTROY (Cur 0 Tot 65)
2026-08-24 20:04:30.040214 97.93% [DEBUG] switch_core_state_machine.c:745 (sofia/internal/1003@aitivopabx.aitivo.co.za) State DESTROY
2026-08-24 20:04:30.040214 97.93% [DEBUG] mod_sofia.c:380 sofia/internal/1003@aitivopabx.aitivo.co.za SOFIA DESTROY
2026-08-24 20:04:30.040214 97.93% [DEBUG] switch_core_state_machine.c:175 sofia/internal/1003@aitivopabx.aitivo.co.za Standard DESTROY
2026-08-24 20:04:30.040214 97.93% [DEBUG] switch_core_state_machine.c:745 (sofia/internal/1003@aitivopabx.aitivo.co.za) State DESTROY going to sleep
I seem to be really struggling with my current fusionpbx install. I am running Debian 13 and Fusionpbx 5.5.13, no matter what I try I cannot get outbound calls to work. My incoming and internal work without hassle. When I try to make a call it last for exactly 32 seconds and then times out. It seems when the call is initiated my sip provider requests auth for the gateway and when fusion sends it there is dead silence and the call times out. I have tried with a different sip providers details as well and the exact same thing happens. I have tested my sip details directly on a softphone and the calls route out. I have build a few fusion systems and have never ran into such a problem. Any help would really be appreciated.
+OK log level [7]
2026-08-24 20:03:57.900243 97.97% [NOTICE] switch_channel.c:1143 New Channel sofia/internal/1003@aitivopabx.aitivo.co.za [3cc5e362-ff60-4aea-ad9d-e83d6a678de7]
2026-08-24 20:03:57.900243 97.97% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/1003@aitivopabx.aitivo.co.za) Running State Change CS_NEW (Cur 1 Tot 64)
2026-08-24 20:03:57.900243 97.97% [INFO] sofia.c:10472 sofia/internal/1003@aitivopabx.aitivo.co.za receiving invite from 165.73.39.93:64280 version: 1.11.2-release git 3f13ad1 2026-08-09 16:23:10Z 64bit call-id: 7d96abb28487474b838f446d9eae409d
2026-08-24 20:03:57.900243 97.97% [DEBUG] sofia.c:10566 verifying acl "providers" for ip/port 165.73.39.93:0.
2026-08-24 20:03:57.900243 97.97% [DEBUG] switch_core_state_machine.c:600 (sofia/internal/1003@aitivopabx.aitivo.co.za) State NEW
2026-08-24 20:03:57.900243 97.97% [DEBUG] sofia.c:2408 detaching session 3cc5e362-ff60-4aea-ad9d-e83d6a678de7
2026-08-24 20:03:57.940230 97.97% [DEBUG] sofia.c:2523 Re-attaching to session 3cc5e362-ff60-4aea-ad9d-e83d6a678de7
2026-08-24 20:03:57.960243 97.97% [INFO] sofia.c:10472 sofia/internal/1003@aitivopabx.aitivo.co.za receiving invite from 165.73.39.93:64280 version: 1.11.2-release git 3f13ad1 2026-08-09 16:23:10Z 64bit call-id: 7d96abb28487474b838f446d9eae409d
2026-08-24 20:03:57.960243 97.97% [DEBUG] sofia.c:10566 verifying acl "providers" for ip/port 165.73.39.93:0.
2026-08-24 20:03:57.960243 97.97% [DEBUG] sofia.c:11687 Setting NAT mode based on nat.auto
2026-08-24 20:03:57.960243 97.97% [DEBUG] sofia.c:7505 Channel sofia/internal/1003@aitivopabx.aitivo.co.za entering state [received][100]
2026-08-24 20:03:57.960243 97.97% [DEBUG] sofia.c:7515 Remote SDP:
v=0
o=- 3996590637 3996590637 IN IP4 192.168.26.132
s=pjmedia
b=AS:84
t=0 0
a=X-nat:0
m=audio 4052 RTP/AVP 0 18 101
c=IN IP4 192.168.26.132
b=TIAS:64000
a=rtpmap:0 PCMU/8000
a=rtpmap:18 G729/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=rtcp:4053 IN IP4 192.168.26.132
a=ssrc:143477049 cname:7aae4e0d32e070c4
2026-08-24 20:03:57.960243 97.97% [DEBUG] switch_core_media.c:5548 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2026-08-24 20:03:57.960243 97.97% [DEBUG] switch_core_media.c:5548 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2026-08-24 20:03:57.960243 97.97% [DEBUG] switch_core_media.c:5610 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
2026-08-24 20:03:57.960243 97.97% [DEBUG] switch_core_media.c:5548 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2026-08-24 20:03:57.960243 97.97% [DEBUG] switch_core_media.c:5548 Audio Codec Compare [G729:18:8000:20:8000:1]/[G722:9:8000:20:64000:1]
2026-08-24 20:03:57.960243 97.97% [DEBUG] switch_core_media.c:5548 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMU:0:8000:20:64000:1]
2026-08-24 20:03:57.960243 97.97% [DEBUG] switch_core_media.c:5548 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMA:8:8000:20:64000:1]
2026-08-24 20:03:57.960243 97.97% [DEBUG] switch_core_media.c:5460 Set telephone-event payload to 101@8000
2026-08-24 20:03:57.960243 97.97% [DEBUG] switch_core_media.c:3745 Set Codec sofia/internal/1003@aitivopabx.aitivo.co.za PCMU/8000 20 ms 160 samples 64000 bits 1 channels
2026-08-24 20:03:57.960243 97.97% [DEBUG] switch_core_codec.c:132 sofia/internal/1003@aitivopabx.aitivo.co.za Original read codec set to PCMU:0
2026-08-24 20:03:57.960243 97.97% [DEBUG] switch_core_media.c:5820 Set telephone-event payload to 101@8000
2026-08-24 20:03:57.960243 97.97% [DEBUG] switch_core_media.c:5878 sofia/internal/1003@aitivopabx.aitivo.co.za Set 2833 dtmf send payload to 101 recv payload to 101
2026-08-24 20:03:57.960243 97.97% [DEBUG] sofia.c:7939 (sofia/internal/1003@aitivopabx.aitivo.co.za) State Change CS_NEW -> CS_INIT
2026-08-24 20:03:57.960243 97.97% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/1003@aitivopabx.aitivo.co.za) Running State Change CS_INIT (Cur 1 Tot 64)
2026-08-24 20:03:57.960243 97.97% [DEBUG] switch_core_state_machine.c:624 (sofia/internal/1003@aitivopabx.aitivo.co.za) State INIT
2026-08-24 20:03:57.960243 97.97% [DEBUG] mod_sofia.c:97 sofia/internal/1003@aitivopabx.aitivo.co.za SOFIA INIT
2026-08-24 20:03:57.960243 97.97% [DEBUG] switch_core_state_machine.c:40 sofia/internal/1003@aitivopabx.aitivo.co.za Standard INIT
2026-08-24 20:03:57.960243 97.97% [DEBUG] switch_core_state_machine.c:48 (sofia/internal/1003@aitivopabx.aitivo.co.za) State Change CS_INIT -> CS_ROUTING
2026-08-24 20:03:57.960243 97.97% [DEBUG] switch_core_state_machine.c:624 (sofia/internal/1003@aitivopabx.aitivo.co.za) State INIT going to sleep
2026-08-24 20:03:57.960243 97.97% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/1003@aitivopabx.aitivo.co.za) Running State Change CS_ROUTING (Cur 1 Tot 64)
2026-08-24 20:03:57.960243 97.97% [DEBUG] switch_channel.c:2400 (sofia/internal/1003@aitivopabx.aitivo.co.za) Callstate Change DOWN -> RINGING
2026-08-24 20:03:57.960243 97.97% [DEBUG] switch_core_state_machine.c:640 (sofia/internal/1003@aitivopabx.aitivo.co.za) State ROUTING
2026-08-24 20:03:57.960243 97.97% [DEBUG] mod_sofia.c:158 sofia/internal/1003@aitivopabx.aitivo.co.za SOFIA ROUTING
2026-08-24 20:03:57.960243 97.97% [DEBUG] switch_core_state_machine.c:230 sofia/internal/1003@aitivopabx.aitivo.co.za Standard ROUTING
2026-08-24 20:03:57.960243 97.97% [INFO] mod_dialplan_xml.c:648 Processing Dean <1003>->27836282655 in context aitivopabx.aitivo.co.za
2026-08-24 20:03:57.980233 97.97% [NOTICE] switch_cpp.cpp:1466 [xml_handler] single key:dialplan:aitivopabx.aitivo.co.za
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za parsing [aitivopabx.aitivo.co.za->user_exists] continue=1
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (FAIL) [user_exists] ${loopback_leg}() =~ /^B$/ break=never
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (PASS) [user_exists] () =~ // break=on-false
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Action set(user_exists=${user_exists id ${destination_number} ${domain_name}}) INLINE
EXECUTE [depth=0] sofia/internal/1003@aitivopabx.aitivo.co.za set(user_exists=false)
2026-08-24 20:03:58.000228 97.97% [DEBUG] mod_dptools.c:1671 SET sofia/internal/1003@aitivopabx.aitivo.co.za [user_exists]=[false]
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Action set(from_user_exists=${user_exists id ${sip_from_user} ${sip_from_host}}) INLINE
EXECUTE [depth=0] sofia/internal/1003@aitivopabx.aitivo.co.za set(from_user_exists=true)
2026-08-24 20:03:58.000228 97.97% [DEBUG] mod_dptools.c:1671 SET sofia/internal/1003@aitivopabx.aitivo.co.za [from_user_exists]=[true]
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (FAIL) [user_exists] ${user_exists}(false) =~ /^true$/ break=on-false
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za parsing [aitivopabx.aitivo.co.za->caller-details] continue=1
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (PASS) [caller-details] ${caller_destination}() =~ /^$/ break=never
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Action set(caller_destination=${destination_number}) INLINE
EXECUTE [depth=0] sofia/internal/1003@aitivopabx.aitivo.co.za set(caller_destination=27836282655)
2026-08-24 20:03:58.000228 97.97% [DEBUG] mod_dptools.c:1671 SET sofia/internal/1003@aitivopabx.aitivo.co.za [caller_destination]=[27836282655]
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Action set(caller_id_name=${caller_id_name}) INLINE
EXECUTE [depth=0] sofia/internal/1003@aitivopabx.aitivo.co.za set(caller_id_name=1003)
2026-08-24 20:03:58.000228 97.97% [DEBUG] mod_dptools.c:1671 SET sofia/internal/1003@aitivopabx.aitivo.co.za [caller_id_name]=[1003]
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Action set(caller_id_number=${caller_id_number})
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za parsing [aitivopabx.aitivo.co.za->global-variables] continue=1
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (PASS) [global-variables] () =~ // break=on-false
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Action set(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Action set(record_ext=mp3) INLINE
EXECUTE [depth=0] sofia/internal/1003@aitivopabx.aitivo.co.za set(record_ext=mp3)
2026-08-24 20:03:58.000228 97.97% [DEBUG] mod_dptools.c:1671 SET sofia/internal/1003@aitivopabx.aitivo.co.za [record_ext]=[mp3]
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za parsing [aitivopabx.aitivo.co.za->domain-variables] continue=1
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (PASS) [domain-variables] () =~ // break=on-false
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Action export(origination_callee_id_name=${caller_destination})
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Action set(operator=1000) INLINE
EXECUTE [depth=0] sofia/internal/1003@aitivopabx.aitivo.co.za set(operator=1000)
2026-08-24 20:03:58.000228 97.97% [DEBUG] mod_dptools.c:1671 SET sofia/internal/1003@aitivopabx.aitivo.co.za [operator]=[1000]
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za parsing [aitivopabx.aitivo.co.za->call_direction-outbound.d420] continue=1
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (PASS) [call_direction-outbound.d420] ${user_exists}(false) =~ /false/ break=on-false
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (PASS) [call_direction-outbound.d420] ${call_direction}() =~ /^$/ break=on-false
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (PASS) [call_direction-outbound.d420] destination_number(27836282655) =~ /^\+?(\d{4,20})$/ break=on-false
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Action export(call_direction=outbound) INLINE
EXECUTE [depth=0] sofia/internal/1003@aitivopabx.aitivo.co.za export(call_direction=outbound)
2026-08-24 20:03:58.000228 97.97% [DEBUG] switch_channel.c:1335 EXPORT (export_vars) [call_direction]=[outbound]
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za parsing [aitivopabx.aitivo.co.za->clear_sip_auto_answer] continue=1
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (FAIL) [clear_sip_auto_answer] ${click_to_call}() =~ /true/ break=on-false
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za parsing [aitivopabx.aitivo.co.za->call-direction] continue=1
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (FAIL) [call-direction] ${call_direction}(outbound) =~ /^$/ break=never
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za parsing [aitivopabx.aitivo.co.za->user_record] continue=1
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (FAIL) [user_record] ${user_record}() =~ /^all$/ break=never
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (FAIL) [user_record] ${call_direction}(outbound) =~ /^inbound$/ break=never
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (FAIL) [user_record] ${user_record}() =~ /^inbound$/ break=never
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (PASS) [user_record] ${call_direction}(outbound) =~ /^outbound$/ break=never
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (FAIL) [user_record] ${user_record}() =~ /^outbound$/ break=never
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (FAIL) [user_record] ${call_direction}(outbound) =~ /^local$/ break=never
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (FAIL) [user_record] ${user_record}() =~ /^local$/ break=never
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Action set(from_user_record=${user_data ${sip_from_user}@${sip_from_host} var user_record}) INLINE
EXECUTE [depth=0] sofia/internal/1003@aitivopabx.aitivo.co.za set(from_user_record=)
2026-08-24 20:03:58.000228 97.97% [DEBUG] mod_dptools.c:1671 SET sofia/internal/1003@aitivopabx.aitivo.co.za [from_user_record]=[UNDEF]
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (FAIL) [user_record] ${from_user_record}() =~ /^all$/ break=never
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (FAIL) [user_record] ${call_direction}(outbound) =~ /^inbound$/ break=never
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (FAIL) [user_record] ${from_user_record}() =~ /^inbound$/ break=never
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (PASS) [user_record] ${call_direction}(outbound) =~ /^outbound$/ break=never
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (FAIL) [user_record] ${from_user_record}() =~ /^outbound$/ break=never
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (FAIL) [user_record] ${call_direction}(outbound) =~ /^local$/ break=never
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (FAIL) [user_record] ${from_user_record}() =~ /^local$/ break=never
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (FAIL) [user_record] ${record_session}() =~ /^true$/ break=on-false
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za parsing [aitivopabx.aitivo.co.za->rtp_has_crypto] continue=1
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za 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/1003@aitivopabx.aitivo.co.za parsing [aitivopabx.aitivo.co.za->redial] continue=1
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (FAIL) [redial] destination_number(27836282655) =~ /^(redial|\*870)$/ break=on-true
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (PASS) [redial] () =~ // break=never
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number})
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za parsing [aitivopabx.aitivo.co.za->emergency_recent_calls] continue=
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (FAIL) [emergency_recent_calls] destination_number(27836282655) =~ /^\*9411$/ break=on-true
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za parsing [aitivopabx.aitivo.co.za->speed_dial] continue=
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (FAIL) [speed_dial] destination_number(27836282655) =~ /^\*0(.*)$/ break=on-false
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za parsing [aitivopabx.aitivo.co.za->default_caller_id] continue=1
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (PASS) [default_caller_id] ${call_direction}(outbound) =~ /outbound/ break=on-false
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (PASS) [default_caller_id] ${emergency_caller_id_name}() =~ /^$/ break=never
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Action set(emergency_caller_id_name=${default_emergency_caller_id_name}) INLINE
EXECUTE [depth=0] sofia/internal/1003@aitivopabx.aitivo.co.za set(emergency_caller_id_name=)
2026-08-24 20:03:58.000228 97.97% [DEBUG] mod_dptools.c:1671 SET sofia/internal/1003@aitivopabx.aitivo.co.za [emergency_caller_id_name]=[UNDEF]
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (PASS) [default_caller_id] ${call_direction}(outbound) =~ /outbound/ break=on-false
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (PASS) [default_caller_id] ${emergency_caller_id_number}() =~ /^$/ break=never
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Action set(emergency_caller_id_number=${default_emergency_caller_id_number}) INLINE
EXECUTE [depth=0] sofia/internal/1003@aitivopabx.aitivo.co.za set(emergency_caller_id_number=)
2026-08-24 20:03:58.000228 97.97% [DEBUG] mod_dptools.c:1671 SET sofia/internal/1003@aitivopabx.aitivo.co.za [emergency_caller_id_number]=[UNDEF]
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (PASS) [default_caller_id] ${call_direction}(outbound) =~ /outbound/ break=on-false
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (PASS) [default_caller_id] ${loopback_leg}() =~ /^$/ break=on-false
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (PASS) [default_caller_id] ${outbound_caller_id_name}() =~ /^$/ break=never
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Action set(outbound_caller_id_name=${default_outbound_caller_id_name}) INLINE
EXECUTE [depth=0] sofia/internal/1003@aitivopabx.aitivo.co.za set(outbound_caller_id_name=)
2026-08-24 20:03:58.000228 97.97% [DEBUG] mod_dptools.c:1671 SET sofia/internal/1003@aitivopabx.aitivo.co.za [outbound_caller_id_name]=[UNDEF]
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (PASS) [default_caller_id] ${call_direction}(outbound) =~ /outbound/ break=on-false
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (PASS) [default_caller_id] ${loopback_leg}() =~ /^$/ break=on-false
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (FAIL) [default_caller_id] ${outbound_caller_id_number}(27101098291) =~ /^$/ break=never
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za parsing [aitivopabx.aitivo.co.za->user_hold_music] continue=1
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (FAIL) [user_hold_music] ${user_exists}(false) =~ /true/ break=on-false
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za parsing [aitivopabx.aitivo.co.za->default_hold_music] continue=1
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (FAIL) [default_hold_music] ${hold_music}(local_stream://default) =~ /^$/ break=on-false
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za parsing [aitivopabx.aitivo.co.za->sessiontelecoms.d420] continue=
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (PASS) [sessiontelecoms.d420] ${user_exists}(false) =~ /false/ break=on-false
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Regex (PASS) [sessiontelecoms.d420] destination_number(27836282655) =~ /^\+?(\d{4,20})$/ break=on-false
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Action export(call_direction=outbound) INLINE
EXECUTE [depth=0] sofia/internal/1003@aitivopabx.aitivo.co.za export(call_direction=outbound)
2026-08-24 20:03:58.000228 97.97% [DEBUG] switch_channel.c:1335 EXPORT (export_vars) [call_direction]=[outbound]
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Action unset(call_timeout)
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Action set(hangup_after_bridge=true)
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Action set(effective_caller_id_name=${outbound_caller_id_name})
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Action set(effective_caller_id_number=${outbound_caller_id_number})
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Action set(inherit_codec=true)
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Action set(ignore_display_updates=true)
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Action set(callee_id_number=27836282655)
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za 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,809)
Dialplan: sofia/internal/1003@aitivopabx.aitivo.co.za Action bridge(sofia/gateway/d363b3f7-f46c-46b5-9ea3-e2a38b6f8546/27836282655)
2026-08-24 20:03:58.000228 97.97% [DEBUG] switch_core_state_machine.c:281 (sofia/internal/1003@aitivopabx.aitivo.co.za) State Change CS_ROUTING -> CS_EXECUTE
2026-08-24 20:03:58.000228 97.97% [DEBUG] switch_core_state_machine.c:640 (sofia/internal/1003@aitivopabx.aitivo.co.za) State ROUTING going to sleep
2026-08-24 20:03:58.000228 97.97% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/1003@aitivopabx.aitivo.co.za) Running State Change CS_EXECUTE (Cur 1 Tot 64)
2026-08-24 20:03:58.000228 97.97% [DEBUG] switch_core_state_machine.c:647 (sofia/internal/1003@aitivopabx.aitivo.co.za) State EXECUTE
2026-08-24 20:03:58.000228 97.97% [DEBUG] mod_sofia.c:213 sofia/internal/1003@aitivopabx.aitivo.co.za SOFIA EXECUTE
2026-08-24 20:03:58.000228 97.97% [DEBUG] switch_core_state_machine.c:323 sofia/internal/1003@aitivopabx.aitivo.co.za Standard EXECUTE
EXECUTE [depth=0] sofia/internal/1003@aitivopabx.aitivo.co.za set(caller_id_number=1003)
2026-08-24 20:03:58.000228 97.97% [DEBUG] mod_dptools.c:1671 SET sofia/internal/1003@aitivopabx.aitivo.co.za [caller_id_number]=[1003]
EXECUTE [depth=0] sofia/internal/1003@aitivopabx.aitivo.co.za set(RFC2822_DATE=Mon, 24 Aug 2026 20:03:58 +0200)
2026-08-24 20:03:58.000228 97.97% [DEBUG] mod_dptools.c:1671 SET sofia/internal/1003@aitivopabx.aitivo.co.za [RFC2822_DATE]=[Mon, 24 Aug 2026 20:03:58 +0200]
EXECUTE [depth=0] sofia/internal/1003@aitivopabx.aitivo.co.za export(origination_callee_id_name=27836282655)
2026-08-24 20:03:58.000228 97.97% [DEBUG] switch_channel.c:1335 EXPORT (export_vars) [origination_callee_id_name]=[27836282655]
EXECUTE [depth=0] sofia/internal/1003@aitivopabx.aitivo.co.za hash(insert/aitivopabx.aitivo.co.za-last_dial/1003/27836282655)
EXECUTE [depth=0] sofia/internal/1003@aitivopabx.aitivo.co.za unset(call_timeout)
2026-08-24 20:03:58.000228 97.97% [DEBUG] mod_dptools.c:1816 UNSET [call_timeout]
EXECUTE [depth=0] sofia/internal/1003@aitivopabx.aitivo.co.za set(hangup_after_bridge=true)
2026-08-24 20:03:58.000228 97.97% [DEBUG] mod_dptools.c:1671 SET sofia/internal/1003@aitivopabx.aitivo.co.za [hangup_after_bridge]=[true]
EXECUTE [depth=0] sofia/internal/1003@aitivopabx.aitivo.co.za set(effective_caller_id_name=)
2026-08-24 20:03:58.000228 97.97% [DEBUG] mod_dptools.c:1671 SET sofia/internal/1003@aitivopabx.aitivo.co.za [effective_caller_id_name]=[UNDEF]
EXECUTE [depth=0] sofia/internal/1003@aitivopabx.aitivo.co.za set(effective_caller_id_number=27101098291)
2026-08-24 20:03:58.020211 97.97% [DEBUG] mod_dptools.c:1671 SET sofia/internal/1003@aitivopabx.aitivo.co.za [effective_caller_id_number]=[27101098291]
EXECUTE [depth=0] sofia/internal/1003@aitivopabx.aitivo.co.za set(inherit_codec=true)
2026-08-24 20:03:58.020211 97.97% [DEBUG] mod_dptools.c:1671 SET sofia/internal/1003@aitivopabx.aitivo.co.za [inherit_codec]=[true]
EXECUTE [depth=0] sofia/internal/1003@aitivopabx.aitivo.co.za set(ignore_display_updates=true)
2026-08-24 20:03:58.020211 97.97% [DEBUG] mod_dptools.c:1671 SET sofia/internal/1003@aitivopabx.aitivo.co.za [ignore_display_updates]=[true]
EXECUTE [depth=0] sofia/internal/1003@aitivopabx.aitivo.co.za set(callee_id_number=27836282655)
2026-08-24 20:03:58.020211 97.97% [DEBUG] mod_dptools.c:1671 SET sofia/internal/1003@aitivopabx.aitivo.co.za [callee_id_number]=[27836282655]
EXECUTE [depth=0] sofia/internal/1003@aitivopabx.aitivo.co.za 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,809)
2026-08-24 20:03:58.020211 97.97% [DEBUG] mod_dptools.c:1671 SET sofia/internal/1003@aitivopabx.aitivo.co.za [continue_on_fail]=[1,2,3,6,18,21,27,28,31,34,38,41,42,44,58,88,111,403,501,602,607,809]
EXECUTE [depth=0] sofia/internal/1003@aitivopabx.aitivo.co.za bridge(sofia/gateway/d363b3f7-f46c-46b5-9ea3-e2a38b6f8546/27836282655)
2026-08-24 20:03:58.020211 97.97% [DEBUG] switch_channel.c:1289 sofia/internal/1003@aitivopabx.aitivo.co.za EXPORTING[export_vars] [domain_name]=[aitivopabx.aitivo.co.za] to event
2026-08-24 20:03:58.020211 97.97% [DEBUG] switch_channel.c:1289 sofia/internal/1003@aitivopabx.aitivo.co.za EXPORTING[export_vars] [domain_uuid]=[9261725e-bdc6-4c59-9db5-d111b7310214] to event
2026-08-24 20:03:58.020211 97.97% [DEBUG] switch_channel.c:1289 sofia/internal/1003@aitivopabx.aitivo.co.za EXPORTING[export_vars] [call_direction]=[outbound] to event
2026-08-24 20:03:58.020211 97.97% [DEBUG] switch_channel.c:1289 sofia/internal/1003@aitivopabx.aitivo.co.za EXPORTING[export_vars] [call_direction]=[outbound] to event
2026-08-24 20:03:58.020211 97.97% [DEBUG] switch_channel.c:1289 sofia/internal/1003@aitivopabx.aitivo.co.za EXPORTING[export_vars] [origination_callee_id_name]=[27836282655] to event
2026-08-24 20:03:58.020211 97.97% [DEBUG] switch_ivr_originate.c:2301 Parsing global variables
2026-08-24 20:03:58.020211 97.97% [NOTICE] switch_channel.c:1143 New Channel sofia/external/27836282655 [55b92fa5-0afb-4484-94fa-01d188bfca5a]
2026-08-24 20:03:58.020211 97.97% [DEBUG] mod_sofia.c:5146 (sofia/external/27836282655) State Change CS_NEW -> CS_INIT
2026-08-24 20:03:58.020211 97.97% [DEBUG] switch_core_state_machine.c:581 (sofia/external/27836282655) Running State Change CS_INIT (Cur 2 Tot 65)
2026-08-24 20:03:58.020211 97.97% [DEBUG] switch_core_state_machine.c:624 (sofia/external/27836282655) State INIT
2026-08-24 20:03:58.020211 97.97% [DEBUG] mod_sofia.c:97 sofia/external/27836282655 SOFIA INIT
2026-08-24 20:03:58.020211 97.97% [INFO] sofia_glue.c:1656 sofia/external/27836282655 sending invite call-id: (null)
2026-08-24 20:03:58.020211 97.97% [DEBUG] sofia_glue.c:1659 sofia/external/27836282655 sending invite version: 1.11.2-release git 3f13ad1 2026-08-09 16:23:10Z 64bit
Local SDP:
v=0
o=FreeSWITCH 1787564444 1787564445 IN IP4 102.206.117.233
s=FreeSWITCH
c=IN IP4 102.206.117.233
t=0 0
m=audio 30194 RTP/AVP 0 8 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=silenceSupp
ff - - - -a=ptime:20
a=sendrecv
2026-08-24 20:03:58.020211 97.97% [DEBUG] switch_core_state_machine.c:40 sofia/external/27836282655 Standard INIT
2026-08-24 20:03:58.020211 97.97% [DEBUG] switch_core_state_machine.c:48 (sofia/external/27836282655) State Change CS_INIT -> CS_ROUTING
2026-08-24 20:03:58.020211 97.97% [DEBUG] switch_core_state_machine.c:624 (sofia/external/27836282655) State INIT going to sleep
2026-08-24 20:03:58.020211 97.97% [DEBUG] switch_core_state_machine.c:581 (sofia/external/27836282655) Running State Change CS_ROUTING (Cur 2 Tot 65)
2026-08-24 20:03:58.020211 97.97% [DEBUG] switch_core_state_machine.c:640 (sofia/external/27836282655) State ROUTING
2026-08-24 20:03:58.020211 97.97% [DEBUG] mod_sofia.c:158 sofia/external/27836282655 SOFIA ROUTING
2026-08-24 20:03:58.020211 97.97% [DEBUG] switch_ivr_originate.c:67 (sofia/external/27836282655) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2026-08-24 20:03:58.020211 97.97% [DEBUG] switch_core_state_machine.c:640 (sofia/external/27836282655) State ROUTING going to sleep
2026-08-24 20:03:58.020211 97.97% [DEBUG] switch_core_state_machine.c:581 (sofia/external/27836282655) Running State Change CS_CONSUME_MEDIA (Cur 2 Tot 65)
2026-08-24 20:03:58.020211 97.97% [DEBUG] switch_core_state_machine.c:659 (sofia/external/27836282655) State CONSUME_MEDIA
2026-08-24 20:03:58.020211 97.97% [DEBUG] switch_core_state_machine.c:659 (sofia/external/27836282655) State CONSUME_MEDIA going to sleep
2026-08-24 20:03:58.020211 97.97% [DEBUG] sofia.c:7505 Channel sofia/external/27836282655 entering state [calling][0]
2026-08-24 20:03:58.020211 97.97% [DEBUG] sofia.c:7505 Channel sofia/external/27836282655 entering state [calling][0]
2026-08-24 20:04:30.020282 97.93% [DEBUG] sofia.c:7505 Channel sofia/external/27836282655 entering state [terminated][408]
2026-08-24 20:04:30.020282 97.93% [NOTICE] sofia.c:8748 Hangup sofia/external/27836282655 [CS_CONSUME_MEDIA] [RECOVERY_ON_TIMER_EXPIRE]
2026-08-24 20:04:30.040214 97.93% [DEBUG] switch_core_state_machine.c:581 (sofia/external/27836282655) Running State Change CS_HANGUP (Cur 2 Tot 65)
2026-08-24 20:04:30.040214 97.93% [DEBUG] switch_core_state_machine.c:844 (sofia/external/27836282655) Callstate Change DOWN -> HANGUP
2026-08-24 20:04:30.040214 97.93% [DEBUG] switch_core_state_machine.c:846 (sofia/external/27836282655) State HANGUP
2026-08-24 20:04:30.040214 97.93% [DEBUG] mod_sofia.c:469 Channel sofia/external/27836282655 hanging up, cause: RECOVERY_ON_TIMER_EXPIRE
2026-08-24 20:04:30.040214 97.93% [DEBUG] switch_core_state_machine.c:59 sofia/external/27836282655 Standard HANGUP, cause: RECOVERY_ON_TIMER_EXPIRE
2026-08-24 20:04:30.040214 97.93% [DEBUG] switch_core_state_machine.c:846 (sofia/external/27836282655) State HANGUP going to sleep
2026-08-24 20:04:30.040214 97.93% [DEBUG] switch_core_state_machine.c:616 (sofia/external/27836282655) State Change CS_HANGUP -> CS_REPORTING
2026-08-24 20:04:30.040214 97.93% [DEBUG] switch_core_state_machine.c:581 (sofia/external/27836282655) Running State Change CS_REPORTING (Cur 2 Tot 65)
2026-08-24 20:04:30.040214 97.93% [DEBUG] switch_core_state_machine.c:932 (sofia/external/27836282655) State REPORTING
2026-08-24 20:04:30.040214 97.93% [DEBUG] switch_core_state_machine.c:168 sofia/external/27836282655 Standard REPORTING, cause: RECOVERY_ON_TIMER_EXPIRE
2026-08-24 20:04:30.040214 97.93% [DEBUG] switch_core_state_machine.c:932 (sofia/external/27836282655) State REPORTING going to sleep
2026-08-24 20:04:30.040214 97.93% [DEBUG] switch_core_state_machine.c:607 (sofia/external/27836282655) State Change CS_REPORTING -> CS_DESTROY
2026-08-24 20:04:30.040214 97.93% [DEBUG] switch_core_session.c:1748 Session 65 (sofia/external/27836282655) Locked, Waiting on external entities
2026-08-24 20:04:30.040214 97.93% [DEBUG] switch_ivr_originate.c:4056 Originate Resulted in Error Cause: 102 [RECOVERY_ON_TIMER_EXPIRE]
2026-08-24 20:04:30.040214 97.93% [NOTICE] switch_core_session.c:1766 Session 65 (sofia/external/27836282655) Ended
2026-08-24 20:04:30.040214 97.93% [NOTICE] switch_core_session.c:1770 Close Channel sofia/external/27836282655 [CS_DESTROY]
2026-08-24 20:04:30.040214 97.93% [DEBUG] switch_core_state_machine.c:735 (sofia/external/27836282655) Running State Change CS_DESTROY (Cur 1 Tot 65)
2026-08-24 20:04:30.040214 97.93% [DEBUG] switch_core_state_machine.c:745 (sofia/external/27836282655) State DESTROY
2026-08-24 20:04:30.040214 97.93% [DEBUG] mod_sofia.c:380 sofia/external/27836282655 SOFIA DESTROY
2026-08-24 20:04:30.040214 97.93% [DEBUG] switch_core_state_machine.c:175 sofia/external/27836282655 Standard DESTROY
2026-08-24 20:04:30.040214 97.93% [DEBUG] switch_core_state_machine.c:745 (sofia/external/27836282655) State DESTROY going to sleep
2026-08-24 20:04:30.040214 97.93% [INFO] mod_dptools.c:3637 Originate Failed. Cause: RECOVERY_ON_TIMER_EXPIRE
2026-08-24 20:04:30.040214 97.93% [NOTICE] switch_channel.c:5016 Hangup sofia/internal/1003@aitivopabx.aitivo.co.za [CS_EXECUTE] [RECOVERY_ON_TIMER_EXPIRE]
2026-08-24 20:04:30.040214 97.93% [DEBUG] switch_core_session.c:2984 sofia/internal/1003@aitivopabx.aitivo.co.za skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
2026-08-24 20:04:30.040214 97.93% [DEBUG] switch_core_state_machine.c:647 (sofia/internal/1003@aitivopabx.aitivo.co.za) State EXECUTE going to sleep
2026-08-24 20:04:30.040214 97.93% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/1003@aitivopabx.aitivo.co.za) Running State Change CS_HANGUP (Cur 1 Tot 65)
2026-08-24 20:04:30.040214 97.93% [DEBUG] switch_core_state_machine.c:844 (sofia/internal/1003@aitivopabx.aitivo.co.za) Callstate Change RINGING -> HANGUP
2026-08-24 20:04:30.040214 97.93% [DEBUG] switch_core_state_machine.c:846 (sofia/internal/1003@aitivopabx.aitivo.co.za) State HANGUP
2026-08-24 20:04:30.040214 97.93% [DEBUG] mod_sofia.c:463 sofia/internal/1003@aitivopabx.aitivo.co.za Overriding SIP cause 504 with 408 from the other leg
2026-08-24 20:04:30.040214 97.93% [DEBUG] mod_sofia.c:469 Channel sofia/internal/1003@aitivopabx.aitivo.co.za hanging up, cause: RECOVERY_ON_TIMER_EXPIRE
2026-08-24 20:04:30.040214 97.93% [DEBUG] mod_sofia.c:637 Responding to INVITE with: 408
2026-08-24 20:04:30.040214 97.93% [DEBUG] switch_core_state_machine.c:59 sofia/internal/1003@aitivopabx.aitivo.co.za Standard HANGUP, cause: RECOVERY_ON_TIMER_EXPIRE
2026-08-24 20:04:30.040214 97.93% [DEBUG] switch_core_state_machine.c:846 (sofia/internal/1003@aitivopabx.aitivo.co.za) State HANGUP going to sleep
2026-08-24 20:04:30.040214 97.93% [DEBUG] switch_core_state_machine.c:616 (sofia/internal/1003@aitivopabx.aitivo.co.za) State Change CS_HANGUP -> CS_REPORTING
2026-08-24 20:04:30.040214 97.93% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/1003@aitivopabx.aitivo.co.za) Running State Change CS_REPORTING (Cur 1 Tot 65)
2026-08-24 20:04:30.040214 97.93% [DEBUG] switch_core_state_machine.c:932 (sofia/internal/1003@aitivopabx.aitivo.co.za) State REPORTING
2026-08-24 20:04:30.040214 97.93% [DEBUG] switch_core_state_machine.c:168 sofia/internal/1003@aitivopabx.aitivo.co.za Standard REPORTING, cause: RECOVERY_ON_TIMER_EXPIRE
2026-08-24 20:04:30.040214 97.93% [DEBUG] switch_core_state_machine.c:932 (sofia/internal/1003@aitivopabx.aitivo.co.za) State REPORTING going to sleep
2026-08-24 20:04:30.040214 97.93% [DEBUG] switch_core_state_machine.c:607 (sofia/internal/1003@aitivopabx.aitivo.co.za) State Change CS_REPORTING -> CS_DESTROY
2026-08-24 20:04:30.040214 97.93% [DEBUG] switch_core_session.c:1748 Session 64 (sofia/internal/1003@aitivopabx.aitivo.co.za) Locked, Waiting on external entities
2026-08-24 20:04:30.040214 97.93% [NOTICE] switch_core_session.c:1766 Session 64 (sofia/internal/1003@aitivopabx.aitivo.co.za) Ended
2026-08-24 20:04:30.040214 97.93% [NOTICE] switch_core_session.c:1770 Close Channel sofia/internal/1003@aitivopabx.aitivo.co.za [CS_DESTROY]
2026-08-24 20:04:30.040214 97.93% [DEBUG] switch_core_state_machine.c:735 (sofia/internal/1003@aitivopabx.aitivo.co.za) Running State Change CS_DESTROY (Cur 0 Tot 65)
2026-08-24 20:04:30.040214 97.93% [DEBUG] switch_core_state_machine.c:745 (sofia/internal/1003@aitivopabx.aitivo.co.za) State DESTROY
2026-08-24 20:04:30.040214 97.93% [DEBUG] mod_sofia.c:380 sofia/internal/1003@aitivopabx.aitivo.co.za SOFIA DESTROY
2026-08-24 20:04:30.040214 97.93% [DEBUG] switch_core_state_machine.c:175 sofia/internal/1003@aitivopabx.aitivo.co.za Standard DESTROY
2026-08-24 20:04:30.040214 97.93% [DEBUG] switch_core_state_machine.c:745 (sofia/internal/1003@aitivopabx.aitivo.co.za) State DESTROY going to sleep
