2022-08-15 14:24:25.183388 73.63% [NOTICE] switch_channel.c:1123 New Channel sofia/internal/
318@mypbx.mydomain.com [f70ead1e-1ca5-11ed-bf9f-9f1656192be6]
2022-08-15 14:24:25.183388 73.63% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/
318@mypbx.mydomain.com) Running State Change CS_NEW (Cur 3 Tot 18121)
2022-08-15 14:24:25.183388 73.63% [INFO] sofia.c:10462 sofia/internal/
318@mypbx.mydomain.com receiving invite from 111.222.333.444:51514 version: 1.10.7 -release 64bit call-id: Q7s4R9xK1oQ0KG0gk1Nxgw..
2022-08-15 14:24:25.183388 73.63% [DEBUG] switch_core_state_machine.c:600 (sofia/internal/
318@mypbx.mydomain.com) State NEW
2022-08-15 14:24:25.203384 73.63% [DEBUG] sofia.c:2419 detaching session f70ead1e-1ca5-11ed-bf9f-9f1656192be6
2022-08-15 14:24:25.503391 73.63% [DEBUG] sofia.c:2532 Re-attaching to session f70ead1e-1ca5-11ed-bf9f-9f1656192be6
2022-08-15 14:24:25.523397 73.63% [INFO] sofia.c:10462 sofia/internal/
318@mypbx.mydomain.com receiving invite from 111.222.333.444:51514 version: 1.10.7 -release 64bit call-id: Q7s4R9xK1oQ0KG0gk1Nxgw..
2022-08-15 14:24:25.523397 73.63% [DEBUG] sofia.c:7499 Channel sofia/internal/
318@mypbx.mydomain.com entering state [received][100]
2022-08-15 14:24:25.523397 73.63% [DEBUG] sofia.c:7509 Remote SDP:
v=0
o=- 0 1 IN IP4 111.222.333.444
s=-
c=IN IP4 111.222.333.444
t=0 0
m=audio 64950 RTP/AVP 9 0 8 3 102 120 101
a=rtpmap:9 G722/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:3 GSM/8000
a=rtpmap:102 iLBC/8000
a=fmtp:102 mode=30
a=rtpmap:120 opus/48000/2
a=fmtp:120 useinbandfec=1; usedtx=1; maxaveragebitrate=64000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
2022-08-15 14:24:25.523397 73.63% [DEBUG] switch_core_media.c:5650 Audio Codec Compare [G722:9:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2022-08-15 14:24:25.523397 73.63% [DEBUG] switch_core_media.c:5705 Audio Codec Compare [G722:9:8000:20:64000:1] ++++ is saved as a match
2022-08-15 14:24:25.523397 73.63% [DEBUG] switch_core_media.c:5650 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2022-08-15 14:24:25.523397 73.63% [DEBUG] switch_core_media.c:5650 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2022-08-15 14:24:25.523397 73.63% [DEBUG] switch_core_media.c:5650 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2022-08-15 14:24:25.523397 73.63% [DEBUG] switch_core_media.c:5650 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2022-08-15 14:24:25.523397 73.63% [DEBUG] switch_core_media.c:5705 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
2022-08-15 14:24:25.523397 73.63% [DEBUG] switch_core_media.c:5650 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2022-08-15 14:24:25.523397 73.63% [DEBUG] switch_core_media.c:5650 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2022-08-15 14:24:25.523397 73.63% [DEBUG] switch_core_media.c:5650 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2022-08-15 14:24:25.523397 73.63% [DEBUG] switch_core_media.c:5650 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2022-08-15 14:24:25.523397 73.63% [DEBUG] switch_core_media.c:5705 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
2022-08-15 14:24:25.523397 73.63% [DEBUG] switch_core_media.c:5650 Audio Codec Compare [GSM:3:8000:20:13200:1]/[G722:9:8000:20:64000:1]
2022-08-15 14:24:25.523397 73.63% [DEBUG] switch_core_media.c:5650 Audio Codec Compare [GSM:3:8000:20:13200:1]/[PCMU:0:8000:20:64000:1]
2022-08-15 14:24:25.523397 73.63% [DEBUG] switch_core_media.c:5650 Audio Codec Compare [GSM:3:8000:20:13200:1]/[PCMA:8:8000:20:64000:1]
2022-08-15 14:24:25.523397 73.63% [DEBUG] switch_core_media.c:5650 Audio Codec Compare [iLBC:102:8000:30:0:1]/[G722:9:8000:20:64000:1]
2022-08-15 14:24:25.523397 73.63% [DEBUG] switch_core_media.c:5650 Audio Codec Compare [iLBC:102:8000:30:0:1]/[PCMU:0:8000:20:64000:1]
2022-08-15 14:24:25.523397 73.63% [DEBUG] switch_core_media.c:5650 Audio Codec Compare [iLBC:102:8000:30:0:1]/[PCMA:8:8000:20:64000:1]
2022-08-15 14:24:25.523397 73.63% [DEBUG] switch_core_media.c:5650 Audio Codec Compare [opus:120:48000:20:0:2]/[G722:9:8000:20:64000:1]
2022-08-15 14:24:25.523397 73.63% [DEBUG] switch_core_media.c:5650 Audio Codec Compare [opus:120:48000:20:0:2]/[PCMU:0:8000:20:64000:1]
2022-08-15 14:24:25.523397 73.63% [DEBUG] switch_core_media.c:5650 Audio Codec Compare [opus:120:48000:20:0:2]/[PCMA:8:8000:20:64000:1]
2022-08-15 14:24:25.523397 73.63% [DEBUG] switch_core_media.c:5566 Set telephone-event payload to 101@8000
2022-08-15 14:24:25.523397 73.63% [DEBUG] switch_core_media.c:3870 Set Codec sofia/internal/
318@mypbx.mydomain.com G722/8000 20 ms 160 samples 64000 bits 1 channels
2022-08-15 14:24:25.523397 73.63% [DEBUG] switch_core_codec.c:111 sofia/internal/
318@mypbx.mydomain.com Original read codec set to G722:9
2022-08-15 14:24:25.523397 73.63% [DEBUG] switch_core_media.c:5915 Set telephone-event payload to 101@8000
2022-08-15 14:24:25.523397 73.63% [DEBUG] switch_core_media.c:5973 sofia/internal/
318@mypbx.mydomain.com Set 2833 dtmf send payload to 101 recv payload to 101
2022-08-15 14:24:25.523397 73.63% [DEBUG] sofia.c:7933 (sofia/internal/
318@mypbx.mydomain.com) State Change CS_NEW -> CS_INIT
2022-08-15 14:24:25.523397 73.63% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/
318@mypbx.mydomain.com) Running State Change CS_INIT (Cur 3 Tot 18121)
2022-08-15 14:24:25.523397 73.63% [DEBUG] switch_core_state_machine.c:624 (sofia/internal/
318@mypbx.mydomain.com) State INIT
2022-08-15 14:24:25.523397 73.63% [DEBUG] mod_sofia.c:97 sofia/internal/
318@mypbx.mydomain.com SOFIA INIT
2022-08-15 14:24:25.523397 73.63% [DEBUG] switch_core_state_machine.c:40 sofia/internal/
318@mypbx.mydomain.com Standard INIT
2022-08-15 14:24:25.523397 73.63% [DEBUG] switch_core_state_machine.c:48 (sofia/internal/
318@mypbx.mydomain.com) State Change CS_INIT -> CS_ROUTING
2022-08-15 14:24:25.523397 73.63% [DEBUG] switch_core_state_machine.c:624 (sofia/internal/
318@mypbx.mydomain.com) State INIT going to sleep
2022-08-15 14:24:25.523397 73.63% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/
318@mypbx.mydomain.com) Running State Change CS_ROUTING (Cur 3 Tot 18121)
2022-08-15 14:24:25.523397 73.63% [DEBUG] switch_channel.c:2380 (sofia/internal/
318@mypbx.mydomain.com) Callstate Change DOWN -> RINGING
2022-08-15 14:24:25.523397 73.63% [DEBUG] switch_core_state_machine.c:640 (sofia/internal/
318@mypbx.mydomain.com) State ROUTING
2022-08-15 14:24:25.523397 73.63% [DEBUG] mod_sofia.c:158 sofia/internal/
318@mypbx.mydomain.com SOFIA ROUTING
2022-08-15 14:24:25.523397 73.63% [DEBUG] switch_core_state_machine.c:230 sofia/internal/
318@mypbx.mydomain.com Standard ROUTING
2022-08-15 14:24:25.523397 73.63% [INFO] mod_dialplan_xml.c:639 Processing 318 <318>->0123456789 in context mypbx.mydomain.com
Dialplan: sofia/internal/
318@mypbx.mydomain.com parsing [mypbx.mydomain.com->caller-details] continue=true
Dialplan: sofia/internal/
318@mypbx.mydomain.com Regex (PASS) [caller-details] () =~ // break=never
Dialplan: sofia/internal/
318@mypbx.mydomain.com Action set(caller_destination=${sip_to_user}) INLINE
EXECUTE [depth=0] sofia/internal/
318@mypbx.mydomain.com set(caller_destination=0123456789)
2022-08-15 14:24:25.543356 73.63% [DEBUG] mod_dptools.c:1685 SET sofia/internal/
318@mypbx.mydomain.com [caller_destination]=[0123456789]
Dialplan: sofia/internal/
318@mypbx.mydomain.com Action set(caller_id_name=${caller_id_name}) INLINE
EXECUTE [depth=0] sofia/internal/
318@mypbx.mydomain.com set(caller_id_name=318)
2022-08-15 14:24:25.543356 73.63% [DEBUG] mod_dptools.c:1685 SET sofia/internal/
318@mypbx.mydomain.com [caller_id_name]=[318]
Dialplan: sofia/internal/
318@mypbx.mydomain.com Action set(caller_id_number=${caller_id_number})
Dialplan: sofia/internal/
318@mypbx.mydomain.com parsing [mypbx.mydomain.com->user_exists] continue=true
Dialplan: sofia/internal/
318@mypbx.mydomain.com Regex (FAIL) [user_exists] ${loopback_leg}() =~ /^B$/ break=never
Dialplan: sofia/internal/
318@mypbx.mydomain.com Regex (PASS) [user_exists] () =~ // break=on-false
Dialplan: sofia/internal/
318@mypbx.mydomain.com Action set(user_exists=${user_exists id ${destination_number} ${domain_name}}) INLINE
EXECUTE [depth=0] sofia/internal/
318@mypbx.mydomain.com set(user_exists=false)
2022-08-15 14:24:25.543356 73.63% [DEBUG] mod_dptools.c:1685 SET sofia/internal/
318@mypbx.mydomain.com [user_exists]=[false]
Dialplan: sofia/internal/
318@mypbx.mydomain.com Action set(from_user_exists=${user_exists id ${sip_from_user} ${sip_from_host}}) INLINE
EXECUTE [depth=0] sofia/internal/
318@mypbx.mydomain.com set(from_user_exists=true)
2022-08-15 14:24:25.543356 73.63% [DEBUG] mod_dptools.c:1685 SET sofia/internal/
318@mypbx.mydomain.com [from_user_exists]=[true]
Dialplan: sofia/internal/
318@mypbx.mydomain.com Regex (FAIL) [user_exists] ${user_exists}(false) =~ /^true$/ break=on-false
Dialplan: sofia/internal/
318@mypbx.mydomain.com parsing [mypbx.mydomain.com->caller-details] continue=true
Dialplan: sofia/internal/
318@mypbx.mydomain.com Regex (FAIL) [caller-details] ${caller_destination}(0123456789) =~ /^$/ break=never
Dialplan: sofia/internal/
318@mypbx.mydomain.com parsing [mypbx.mydomain.com->global-variables] continue=true
Dialplan: sofia/internal/
318@mypbx.mydomain.com Regex (PASS) [global-variables] () =~ // break=on-false
Dialplan: sofia/internal/
318@mypbx.mydomain.com Action set(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
Dialplan: sofia/internal/
318@mypbx.mydomain.com parsing [mypbx.mydomain.com->domain-variables] continue=true
Dialplan: sofia/internal/
318@mypbx.mydomain.com Regex (PASS) [domain-variables] () =~ // break=on-false
Dialplan: sofia/internal/
318@mypbx.mydomain.com Action export(origination_callee_id_name=${destination_number})
Dialplan: sofia/internal/
318@mypbx.mydomain.com Action set(operator=1000) INLINE
EXECUTE [depth=0] sofia/internal/
318@mypbx.mydomain.com set(operator=1000)
2022-08-15 14:24:25.543356 73.63% [DEBUG] mod_dptools.c:1685 SET sofia/internal/
318@mypbx.mydomain.com [operator]=[1000]
Dialplan: sofia/internal/
318@mypbx.mydomain.com parsing [mypbx.mydomain.com->clear_sip_auto_answer] continue=true
Dialplan: sofia/internal/
318@mypbx.mydomain.com Regex (FAIL) [clear_sip_auto_answer] ${click_to_call}() =~ /true/ break=on-false
Dialplan: sofia/internal/
318@mypbx.mydomain.com parsing [mypbx.mydomain.com->is_loopback] continue=true
Dialplan: sofia/internal/
318@mypbx.mydomain.com Regex (FAIL) [is_loopback] ${is_follow_me_loopback}() =~ /true/ break=on-false
Dialplan: sofia/internal/
318@mypbx.mydomain.com parsing [mypbx.mydomain.com->call-direction] continue=true
Dialplan: sofia/internal/
318@mypbx.mydomain.com Regex (FAIL) [call-direction] ${call_direction}() =~ /^(inbound|outbound|local)$/ break=never
Dialplan: sofia/internal/
318@mypbx.mydomain.com ANTI-Action export(call_direction=local) INLINE
EXECUTE [depth=0] sofia/internal/
318@mypbx.mydomain.com export(call_direction=local)
2022-08-15 14:24:25.543356 73.63% [DEBUG] switch_channel.c:1315 EXPORT (export_vars) [call_direction]=[local]
Dialplan: sofia/internal/
318@mypbx.mydomain.com parsing [mypbx.mydomain.com->user_record] continue=true
Dialplan: sofia/internal/
318@mypbx.mydomain.com Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/
318@mypbx.mydomain.com Regex (FAIL) [user_record] ${user_record}() =~ /^all$/ break=never
Dialplan: sofia/internal/
318@mypbx.mydomain.com Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/
318@mypbx.mydomain.com Regex (FAIL) [user_record] ${call_direction}(local) =~ /^inbound$/ break=never
Dialplan: sofia/internal/
318@mypbx.mydomain.com Regex (FAIL) [user_record] ${user_record}() =~ /^inbound$/ break=never
Dialplan: sofia/internal/
318@mypbx.mydomain.com Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/
318@mypbx.mydomain.com Regex (FAIL) [user_record] ${call_direction}(local) =~ /^outbound$/ break=never
Dialplan: sofia/internal/
318@mypbx.mydomain.com Regex (FAIL) [user_record] ${user_record}() =~ /^outbound$/ break=never
Dialplan: sofia/internal/
318@mypbx.mydomain.com Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/
318@mypbx.mydomain.com Regex (PASS) [user_record] ${call_direction}(local) =~ /^local$/ break=never
Dialplan: sofia/internal/
318@mypbx.mydomain.com Regex (FAIL) [user_record] ${user_record}() =~ /^local$/ break=never
Dialplan: sofia/internal/
318@mypbx.mydomain.com Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/internal/
318@mypbx.mydomain.com Action set(from_user_record=${user_data ${sip_from_user}@${sip_from_host} var user_record}) INLINE
EXECUTE [depth=0] sofia/internal/
318@mypbx.mydomain.com set(from_user_record=)
2022-08-15 14:24:25.563384 73.63% [DEBUG] mod_dptools.c:1685 SET sofia/internal/
318@mypbx.mydomain.com [from_user_record]=[UNDEF]
Dialplan: sofia/internal/
318@mypbx.mydomain.com Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/internal/
318@mypbx.mydomain.com Regex (FAIL) [user_record] ${from_user_record}() =~ /^all$/ break=never
Dialplan: sofia/internal/
318@mypbx.mydomain.com Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/internal/
318@mypbx.mydomain.com Regex (FAIL) [user_record] ${call_direction}(local) =~ /^inbound$/ break=never
Dialplan: sofia/internal/
318@mypbx.mydomain.com Regex (FAIL) [user_record] ${from_user_record}() =~ /^inbound$/ break=never
Dialplan: sofia/internal/
318@mypbx.mydomain.com Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/internal/
318@mypbx.mydomain.com Regex (FAIL) [user_record] ${call_direction}(local) =~ /^outbound$/ break=never
Dialplan: sofia/internal/
318@mypbx.mydomain.com Regex (FAIL) [user_record] ${from_user_record}() =~ /^outbound$/ break=never
Dialplan: sofia/internal/
318@mypbx.mydomain.com Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/internal/
318@mypbx.mydomain.com Regex (PASS) [user_record] ${call_direction}(local) =~ /^local$/ break=never
Dialplan: sofia/internal/
318@mypbx.mydomain.com Regex (FAIL) [user_record] ${from_user_record}() =~ /^local$/ break=never
Dialplan: sofia/internal/
318@mypbx.mydomain.com Regex (FAIL) [user_record] ${record_session}() =~ /^true$/ break=on-false
Dialplan: sofia/internal/
318@mypbx.mydomain.com parsing [mypbx.mydomain.com->rtp_has_crypto] continue=true
Dialplan: sofia/internal/
318@mypbx.mydomain.com 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/
318@mypbx.mydomain.com parsing [mypbx.mydomain.com->redial] continue=true
Dialplan: sofia/internal/
318@mypbx.mydomain.com Regex (FAIL) [redial] destination_number(0123456789) =~ /^(redial|\*870)$/ break=on-true
Dialplan: sofia/internal/
318@mypbx.mydomain.com Regex (PASS) [redial] () =~ // break=never
Dialplan: sofia/internal/
318@mypbx.mydomain.com Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number})
Dialplan: sofia/internal/
318@mypbx.mydomain.com parsing [mypbx.mydomain.com->speed_dial] continue=false
Dialplan: sofia/internal/
318@mypbx.mydomain.com Regex (FAIL) [speed_dial] destination_number(0123456789) =~ /^\*0(.*)$/ break=on-false
Dialplan: sofia/internal/
318@mypbx.mydomain.com parsing [mypbx.mydomain.com->default_caller_id] continue=true
Dialplan: sofia/internal/
318@mypbx.mydomain.com Regex (FAIL) [default_caller_id] ${call_direction}(local) =~ /outbound/ break=on-false
Dialplan: sofia/internal/
318@mypbx.mydomain.com parsing [mypbx.mydomain.com->user_hold_music] continue=true
Dialplan: sofia/internal/
318@mypbx.mydomain.com Regex (FAIL) [user_hold_music] ${user_exists}(false) =~ /true/ break=on-false
Dialplan: sofia/internal/
318@mypbx.mydomain.com parsing [mypbx.mydomain.com->trunk1-fix.10d] continue=false
Dialplan: sofia/internal/
318@mypbx.mydomain.com Regex (FAIL) [trunk1-fix.10d] ${sip_from_user}(318) =~ /319/ break=on-false
Dialplan: sofia/internal/
318@mypbx.mydomain.com parsing [mypbx.mydomain.com->trunk2-mob.10d] continue=false
Dialplan: sofia/internal/
318@mypbx.mydomain.com Regex (PASS) [trunk2-mob.10d] ${sip_from_user}(318) =~ /318/ break=on-false
Dialplan: sofia/internal/
318@mypbx.mydomain.com Regex (PASS) [trunk2-mob.10d] ${user_exists}(false) =~ /false/ break=on-false
Dialplan: sofia/internal/
318@mypbx.mydomain.com Regex (PASS) [trunk2-mob.10d] destination_number(0123456789) =~ /^(\d{10})$/ break=on-false
Dialplan: sofia/internal/
318@mypbx.mydomain.com Action set(sip_h_X-accountcode=${accountcode})
Dialplan: sofia/internal/
318@mypbx.mydomain.com Action export(call_direction=outbound) INLINE
EXECUTE [depth=0] sofia/internal/
318@mypbx.mydomain.com export(call_direction=outbound)
2022-08-15 14:24:25.563384 73.63% [DEBUG] switch_channel.c:1315 EXPORT (export_vars) [call_direction]=[outbound]
Dialplan: sofia/internal/
318@mypbx.mydomain.com Action unset(call_timeout)
Dialplan: sofia/internal/
318@mypbx.mydomain.com Action set(hangup_after_bridge=true)
Dialplan: sofia/internal/
318@mypbx.mydomain.com Action set(effective_caller_id_name=${outbound_caller_id_name})
Dialplan: sofia/internal/
318@mypbx.mydomain.com Action set(effective_caller_id_number=${outbound_caller_id_number})
Dialplan: sofia/internal/
318@mypbx.mydomain.com Action set(inherit_codec=true)
Dialplan: sofia/internal/
318@mypbx.mydomain.com Action set(ignore_display_updates=true)
Dialplan: sofia/internal/
318@mypbx.mydomain.com Action set(callee_id_number=0123456789)
Dialplan: sofia/internal/
318@mypbx.mydomain.com 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/
318@mypbx.mydomain.com Action bridge(sofia/gateway/926e136f-0e02-46e5-85a2-0d0b3c422a4f/0123456789)
2022-08-15 14:24:25.563384 73.63% [DEBUG] switch_core_state_machine.c:281 (sofia/internal/
318@mypbx.mydomain.com) State Change CS_ROUTING -> CS_EXECUTE
2022-08-15 14:24:25.563384 73.63% [DEBUG] switch_core_state_machine.c:640 (sofia/internal/
318@mypbx.mydomain.com) State ROUTING going to sleep
2022-08-15 14:24:25.563384 73.63% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/
318@mypbx.mydomain.com) Running State Change CS_EXECUTE (Cur 3 Tot 18121)
2022-08-15 14:24:25.563384 73.63% [DEBUG] switch_core_state_machine.c:647 (sofia/internal/
318@mypbx.mydomain.com) State EXECUTE
2022-08-15 14:24:25.563384 73.63% [DEBUG] mod_sofia.c:213 sofia/internal/
318@mypbx.mydomain.com SOFIA EXECUTE
2022-08-15 14:24:25.563384 73.63% [DEBUG] switch_core_state_machine.c:323 sofia/internal/
318@mypbx.mydomain.com Standard EXECUTE
EXECUTE [depth=0] sofia/internal/
318@mypbx.mydomain.com set(caller_id_number=318)
2022-08-15 14:24:25.563384 73.63% [DEBUG] mod_dptools.c:1685 SET sofia/internal/
318@mypbx.mydomain.com [caller_id_number]=[318]
EXECUTE [depth=0] sofia/internal/
318@mypbx.mydomain.com set(RFC2822_DATE=Mon, 15 Aug 2022 14:24:25 +0000)
2022-08-15 14:24:25.563384 73.63% [DEBUG] mod_dptools.c:1685 SET sofia/internal/
318@mypbx.mydomain.com [RFC2822_DATE]=[Mon, 15 Aug 2022 14:24:25 +0000]
EXECUTE [depth=0] sofia/internal/
318@mypbx.mydomain.com export(origination_callee_id_name=0123456789)
2022-08-15 14:24:25.563384 73.63% [DEBUG] switch_channel.c:1315 EXPORT (export_vars) [origination_callee_id_name]=[0123456789]
EXECUTE [depth=0] sofia/internal/
318@mypbx.mydomain.com hash(insert/mypbx.mydomain.com-last_dial/318/0123456789)
EXECUTE [depth=0] sofia/internal/
318@mypbx.mydomain.com set(sip_h_X-accountcode=mypbx.mydomain.com)
2022-08-15 14:24:25.563384 73.63% [DEBUG] mod_dptools.c:1685 SET sofia/internal/
318@mypbx.mydomain.com [sip_h_X-accountcode]=[mypbx.mydomain.com]
EXECUTE [depth=0] sofia/internal/
318@mypbx.mydomain.com unset(call_timeout)
2022-08-15 14:24:25.563384 73.63% [DEBUG] mod_dptools.c:1830 UNSET [call_timeout]
EXECUTE [depth=0] sofia/internal/
318@mypbx.mydomain.com set(hangup_after_bridge=true)
2022-08-15 14:24:25.563384 73.63% [DEBUG] mod_dptools.c:1685 SET sofia/internal/
318@mypbx.mydomain.com [hangup_after_bridge]=[true]
EXECUTE [depth=0] sofia/internal/
318@mypbx.mydomain.com set(effective_caller_id_name=)
2022-08-15 14:24:25.563384 73.63% [DEBUG] mod_dptools.c:1685 SET sofia/internal/
318@mypbx.mydomain.com [effective_caller_id_name]=[UNDEF]
EXECUTE [depth=0] sofia/internal/
318@mypbx.mydomain.com set(effective_caller_id_number=+40731000700)
2022-08-15 14:24:25.563384 73.63% [DEBUG] mod_dptools.c:1685 SET sofia/internal/
318@mypbx.mydomain.com [effective_caller_id_number]=[+40731000700]
EXECUTE [depth=0] sofia/internal/
318@mypbx.mydomain.com set(inherit_codec=true)
2022-08-15 14:24:25.563384 73.63% [DEBUG] mod_dptools.c:1685 SET sofia/internal/
318@mypbx.mydomain.com [inherit_codec]=[true]
EXECUTE [depth=0] sofia/internal/
318@mypbx.mydomain.com set(ignore_display_updates=true)
2022-08-15 14:24:25.563384 73.63% [DEBUG] mod_dptools.c:1685 SET sofia/internal/
318@mypbx.mydomain.com [ignore_display_updates]=[true]
fEXECUTE [depth=0] sofia/internal/
318@mypbx.mydomain.com set(callee_id_number=0123456789)
2022-08-15 14:24:25.563384 73.63% [DEBUG] mod_dptools.c:1685 SET sofia/internal/
318@mypbx.mydomain.com [callee_id_number]=[0123456789]
EXECUTE [depth=0] sofia/internal/
318@mypbx.mydomain.com 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)
2022-08-15 14:24:25.563384 73.63% [DEBUG] mod_dptools.c:1685 SET sofia/internal/
318@mypbx.mydomain.com [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/
318@mypbx.mydomain.com bridge(sofia/gateway/926e136f-0e02-46e5-85a2-0d0b3c422a4f/0123456789)
2022-08-15 14:24:25.563384 73.63% [DEBUG] switch_channel.c:1269 sofia/internal/
318@mypbx.mydomain.com EXPORTING[export_vars] [domain_name]=[mypbx.mydomain.com] to event
2022-08-15 14:24:25.563384 73.63% [DEBUG] switch_channel.c:1269 sofia/internal/
318@mypbx.mydomain.com EXPORTING[export_vars] [call_direction]=[outbound] to event
2022-08-15 14:24:25.563384 73.63% [DEBUG] switch_channel.c:1269 sofia/internal/
318@mypbx.mydomain.com EXPORTING[export_vars] [call_direction]=[outbound] to event
2022-08-15 14:24:25.563384 73.63% [DEBUG] switch_channel.c:1269 sofia/internal/
318@mypbx.mydomain.com EXPORTING[export_vars] [origination_callee_id_name]=[0123456789] to event
2022-08-15 14:24:25.563384 73.63% [DEBUG] switch_ivr_originate.c:2281 Parsing global variables
2022-08-15 14:24:25.583387 73.63% [DEBUG] switch_ivr_originate.c:4035 Originate Resulted in Error Cause: 1 [UNALLOCATED_NUMBER]
2022-08-15 14:24:25.583387 73.63% [INFO] mod_dptools.c:3653 Originate Failed. Cause: UNALLOCATED_NUMBER
2022-08-15 14:24:25.583387 73.63% [DEBUG] switch_channel.c:4981 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: UNALLOCATED_NUMBER
2022-08-15 14:24:25.583387 73.63% [NOTICE] switch_core_state_machine.c:382 sofia/internal/
318@mypbx.mydomain.com has executed the last dialplan instruction, hanging up.
2022-08-15 14:24:25.583387 73.63% [NOTICE] switch_core_state_machine.c:384 Hangup sofia/internal/
318@mypbx.mydomain.com [CS_EXECUTE] [NORMAL_CLEARING]
2022-08-15 14:24:25.583387 73.63% [DEBUG] switch_core_state_machine.c:647 (sofia/internal/
318@mypbx.mydomain.com) State EXECUTE going to sleep
2022-08-15 14:24:25.583387 73.63% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/
318@mypbx.mydomain.com) Running State Change CS_HANGUP (Cur 3 Tot 18122)
2022-08-15 14:24:25.583387 73.63% [DEBUG] switch_core_state_machine.c:844 (sofia/internal/
318@mypbx.mydomain.com) Callstate Change RINGING -> HANGUP
2022-08-15 14:24:25.583387 73.63% [DEBUG] switch_core_state_machine.c:846 (sofia/internal/
318@mypbx.mydomain.com) State HANGUP
2022-08-15 14:24:25.583387 73.63% [DEBUG] mod_sofia.c:462 sofia/internal/
318@mypbx.mydomain.com Overriding SIP cause 480 with 404 from the other leg
2022-08-15 14:24:25.583387 73.63% [DEBUG] mod_sofia.c:468 Channel sofia/internal/
318@mypbx.mydomain.com hanging up, cause: NORMAL_CLEARING
2022-08-15 14:24:25.603808 73.63% [DEBUG] mod_sofia.c:613 Responding to INVITE with: 404
2022-08-15 14:24:25.603808 73.63% [DEBUG] switch_core_state_machine.c:59 sofia/internal/
318@mypbx.mydomain.com Standard HANGUP, cause: NORMAL_CLEARING
2022-08-15 14:24:25.603808 73.63% [DEBUG] switch_core_state_machine.c:846 (sofia/internal/
318@mypbx.mydomain.com) State HANGUP going to sleep
2022-08-15 14:24:25.603808 73.63% [DEBUG] switch_core_state_machine.c:616 (sofia/internal/
318@mypbx.mydomain.com) State Change CS_HANGUP -> CS_REPORTING
2022-08-15 14:24:25.603808 73.63% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/
318@mypbx.mydomain.com) Running State Change CS_REPORTING (Cur 3 Tot 18122)
2022-08-15 14:24:25.603808 73.63% [DEBUG] switch_core_state_machine.c:932 (sofia/internal/
318@mypbx.mydomain.com) State REPORTING
2022-08-15 14:24:25.843373 73.63% [DEBUG] switch_core_state_machine.c:168 sofia/internal/
318@mypbx.mydomain.com Standard REPORTING, cause: NORMAL_CLEARING
2022-08-15 14:24:25.843373 73.63% [DEBUG] switch_core_state_machine.c:932 (sofia/internal/
318@mypbx.mydomain.com) State REPORTING going to sleep
2022-08-15 14:24:25.843373 73.63% [DEBUG] switch_core_state_machine.c:607 (sofia/internal/
318@mypbx.mydomain.com) State Change CS_REPORTING -> CS_DESTROY
2022-08-15 14:24:25.843373 73.63% [DEBUG] switch_core_session.c:1753 Session 18121 (sofia/internal/
318@mypbx.mydomain.com) Locked, Waiting on external entities
2022-08-15 14:24:25.843373 73.63% [NOTICE] switch_core_session.c:1771 Session 18121 (sofia/internal/
318@mypbx.mydomain.com) Ended
2022-08-15 14:24:25.843373 73.63% [NOTICE] switch_core_session.c:1775 Close Channel sofia/internal/
318@mypbx.mydomain.com [CS_DESTROY]
2022-08-15 14:24:25.843373 73.63% [DEBUG] switch_core_state_machine.c:735 (sofia/internal/
318@mypbx.mydomain.com) Running State Change CS_DESTROY (Cur 2 Tot 18122)
2022-08-15 14:24:25.843373 73.63% [DEBUG] switch_core_state_machine.c:745 (sofia/internal/
318@mypbx.mydomain.com) State DESTROY
2022-08-15 14:24:25.843373 73.63% [DEBUG] mod_sofia.c:379 sofia/internal/
318@mypbx.mydomain.com SOFIA DESTROY
2022-08-15 14:24:25.843373 73.63% [DEBUG] switch_core_state_machine.c:175 sofia/internal/
318@mypbx.mydomain.com Standard DESTROY
2022-08-15 14:24:25.843373 73.63% [DEBUG] switch_core_state_machine.c:745 (sofia/internal/
318@mypbx.mydomain.com) State DESTROY going to sleep
where:
mypbx.mydomain.com - domain for my pbx, it's a multitenant pbx
111.222.333.444 - ip from extension (it's a softphone on my mobile phone)
318 - extension from my softphone
0123456789 - mobile number that i try to reach
trunk1-fix - sip trunk from voip provider, register mode, which works in/outbound
trunk2-mob - tg400 trunk, peer mode, which works only inbound