+OK log level 7 [7]
2022-04-22 10:27:24.577453 [WARNING] switch_core_state_machine.c:687 b714f266-d654-4cfc-af4c-cd1d2448514e sofia/internal/17@156.0.249.118 Abandoned
2022-04-22 10:27:24.577453 [NOTICE] switch_core_state_machine.c:690 Hangup sofia/internal/17@156.0.249.118 [CS_NEW] [WRONG_CALL_STATE]
2022-04-22 10:27:24.577453 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/17@156.0.249.118) Running State Change CS_HANGUP (Cur 2 Tot 14683)
2022-04-22 10:27:24.577453 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/17@156.0.249.118) Callstate Change DOWN -> HANGUP
2022-04-22 10:27:24.577453 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/17@156.0.249.118) State HANGUP
2022-04-22 10:27:24.577453 [DEBUG] mod_sofia.c:438 Channel sofia/internal/17@156.0.249.118 hanging up, cause: WRONG_CALL_STATE
2022-04-22 10:27:24.577453 [DEBUG] switch_core_state_machine.c:60 sofia/internal/17@156.0.249.118 Standard HANGUP, cause: WRONG_CALL_STATE
2022-04-22 10:27:24.577453 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/17@156.0.249.118) State HANGUP going to sleep
2022-04-22 10:27:24.577453 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/17@156.0.249.118) State Change CS_HANGUP -> CS_REPORTING
2022-04-22 10:27:24.577453 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/17@156.0.249.118) Running State Change CS_REPORTING (Cur 2 Tot 14683)
2022-04-22 10:27:24.577453 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/17@156.0.249.118) State REPORTING
2022-04-22 10:27:24.577453 [DEBUG] switch_core_state_machine.c:174 sofia/internal/17@156.0.249.118 Standard REPORTING, cause: WRONG_CALL_STATE
2022-04-22 10:27:24.577453 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/17@156.0.249.118) State REPORTING going to sleep
2022-04-22 10:27:24.577453 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/17@156.0.249.118) State Change CS_REPORTING -> CS_DESTROY
2022-04-22 10:27:24.577453 [DEBUG] switch_core_session.c:1665 Session 14676 (sofia/internal/17@156.0.249.118) Locked, Waiting on external entities
2022-04-22 10:27:24.577453 [NOTICE] switch_core_session.c:1683 Session 14676 (sofia/internal/17@156.0.249.118) Ended
2022-04-22 10:27:24.577453 [NOTICE] switch_core_session.c:1687 Close Channel sofia/internal/17@156.0.249.118 [CS_DESTROY]
2022-04-22 10:27:24.577453 [DEBUG] switch_core_state_machine.c:741 (sofia/internal/17@156.0.249.118) Running State Change CS_DESTROY (Cur 1 Tot 14683)
2022-04-22 10:27:24.577453 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/17@156.0.249.118) State DESTROY
2022-04-22 10:27:24.577453 [DEBUG] mod_sofia.c:343 sofia/internal/17@156.0.249.118 SOFIA DESTROY
2022-04-22 10:27:24.577453 [DEBUG] switch_core_state_machine.c:181 sofia/internal/17@156.0.249.118 Standard DESTROY
2022-04-22 10:27:24.577453 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/17@156.0.249.118) State DESTROY going to sleep
2022-04-22 10:27:25.737467 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/08176416480@37.9.63.182:5060 [f79acedd-70a7-4303-a9ab-ef0a3fed635b]
2022-04-22 10:27:25.737467 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/08176416480@37.9.63.182:5060) Running State Change CS_NEW (Cur 2 Tot 14684)
2022-04-22 10:27:25.737467 [DEBUG] sofia.c:9873 sofia/internal/08176416480@37.9.63.182:5060 receiving invite from 37.9.63.182:5060 version: 1.6.20 git 43a9feb 2018-05-07 18:56:11Z 64bit
2022-04-22 10:27:25.737467 [DEBUG] sofia.c:9989 IP 37.9.63.182 Approved by acl "domains[]". Access Granted.
2022-04-22 10:27:25.737467 [DEBUG] sofia.c:7084 Channel sofia/internal/08176416480@37.9.63.182:5060 entering state [received][100]
2022-04-22 10:27:25.737467 [DEBUG] sofia.c:7094 Remote SDP:
v=0
o=- 221063692 221063677 IN IP4 37.9.63.182
s=VoipSIP
c=IN IP4 37.9.63.182
t=0 0
m=audio 7618 RTP/AVP 18
a=rtpmap:18 G729/8000/1
a=fmtp:18 annexb=no

2022-04-22 10:27:25.737467 [DEBUG] sofia.c:7486 (sofia/internal/08176416480@37.9.63.182:5060) State Change CS_NEW -> CS_INIT
2022-04-22 10:27:25.737467 [DEBUG] switch_core_state_machine.c:603 (sofia/internal/08176416480@37.9.63.182:5060) State NEW
2022-04-22 10:27:25.737467 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/08176416480@37.9.63.182:5060) Running State Change CS_INIT (Cur 2 Tot 14684)
2022-04-22 10:27:25.737467 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/08176416480@37.9.63.182:5060) State INIT
2022-04-22 10:27:25.737467 [DEBUG] mod_sofia.c:90 sofia/internal/08176416480@37.9.63.182:5060 SOFIA INIT
2022-04-22 10:27:25.737467 [DEBUG] switch_core_state_machine.c:40 sofia/internal/08176416480@37.9.63.182:5060 Standard INIT
2022-04-22 10:27:25.737467 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/08176416480@37.9.63.182:5060) State Change CS_INIT -> CS_ROUTING
2022-04-22 10:27:25.737467 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/08176416480@37.9.63.182:5060) State INIT going to sleep
2022-04-22 10:27:25.737467 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/08176416480@37.9.63.182:5060) Running State Change CS_ROUTING (Cur 2 Tot 14684)
2022-04-22 10:27:25.737467 [DEBUG] switch_channel.c:2249 (sofia/internal/08176416480@37.9.63.182:5060) Callstate Change DOWN -> RINGING
2022-04-22 10:27:25.737467 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/08176416480@37.9.63.182:5060) State ROUTING
2022-04-22 10:27:25.737467 [DEBUG] mod_sofia.c:143 sofia/internal/08176416480@37.9.63.182:5060 SOFIA ROUTING
2022-04-22 10:27:25.737467 [DEBUG] switch_core_state_machine.c:236 sofia/internal/08176416480@37.9.63.182:5060 Standard ROUTING
2022-04-22 10:27:25.737467 [INFO] mod_dialplan_xml.c:637 Processing 08176416480 <08176416480>->23418888325 in context public
Dialplan: sofia/internal/08176416480@37.9.63.182:5060 parsing [public->unloop] continue=false
Dialplan: sofia/internal/08176416480@37.9.63.182:5060 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false
Dialplan: sofia/internal/08176416480@37.9.63.182:5060 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false
Dialplan: sofia/internal/08176416480@37.9.63.182:5060 parsing [public->outside_call] continue=true
Dialplan: sofia/internal/08176416480@37.9.63.182:5060 Absolute Condition [outside_call]
Dialplan: sofia/internal/08176416480@37.9.63.182:5060 Action set(outside_call=true) 
Dialplan: sofia/internal/08176416480@37.9.63.182:5060 Action export(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)}) 
Dialplan: sofia/internal/08176416480@37.9.63.182:5060 parsing [public->call_debug] continue=true
Dialplan: sofia/internal/08176416480@37.9.63.182:5060 Regex (FAIL) [call_debug] ${call_debug}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/08176416480@37.9.63.182:5060 parsing [public->public_extensions] continue=false
Dialplan: sofia/internal/08176416480@37.9.63.182:5060 Regex (FAIL) [public_extensions] destination_number(23418888325) =~ /^(10[01][0-9])$/ break=on-false
Dialplan: sofia/internal/08176416480@37.9.63.182:5060 parsing [public->public_did] continue=false
Dialplan: sofia/internal/08176416480@37.9.63.182:5060 Regex (FAIL) [public_did] destination_number(23418888325) =~ /^(5551212)$/ break=on-false
Dialplan: sofia/internal/08176416480@37.9.63.182:5060 parsing [public->mydid] continue=false
Dialplan: sofia/internal/08176416480@37.9.63.182:5060 Regex (PASS) [mydid] destination_number(23418888325) =~ /^(23418888325)$/ break=on-false
Dialplan: sofia/internal/08176416480@37.9.63.182:5060 Action set(domain_name=156.0.249.118) 
Dialplan: sofia/internal/08176416480@37.9.63.182:5060 Action transfer(1002 XML default) 
2022-04-22 10:27:25.737467 [DEBUG] switch_core_state_machine.c:286 (sofia/internal/08176416480@37.9.63.182:5060) State Change CS_ROUTING -> CS_EXECUTE
2022-04-22 10:27:25.737467 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/08176416480@37.9.63.182:5060) State ROUTING going to sleep
2022-04-22 10:27:25.737467 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/08176416480@37.9.63.182:5060) Running State Change CS_EXECUTE (Cur 2 Tot 14684)
2022-04-22 10:27:25.737467 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/08176416480@37.9.63.182:5060) State EXECUTE
2022-04-22 10:27:25.737467 [DEBUG] mod_sofia.c:198 sofia/internal/08176416480@37.9.63.182:5060 SOFIA EXECUTE
2022-04-22 10:27:25.737467 [DEBUG] switch_core_state_machine.c:328 sofia/internal/08176416480@37.9.63.182:5060 Standard EXECUTE
EXECUTE sofia/internal/08176416480@37.9.63.182:5060 set(outside_call=true)
2022-04-22 10:27:25.737467 [DEBUG] mod_dptools.c:1548 SET sofia/internal/08176416480@37.9.63.182:5060 [outside_call]=[true]
EXECUTE sofia/internal/08176416480@37.9.63.182:5060 export(RFC2822_DATE=Fri, 22 Apr 2022 10:27:25 +0100)
2022-04-22 10:27:25.737467 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [RFC2822_DATE]=[Fri, 22 Apr 2022 10:27:25 +0100]
EXECUTE sofia/internal/08176416480@37.9.63.182:5060 set(domain_name=156.0.249.118)
2022-04-22 10:27:25.737467 [DEBUG] mod_dptools.c:1548 SET sofia/internal/08176416480@37.9.63.182:5060 [domain_name]=[156.0.249.118]
EXECUTE sofia/internal/08176416480@37.9.63.182:5060 transfer(1002 XML default)
2022-04-22 10:27:25.737467 [DEBUG] switch_ivr.c:2165 (sofia/internal/08176416480@37.9.63.182:5060) State Change CS_EXECUTE -> CS_ROUTING
2022-04-22 10:27:25.737467 [NOTICE] switch_ivr.c:2172 Transfer sofia/internal/08176416480@37.9.63.182:5060 to XML[1002@default]
2022-04-22 10:27:25.737467 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/08176416480@37.9.63.182:5060) State EXECUTE going to sleep
2022-04-22 10:27:25.737467 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/08176416480@37.9.63.182:5060) Running State Change CS_ROUTING (Cur 2 Tot 14684)
2022-04-22 10:27:25.737467 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/08176416480@37.9.63.182:5060) State ROUTING
2022-04-22 10:27:25.737467 [DEBUG] mod_sofia.c:143 sofia/internal/08176416480@37.9.63.182:5060 SOFIA ROUTING
2022-04-22 10:27:25.737467 [DEBUG] switch_core_state_machine.c:236 sofia/internal/08176416480@37.9.63.182:5060 Standard ROUTING
2022-04-22 10:27:25.737467 [INFO] mod_dialplan_xml.c:637 Processing 08176416480 <08176416480>->1002 in context default
Dialplan: sofia/internal/08176416480@37.9.63.182:5060 parsing [default->nativetalk] continue=false
Dialplan: sofia/internal/08176416480@37.9.63.182:5060 Regex (FAIL) [nativetalk] destination_number(1002) =~ /^(/d{11)$/ break=on-false
Dialplan: sofia/internal/08176416480@37.9.63.182:5060 parsing [default->unloop] continue=false
Dialplan: sofia/internal/08176416480@37.9.63.182:5060 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false
Dialplan: sofia/internal/08176416480@37.9.63.182:5060 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false
Dialplan: sofia/internal/08176416480@37.9.63.182:5060 parsing [default->tod_example] continue=true
Dialplan: sofia/internal/08176416480@37.9.63.182:5060 Date/Time Match (PASS) [tod_example] break=on-false
Dialplan: sofia/internal/08176416480@37.9.63.182:5060 Action set(open=true) 
Dialplan: sofia/internal/08176416480@37.9.63.182:5060 parsing [default->holiday_example] continue=true
Dialplan: sofia/internal/08176416480@37.9.63.182:5060 Date/TimeMatch (FAIL) [holiday_example] break=on-false
Dialplan: sofia/internal/08176416480@37.9.63.182:5060 parsing [default->global-intercept] continue=false
Dialplan: sofia/internal/08176416480@37.9.63.182:5060 Regex (FAIL) [global-intercept] destination_number(1002) =~ /^886$/ break=on-false
Dialplan: sofia/internal/08176416480@37.9.63.182:5060 parsing [default->group-intercept] continue=false
Dialplan: sofia/internal/08176416480@37.9.63.182:5060 Regex (FAIL) [group-intercept] destination_number(1002) =~ /^\*8$/ break=on-false
Dialplan: sofia/internal/08176416480@37.9.63.182:5060 parsing [default->intercept-ext] continue=false
Dialplan: sofia/internal/08176416480@37.9.63.182:5060 Regex (FAIL) [intercept-ext] destination_number(1002) =~ /^\*\*(\d+)$/ break=on-false
Dialplan: sofia/internal/08176416480@37.9.63.182:5060 parsing [default->redial] continue=false
Dialplan: sofia/internal/08176416480@37.9.63.182:5060 Regex (FAIL) [redial] destination_number(1002) =~ /^(redial|870)$/ break=on-false
Dialplan: sofia/internal/08176416480@37.9.63.182:5060 parsing [default->global] continue=true
Dialplan: sofia/internal/08176416480@37.9.63.182:5060 Regex (FAIL) [global] ${call_debug}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/08176416480@37.9.63.182:5060 Regex (FAIL) [global] ${default_password}(012345) =~ /^1234$/ break=never
Dialplan: sofia/internal/08176416480@37.9.63.182:5060 Regex (FAIL) [global] ${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=never
Dialplan: sofia/internal/08176416480@37.9.63.182:5060 Regex (PASS) [global] ${endpoint_disposition}(DELAYED NEGOTIATION) =~ /^(DELAYED NEGOTIATION)/ break=on-false
Dialplan: sofia/internal/08176416480@37.9.63.182:5060 Regex (FAIL) [global] ${switch_r_sdp}(v=0
o=- 221063692 221063677 IN IP4 37.9.63.182
s=VoipSIP
c=IN IP4 37.9.63.182
t=0 0
m=audio 7618 RTP/AVP 18
a=rtpmap:18 G729/8000/1
a=fmtp:18 annexb=no
) =~ /(AES_CM_128_HMAC_SHA1_32|AES_CM_128_HMAC_SHA1_80)/ break=never
Dialplan: sofia/internal/08176416480@37.9.63.182:5060 Absolute Condition [global]
Dialplan: sofia/internal/08176416480@37.9.63.182:5060 Action hash(insert/${domain_name}-spymap/${caller_id_number}/${uuid}) 
Dialplan: sofia/internal/08176416480@37.9.63.182:5060 Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number}) 
Dialplan: sofia/internal/08176416480@37.9.63.182:5060 Action hash(insert/${domain_name}-last_dial/global/${uuid}) 
Dialplan: sofia/internal/08176416480@37.9.63.182:5060 Action export(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)}) 
Dialplan: sofia/internal/08176416480@37.9.63.182:5060 parsing [default->snom-demo-2] continue=false
Dialplan: sofia/internal/08176416480@37.9.63.182:5060 Regex (FAIL) [snom-demo-2] destination_number(1002) =~ /^9001$/ break=on-false
Dialplan: sofia/internal/08176416480@37.9.63.182:5060 parsing [default->snom-demo-1] continue=false
Dialplan: sofia/internal/08176416480@37.9.63.182:5060 Regex (FAIL) [snom-demo-1] destination_number(1002) =~ /^9000$/ break=on-false
Dialplan: sofia/internal/08176416480@37.9.63.182:5060 parsing [default->eavesdrop] continue=false
Dialplan: sofia/internal/08176416480@37.9.63.182:5060 Regex (FAIL) [eavesdrop] destination_number(1002) =~ /^88(\d{4})$|^\*0(.*)$/ break=on-false
Dialplan: sofia/internal/08176416480@37.9.63.182:5060 parsing [default->eavesdrop] continue=false
Dialplan: sofia/internal/08176416480@37.9.63.182:5060 Regex (FAIL) [eavesdrop] destination_number(1002) =~ /^779$/ break=on-false
Dialplan: sofia/internal/08176416480@37.9.63.182:5060 parsing [default->call_return] continue=false
Dialplan: sofia/internal/08176416480@37.9.63.182:5060 Regex (FAIL) [call_return] destination_number(1002) =~ /^\*69$|^869$|^lcr$/ break=on-false
Dialplan: sofia/internal/08176416480@37.9.63.182:5060 parsing [default->del-group] continue=false
Dialplan: sofia/internal/08176416480@37.9.63.182:5060 Regex (FAIL) [del-group] destination_number(1002) =~ /^80(\d{2})$/ break=on-false
Dialplan: sofia/internal/08176416480@37.9.63.182:5060 parsing [default->add-group] continue=false
Dialplan: sofia/internal/08176416480@37.9.63.182:5060 Regex (FAIL) [add-group] destination_number(1002) =~ /^81(\d{2})$/ break=on-false
Dialplan: sofia/internal/08176416480@37.9.63.182:5060 parsing [default->call-group-simo] continue=false
Dialplan: sofia/internal/08176416480@37.9.63.182:5060 Regex (FAIL) [call-group-simo] destination_number(1002) =~ /^82(\d{2})$/ break=on-false
Dialplan: sofia/internal/08176416480@37.9.63.182:5060 parsing [default->call-group-order] continue=false
Dialplan: sofia/internal/08176416480@37.9.63.182:5060 Regex (FAIL) [call-group-order] destination_number(1002) =~ /^83(\d{2})$/ break=on-false
Dialplan: sofia/internal/08176416480@37.9.63.182:5060 parsing [default->extension-intercom] continue=false
Dialplan: sofia/internal/08176416480@37.9.63.182:5060 Regex (FAIL) [extension-intercom] destination_number(1002) =~ /^8(10[01][0-9])$/ break=on-false
Dialplan: sofia/internal/08176416480@37.9.63.182:5060 parsing [default->Local_Extension] continue=false
Dialplan: sofia/internal/08176416480@37.9.63.182:5060 Regex (PASS) [Local_Extension] destination_number(1002) =~ /^(10[0-9]|1[1-9][0-9]|[2-9][0-9]{2}|10[01][0-9])$/ break=on-false
Dialplan: sofia/internal/08176416480@37.9.63.182:5060 Action export(dialed_extension=1002) 
Dialplan: sofia/internal/08176416480@37.9.63.182:5060 Action bind_meta_app(1 b s execute_extension::dx XML features) 
Dialplan: sofia/internal/08176416480@37.9.63.182:5060 Action bind_meta_app(2 b s record_session::/usr/local/freeswitch/recordings/${caller_id_number}.${strftime(%Y-%m-%d-%H-%M-%S)}.wav) 
Dialplan: sofia/internal/08176416480@37.9.63.182:5060 Action bind_meta_app(3 b s execute_extension::cf XML features) 
Dialplan: sofia/internal/08176416480@37.9.63.182:5060 Action bind_meta_app(4 b s execute_extension::att_xfer XML features) 
Dialplan: sofia/internal/08176416480@37.9.63.182:5060 Action set(ringback=${us-ring}) 
Dialplan: sofia/internal/08176416480@37.9.63.182:5060 Action set(transfer_ringback=local_stream://moh) 
Dialplan: sofia/internal/08176416480@37.9.63.182:5060 Action set(call_timeout=30) 
Dialplan: sofia/internal/08176416480@37.9.63.182:5060 Action set(hangup_after_bridge=true) 
Dialplan: sofia/internal/08176416480@37.9.63.182:5060 Action set(continue_on_fail=true) 
Dialplan: sofia/internal/08176416480@37.9.63.182:5060 Action hash(insert/${domain_name}-call_return/${dialed_extension}/${caller_id_number}) 
Dialplan: sofia/internal/08176416480@37.9.63.182:5060 Action hash(insert/${domain_name}-last_dial_ext/${dialed_extension}/${uuid}) 
Dialplan: sofia/internal/08176416480@37.9.63.182:5060 Action set(called_party_callgroup=${user_data(${dialed_extension}@${domain_name} var callgroup)}) 
Dialplan: sofia/internal/08176416480@37.9.63.182:5060 Action hash(insert/${domain_name}-last_dial_ext/${called_party_callgroup}/${uuid}) 
Dialplan: sofia/internal/08176416480@37.9.63.182:5060 Action hash(insert/${domain_name}-last_dial_ext/global/${uuid}) 
Dialplan: sofia/internal/08176416480@37.9.63.182:5060 Action hash(insert/${domain_name}-last_dial/${called_party_callgroup}/${uuid}) 
Dialplan: sofia/internal/08176416480@37.9.63.182:5060 Action bridge(user/${dialed_extension}@${domain_name}) 
Dialplan: sofia/internal/08176416480@37.9.63.182:5060 Action answer() 
Dialplan: sofia/internal/08176416480@37.9.63.182:5060 Action sleep(1000) 
Dialplan: sofia/internal/08176416480@37.9.63.182:5060 Action bridge(loopback/app=voicemail:default ${domain_name} ${dialed_extension}) 
2022-04-22 10:27:25.737467 [DEBUG] switch_core_state_machine.c:286 (sofia/internal/08176416480@37.9.63.182:5060) State Change CS_ROUTING -> CS_EXECUTE
2022-04-22 10:27:25.737467 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/08176416480@37.9.63.182:5060) State ROUTING going to sleep
2022-04-22 10:27:25.737467 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/08176416480@37.9.63.182:5060) Running State Change CS_EXECUTE (Cur 2 Tot 14684)
2022-04-22 10:27:25.737467 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/08176416480@37.9.63.182:5060) State EXECUTE
2022-04-22 10:27:25.737467 [DEBUG] mod_sofia.c:198 sofia/internal/08176416480@37.9.63.182:5060 SOFIA EXECUTE
2022-04-22 10:27:25.737467 [DEBUG] switch_core_state_machine.c:328 sofia/internal/08176416480@37.9.63.182:5060 Standard EXECUTE
EXECUTE sofia/internal/08176416480@37.9.63.182:5060 set(open=true)
2022-04-22 10:27:25.737467 [DEBUG] mod_dptools.c:1548 SET sofia/internal/08176416480@37.9.63.182:5060 [open]=[true]
EXECUTE sofia/internal/08176416480@37.9.63.182:5060 hash(insert/156.0.249.118-spymap/08176416480/f79acedd-70a7-4303-a9ab-ef0a3fed635b)
EXECUTE sofia/internal/08176416480@37.9.63.182:5060 hash(insert/156.0.249.118-last_dial/08176416480/1002)
EXECUTE sofia/internal/08176416480@37.9.63.182:5060 hash(insert/156.0.249.118-last_dial/global/f79acedd-70a7-4303-a9ab-ef0a3fed635b)
EXECUTE sofia/internal/08176416480@37.9.63.182:5060 export(RFC2822_DATE=Fri, 22 Apr 2022 10:27:25 +0100)
2022-04-22 10:27:25.757373 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [RFC2822_DATE]=[Fri, 22 Apr 2022 10:27:25 +0100]
EXECUTE sofia/internal/08176416480@37.9.63.182:5060 export(dialed_extension=1002)
2022-04-22 10:27:25.757373 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [dialed_extension]=[1002]
EXECUTE sofia/internal/08176416480@37.9.63.182:5060 bind_meta_app(1 b s execute_extension::dx XML features)
2022-04-22 10:27:25.757373 [INFO] switch_ivr_async.c:4173 Bound B-Leg: *1 execute_extension::dx XML features
EXECUTE sofia/internal/08176416480@37.9.63.182:5060 bind_meta_app(2 b s record_session::/usr/local/freeswitch/recordings/08176416480.2022-04-22-10-27-25.wav)
2022-04-22 10:27:25.757373 [INFO] switch_ivr_async.c:4173 Bound B-Leg: *2 record_session::/usr/local/freeswitch/recordings/08176416480.2022-04-22-10-27-25.wav
EXECUTE sofia/internal/08176416480@37.9.63.182:5060 bind_meta_app(3 b s execute_extension::cf XML features)
2022-04-22 10:27:25.757373 [INFO] switch_ivr_async.c:4173 Bound B-Leg: *3 execute_extension::cf XML features
EXECUTE sofia/internal/08176416480@37.9.63.182:5060 bind_meta_app(4 b s execute_extension::att_xfer XML features)
2022-04-22 10:27:25.757373 [INFO] switch_ivr_async.c:4173 Bound B-Leg: *4 execute_extension::att_xfer XML features
EXECUTE sofia/internal/08176416480@37.9.63.182:5060 set(ringback=%(2000,4000,440,480))
2022-04-22 10:27:25.757373 [DEBUG] mod_dptools.c:1548 SET sofia/internal/08176416480@37.9.63.182:5060 [ringback]=[%(2000,4000,440,480)]
EXECUTE sofia/internal/08176416480@37.9.63.182:5060 set(transfer_ringback=local_stream://moh)
2022-04-22 10:27:25.757373 [DEBUG] mod_dptools.c:1548 SET sofia/internal/08176416480@37.9.63.182:5060 [transfer_ringback]=[local_stream://moh]
EXECUTE sofia/internal/08176416480@37.9.63.182:5060 set(call_timeout=30)
2022-04-22 10:27:25.757373 [DEBUG] mod_dptools.c:1548 SET sofia/internal/08176416480@37.9.63.182:5060 [call_timeout]=[30]
EXECUTE sofia/internal/08176416480@37.9.63.182:5060 set(hangup_after_bridge=true)
2022-04-22 10:27:25.757373 [DEBUG] mod_dptools.c:1548 SET sofia/internal/08176416480@37.9.63.182:5060 [hangup_after_bridge]=[true]
EXECUTE sofia/internal/08176416480@37.9.63.182:5060 set(continue_on_fail=true)
2022-04-22 10:27:25.757373 [DEBUG] mod_dptools.c:1548 SET sofia/internal/08176416480@37.9.63.182:5060 [continue_on_fail]=[true]
EXECUTE sofia/internal/08176416480@37.9.63.182:5060 hash(insert/156.0.249.118-call_return/1002/08176416480)
EXECUTE sofia/internal/08176416480@37.9.63.182:5060 hash(insert/156.0.249.118-last_dial_ext/1002/f79acedd-70a7-4303-a9ab-ef0a3fed635b)
EXECUTE sofia/internal/08176416480@37.9.63.182:5060 set(called_party_callgroup=techsupport)
2022-04-22 10:27:25.757373 [DEBUG] mod_dptools.c:1548 SET sofia/internal/08176416480@37.9.63.182:5060 [called_party_callgroup]=[techsupport]
EXECUTE sofia/internal/08176416480@37.9.63.182:5060 hash(insert/156.0.249.118-last_dial_ext/techsupport/f79acedd-70a7-4303-a9ab-ef0a3fed635b)
EXECUTE sofia/internal/08176416480@37.9.63.182:5060 hash(insert/156.0.249.118-last_dial_ext/global/f79acedd-70a7-4303-a9ab-ef0a3fed635b)
EXECUTE sofia/internal/08176416480@37.9.63.182:5060 hash(insert/156.0.249.118-last_dial/techsupport/f79acedd-70a7-4303-a9ab-ef0a3fed635b)
EXECUTE sofia/internal/08176416480@37.9.63.182:5060 bridge(user/1002@156.0.249.118)
2022-04-22 10:27:25.757373 [DEBUG] switch_channel.c:1250 sofia/internal/08176416480@37.9.63.182:5060 EXPORTING[export_vars] [RFC2822_DATE]=[Fri, 22 Apr 2022 10:27:25 +0100] to event
2022-04-22 10:27:25.757373 [DEBUG] switch_channel.c:1250 sofia/internal/08176416480@37.9.63.182:5060 EXPORTING[export_vars] [RFC2822_DATE]=[Fri, 22 Apr 2022 10:27:25 +0100] to event
2022-04-22 10:27:25.757373 [DEBUG] switch_channel.c:1250 sofia/internal/08176416480@37.9.63.182:5060 EXPORTING[export_vars] [dialed_extension]=[1002] to event
2022-04-22 10:27:25.757373 [DEBUG] switch_ivr_originate.c:2142 Parsing global variables
2022-04-22 10:27:25.757373 [DEBUG] switch_channel.c:1250 sofia/internal/08176416480@37.9.63.182:5060 EXPORTING[export_vars] [RFC2822_DATE]=[Fri, 22 Apr 2022 10:27:25 +0100] to event
2022-04-22 10:27:25.757373 [DEBUG] switch_channel.c:1250 sofia/internal/08176416480@37.9.63.182:5060 EXPORTING[export_vars] [RFC2822_DATE]=[Fri, 22 Apr 2022 10:27:25 +0100] to event
2022-04-22 10:27:25.757373 [DEBUG] switch_channel.c:1250 sofia/internal/08176416480@37.9.63.182:5060 EXPORTING[export_vars] [dialed_extension]=[1002] to event
2022-04-22 10:27:25.757373 [DEBUG] switch_ivr_originate.c:2142 Parsing global variables
2022-04-22 10:27:25.757373 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/1002@41.204.224.210:5060 [9d8f8d44-d5de-4b30-b2a7-f0a0886df5f8]
2022-04-22 10:27:25.757373 [DEBUG] mod_sofia.c:4819 (sofia/internal/1002@41.204.224.210:5060) State Change CS_NEW -> CS_INIT
2022-04-22 10:27:25.757373 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1002@41.204.224.210:5060) Running State Change CS_INIT (Cur 3 Tot 14685)
2022-04-22 10:27:25.757373 [NOTICE] switch_ivr_originate.c:2851 Cannot create outgoing channel of type [error] cause: [USER_NOT_REGISTERED]
2022-04-22 10:27:25.757373 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/1002@41.204.224.210:5060) State INIT
2022-04-22 10:27:25.757373 [DEBUG] mod_sofia.c:90 sofia/internal/1002@41.204.224.210:5060 SOFIA INIT
2022-04-22 10:27:25.757373 [DEBUG] sofia_glue.c:1295 sofia/internal/1002@41.204.224.210:5060 sending invite version: 1.6.20 git 43a9feb 2018-05-07 18:56:11Z 64bit
Local SDP:
v=0
o=FreeSWITCH 1650587957 1650587958 IN IP4 156.0.249.118
s=FreeSWITCH
c=IN IP4 156.0.249.118
t=0 0
m=audio 31688 RTP/AVP 9 0 8 101
a=rtpmap:9 G722/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv
m=video 17190 RTP/AVP 102
b=AS:1024
a=rtpmap:102 VP8/90000
a=rtcp-fb:102 ccm fir
a=rtcp-fb:102 ccm tmmbr
a=rtcp-fb:102 nack
a=rtcp-fb:102 nack pli

2022-04-22 10:27:25.757373 [DEBUG] switch_core_state_machine.c:40 sofia/internal/1002@41.204.224.210:5060 Standard INIT
2022-04-22 10:27:25.757373 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/1002@41.204.224.210:5060) State Change CS_INIT -> CS_ROUTING
2022-04-22 10:27:25.757373 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/1002@41.204.224.210:5060) State INIT going to sleep
2022-04-22 10:27:25.757373 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1002@41.204.224.210:5060) Running State Change CS_ROUTING (Cur 3 Tot 14685)
2022-04-22 10:27:25.757373 [DEBUG] sofia.c:7084 Channel sofia/internal/1002@41.204.224.210:5060 entering state [calling][0]
2022-04-22 10:27:25.757373 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/1002@41.204.224.210:5060) State ROUTING
2022-04-22 10:27:25.757373 [DEBUG] mod_sofia.c:143 sofia/internal/1002@41.204.224.210:5060 SOFIA ROUTING
2022-04-22 10:27:25.757373 [DEBUG] switch_ivr_originate.c:67 (sofia/internal/1002@41.204.224.210:5060) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2022-04-22 10:27:25.757373 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/1002@41.204.224.210:5060) State ROUTING going to sleep
2022-04-22 10:27:25.757373 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1002@41.204.224.210:5060) Running State Change CS_CONSUME_MEDIA (Cur 3 Tot 14685)
2022-04-22 10:27:25.757373 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/1002@41.204.224.210:5060) State CONSUME_MEDIA
2022-04-22 10:27:25.757373 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/1002@41.204.224.210:5060) State CONSUME_MEDIA going to sleep
2022-04-22 10:27:26.097407 [DEBUG] sofia.c:7084 Channel sofia/internal/1002@41.204.224.210:5060 entering state [proceeding][180]
2022-04-22 10:27:26.097407 [NOTICE] sofia.c:7192 Ring-Ready sofia/internal/1002@41.204.224.210:5060!
2022-04-22 10:27:26.097407 [DEBUG] switch_channel.c:3346 (sofia/internal/1002@41.204.224.210:5060) Callstate Change DOWN -> RINGING
2022-04-22 10:27:26.117386 [INFO] switch_ivr_originate.c:1215 Sending early media
2022-04-22 10:27:26.117386 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G729:18:8000:20:8000:1]/[G722:9:8000:20:64000:1]
2022-04-22 10:27:26.117386 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMU:0:8000:20:64000:1]
2022-04-22 10:27:26.117386 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMA:8:8000:20:64000:1]
2022-04-22 10:27:26.117386 [DEBUG] switch_core_media.c:4738 No 2833 in SDP. Liberal DTMF mode adding 101 as telephone-event.
2022-04-22 10:27:26.117386 [DEBUG] switch_core_media.c:4767 sofia/internal/08176416480@37.9.63.182:5060 Set 2833 dtmf send payload to 101 recv payload to 101
2022-04-22 10:27:26.117386 [ERR] mod_sofia.c:2343 CODEC NEGOTIATION ERROR.  SDP:
v=0
o=- 221063692 221063677 IN IP4 37.9.63.182
s=VoipSIP
c=IN IP4 37.9.63.182
t=0 0
m=audio 7618 RTP/AVP 18
a=rtpmap:18 G729/8000/1
a=fmtp:18 annexb=no

2022-04-22 10:27:26.117386 [NOTICE] switch_channel.c:3515 Hangup sofia/internal/08176416480@37.9.63.182:5060 [CS_EXECUTE] [INCOMPATIBLE_DESTINATION]
2022-04-22 10:27:26.117386 [DEBUG] switch_ivr_originate.c:1216 sofia/internal/08176416480@37.9.63.182:5060 Media Establishment Failed.
2022-04-22 10:27:26.117386 [DEBUG] switch_ivr_originate.c:3848 Originate Resulted in Error Cause: 606 [USER_NOT_REGISTERED]
2022-04-22 10:27:26.117386 [NOTICE] switch_ivr_originate.c:3938 Hangup sofia/internal/1002@41.204.224.210:5060 [CS_CONSUME_MEDIA] [USER_NOT_REGISTERED]
2022-04-22 10:27:26.117386 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1002@41.204.224.210:5060) Running State Change CS_HANGUP (Cur 3 Tot 14685)
2022-04-22 10:27:26.117386 [NOTICE] switch_ivr_originate.c:2851 Cannot create outgoing channel of type [user] cause: [USER_NOT_REGISTERED]
2022-04-22 10:27:26.117386 [DEBUG] switch_ivr_originate.c:3848 Originate Resulted in Error Cause: 606 [USER_NOT_REGISTERED]
2022-04-22 10:27:26.117386 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/1002@41.204.224.210:5060) Callstate Change RINGING -> HANGUP
2022-04-22 10:27:26.117386 [INFO] mod_dptools.c:3436 Originate Failed.  Cause: USER_NOT_REGISTERED
2022-04-22 10:27:26.117386 [DEBUG] switch_core_session.c:2815 sofia/internal/08176416480@37.9.63.182:5060 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
2022-04-22 10:27:26.117386 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/08176416480@37.9.63.182:5060) State EXECUTE going to sleep
2022-04-22 10:27:26.117386 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/08176416480@37.9.63.182:5060) Running State Change CS_HANGUP (Cur 3 Tot 14685)
2022-04-22 10:27:26.117386 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/1002@41.204.224.210:5060) State HANGUP
2022-04-22 10:27:26.117386 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/08176416480@37.9.63.182:5060) Callstate Change RINGING -> HANGUP
2022-04-22 10:27:26.117386 [DEBUG] mod_sofia.c:438 Channel sofia/internal/1002@41.204.224.210:5060 hanging up, cause: USER_NOT_REGISTERED
2022-04-22 10:27:26.117386 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/08176416480@37.9.63.182:5060) State HANGUP
2022-04-22 10:27:26.117386 [DEBUG] mod_sofia.c:438 Channel sofia/internal/08176416480@37.9.63.182:5060 hanging up, cause: INCOMPATIBLE_DESTINATION
2022-04-22 10:27:26.117386 [DEBUG] mod_sofia.c:502 Sending CANCEL to sofia/internal/1002@41.204.224.210:5060
2022-04-22 10:27:26.117386 [DEBUG] switch_core_state_machine.c:60 sofia/internal/1002@41.204.224.210:5060 Standard HANGUP, cause: USER_NOT_REGISTERED
2022-04-22 10:27:26.117386 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/1002@41.204.224.210:5060) State HANGUP going to sleep
2022-04-22 10:27:26.117386 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/1002@41.204.224.210:5060) State Change CS_HANGUP -> CS_REPORTING
2022-04-22 10:27:26.117386 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1002@41.204.224.210:5060) Running State Change CS_REPORTING (Cur 3 Tot 14685)
2022-04-22 10:27:26.117386 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/1002@41.204.224.210:5060) State REPORTING
2022-04-22 10:27:26.117386 [DEBUG] switch_core_state_machine.c:174 sofia/internal/1002@41.204.224.210:5060 Standard REPORTING, cause: USER_NOT_REGISTERED
2022-04-22 10:27:26.117386 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/1002@41.204.224.210:5060) State REPORTING going to sleep
2022-04-22 10:27:26.117386 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/1002@41.204.224.210:5060) State Change CS_REPORTING -> CS_DESTROY
2022-04-22 10:27:26.117386 [DEBUG] switch_core_session.c:1665 Session 14685 (sofia/internal/1002@41.204.224.210:5060) Locked, Waiting on external entities
2022-04-22 10:27:26.117386 [NOTICE] switch_core_session.c:1683 Session 14685 (sofia/internal/1002@41.204.224.210:5060) Ended
2022-04-22 10:27:26.117386 [NOTICE] switch_core_session.c:1687 Close Channel sofia/internal/1002@41.204.224.210:5060 [CS_DESTROY]
2022-04-22 10:27:26.117386 [DEBUG] switch_core_state_machine.c:741 (sofia/internal/1002@41.204.224.210:5060) Running State Change CS_DESTROY (Cur 2 Tot 14685)
2022-04-22 10:27:26.117386 [DEBUG] mod_sofia.c:577 Responding to INVITE with: 488
2022-04-22 10:27:26.117386 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/1002@41.204.224.210:5060) State DESTROY
2022-04-22 10:27:26.117386 [DEBUG] mod_sofia.c:343 sofia/internal/1002@41.204.224.210:5060 SOFIA DESTROY
2022-04-22 10:27:26.117386 [DEBUG] switch_core_state_machine.c:181 sofia/internal/1002@41.204.224.210:5060 Standard DESTROY
2022-04-22 10:27:26.117386 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/1002@41.204.224.210:5060) State DESTROY going to sleep
2022-04-22 10:27:26.117386 [DEBUG] switch_core_state_machine.c:60 sofia/internal/08176416480@37.9.63.182:5060 Standard HANGUP, cause: INCOMPATIBLE_DESTINATION
2022-04-22 10:27:26.117386 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/08176416480@37.9.63.182:5060) State HANGUP going to sleep
2022-04-22 10:27:26.117386 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/08176416480@37.9.63.182:5060) State Change CS_HANGUP -> CS_REPORTING
2022-04-22 10:27:26.117386 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/08176416480@37.9.63.182:5060) Running State Change CS_REPORTING (Cur 2 Tot 14685)
2022-04-22 10:27:26.117386 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/08176416480@37.9.63.182:5060) State REPORTING
2022-04-22 10:27:26.117386 [DEBUG] switch_core_state_machine.c:174 sofia/internal/08176416480@37.9.63.182:5060 Standard REPORTING, cause: INCOMPATIBLE_DESTINATION
2022-04-22 10:27:26.117386 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/08176416480@37.9.63.182:5060) State REPORTING going to sleep
2022-04-22 10:27:26.117386 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/08176416480@37.9.63.182:5060) State Change CS_REPORTING -> CS_DESTROY
2022-04-22 10:27:26.117386 [DEBUG] switch_core_session.c:1665 Session 14684 (sofia/internal/08176416480@37.9.63.182:5060) Locked, Waiting on external entities
2022-04-22 10:27:26.117386 [NOTICE] switch_core_session.c:1683 Session 14684 (sofia/internal/08176416480@37.9.63.182:5060) Ended
2022-04-22 10:27:26.117386 [NOTICE] switch_core_session.c:1687 Close Channel sofia/internal/08176416480@37.9.63.182:5060 [CS_DESTROY]
2022-04-22 10:27:26.117386 [DEBUG] switch_core_state_machine.c:741 (sofia/internal/08176416480@37.9.63.182:5060) Running State Change CS_DESTROY (Cur 1 Tot 14685)
2022-04-22 10:27:26.117386 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/08176416480@37.9.63.182:5060) State DESTROY
2022-04-22 10:27:26.117386 [DEBUG] mod_sofia.c:343 sofia/internal/08176416480@37.9.63.182:5060 SOFIA DESTROY
2022-04-22 10:27:26.117386 [DEBUG] switch_core_state_machine.c:181 sofia/internal/08176416480@37.9.63.182:5060 Standard DESTROY
2022-04-22 10:27:26.117386 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/08176416480@37.9.63.182:5060) State DESTROY going to sleep
2022-04-22 10:27:26.677391 [WARNING] switch_core_state_machine.c:687 d97b5d8b-18ce-4d1f-8dca-aac956a3a128 sofia/internal/10001@156.0.249.118 Abandoned
2022-04-22 10:27:26.677391 [NOTICE] switch_core_state_machine.c:690 Hangup sofia/internal/10001@156.0.249.118 [CS_NEW] [WRONG_CALL_STATE]
2022-04-22 10:27:26.677391 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/10001@156.0.249.118) Running State Change CS_HANGUP (Cur 1 Tot 14685)
2022-04-22 10:27:26.677391 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/10001@156.0.249.118) Callstate Change DOWN -> HANGUP
2022-04-22 10:27:26.677391 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/10001@156.0.249.118) State HANGUP
2022-04-22 10:27:26.677391 [DEBUG] mod_sofia.c:438 Channel sofia/internal/10001@156.0.249.118 hanging up, cause: WRONG_CALL_STATE
2022-04-22 10:27:26.677391 [DEBUG] switch_core_state_machine.c:60 sofia/internal/10001@156.0.249.118 Standard HANGUP, cause: WRONG_CALL_STATE
2022-04-22 10:27:26.677391 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/10001@156.0.249.118) State HANGUP going to sleep
2022-04-22 10:27:26.677391 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/10001@156.0.249.118) State Change CS_HANGUP -> CS_REPORTING
2022-04-22 10:27:26.677391 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/10001@156.0.249.118) Running State Change CS_REPORTING (Cur 1 Tot 14685)
2022-04-22 10:27:26.677391 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/10001@156.0.249.118) State REPORTING
2022-04-22 10:27:26.677391 [DEBUG] switch_core_state_machine.c:174 sofia/internal/10001@156.0.249.118 Standard REPORTING, cause: WRONG_CALL_STATE
2022-04-22 10:27:26.677391 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/10001@156.0.249.118) State REPORTING going to sleep
2022-04-22 10:27:26.677391 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/10001@156.0.249.118) State Change CS_REPORTING -> CS_DESTROY
2022-04-22 10:27:26.677391 [DEBUG] switch_core_session.c:1665 Session 14679 (sofia/internal/10001@156.0.249.118) Locked, Waiting on external entities
2022-04-22 10:27:26.677391 [NOTICE] switch_core_session.c:1683 Session 14679 (sofia/internal/10001@156.0.249.118) Ended
2022-04-22 10:27:26.677391 [NOTICE] switch_core_session.c:1687 Close Channel sofia/internal/10001@156.0.249.118 [CS_DESTROY]
2022-04-22 10:27:26.677391 [DEBUG] switch_core_state_machine.c:741 (sofia/internal/10001@156.0.249.118) Running State Change CS_DESTROY (Cur 0 Tot 14685)
2022-04-22 10:27:26.677391 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/10001@156.0.249.118) State DESTROY
2022-04-22 10:27:26.677391 [DEBUG] mod_sofia.c:343 sofia/internal/10001@156.0.249.118 SOFIA DESTROY
2022-04-22 10:27:26.677391 [DEBUG] switch_core_state_machine.c:181 sofia/internal/10001@156.0.249.118 Standard DESTROY
2022-04-22 10:27:26.677391 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/10001@156.0.249.118) State DESTROY going to sleep
2022-04-22 10:27:27.277382 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/1000@156.0.249.118 [a25b8ee0-7e54-4213-a05a-75014319fada]
2022-04-22 10:27:27.277382 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1000@156.0.249.118) Running State Change CS_NEW (Cur 1 Tot 14686)
2022-04-22 10:27:27.277382 [DEBUG] sofia.c:9873 sofia/internal/1000@156.0.249.118 receiving invite from 103.213.247.230:63874 version: 1.6.20 git 43a9feb 2018-05-07 18:56:11Z 64bit
2022-04-22 10:27:27.277382 [DEBUG] sofia.c:10044 IP 103.213.247.230 Rejected by acl "domains". Falling back to Digest auth.
2022-04-22 10:27:27.277382 [DEBUG] switch_core_state_machine.c:603 (sofia/internal/1000@156.0.249.118) State NEW
2022-04-22 10:27:27.277382 [DEBUG] sofia.c:2334 detaching session a25b8ee0-7e54-4213-a05a-75014319fada
2022-04-22 10:27:27.577389 [DEBUG] sofia.c:2442 Re-attaching to session a25b8ee0-7e54-4213-a05a-75014319fada
2022-04-22 10:27:27.577389 [DEBUG] sofia.c:9873 sofia/internal/1000@156.0.249.118 receiving invite from 103.213.247.230:63874 version: 1.6.20 git 43a9feb 2018-05-07 18:56:11Z 64bit
2022-04-22 10:27:27.577389 [DEBUG] sofia.c:10044 IP 103.213.247.230 Rejected by acl "domains". Falling back to Digest auth.
2022-04-22 10:27:27.577389 [NOTICE] sofia.c:2332 Hangup sofia/internal/1000@156.0.249.118 [CS_NEW] [CALL_REJECTED]
2022-04-22 10:27:27.597387 [DEBUG] sofia.c:1453 Channel is already hungup.
2022-04-22 10:27:27.597387 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1000@156.0.249.118) Running State Change CS_HANGUP (Cur 1 Tot 14686)
2022-04-22 10:27:27.597387 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/1000@156.0.249.118) Callstate Change DOWN -> HANGUP
2022-04-22 10:27:27.597387 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/1000@156.0.249.118) State HANGUP
2022-04-22 10:27:27.597387 [DEBUG] mod_sofia.c:438 Channel sofia/internal/1000@156.0.249.118 hanging up, cause: CALL_REJECTED
2022-04-22 10:27:27.597387 [DEBUG] switch_core_state_machine.c:60 sofia/internal/1000@156.0.249.118 Standard HANGUP, cause: CALL_REJECTED
2022-04-22 10:27:27.597387 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/1000@156.0.249.118) State HANGUP going to sleep
2022-04-22 10:27:27.597387 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/1000@156.0.249.118) State Change CS_HANGUP -> CS_REPORTING
2022-04-22 10:27:27.597387 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1000@156.0.249.118) Running State Change CS_REPORTING (Cur 1 Tot 14686)
2022-04-22 10:27:27.597387 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/1000@156.0.249.118) State REPORTING
2022-04-22 10:27:27.597387 [DEBUG] switch_core_state_machine.c:174 sofia/internal/1000@156.0.249.118 Standard REPORTING, cause: CALL_REJECTED
2022-04-22 10:27:27.597387 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/1000@156.0.249.118) State REPORTING going to sleep
2022-04-22 10:27:27.597387 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/1000@156.0.249.118) State Change CS_REPORTING -> CS_DESTROY
2022-04-22 10:27:27.597387 [DEBUG] switch_core_session.c:1665 Session 14686 (sofia/internal/1000@156.0.249.118) Locked, Waiting on external entities
2022-04-22 10:27:27.597387 [NOTICE] switch_core_session.c:1683 Session 14686 (sofia/internal/1000@156.0.249.118) Ended
2022-04-22 10:27:27.597387 [NOTICE] switch_core_session.c:1687 Close Channel sofia/internal/1000@156.0.249.118 [CS_DESTROY]
2022-04-22 10:27:27.597387 [DEBUG] switch_core_state_machine.c:741 (sofia/internal/1000@156.0.249.118) Running State Change CS_DESTROY (Cur 0 Tot 14686)
2022-04-22 10:27:27.597387 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/1000@156.0.249.118) State DESTROY
2022-04-22 10:27:27.597387 [DEBUG] mod_sofia.c:343 sofia/internal/1000@156.0.249.118 SOFIA DESTROY
2022-04-22 10:27:27.597387 [DEBUG] switch_core_state_machine.c:181 sofia/internal/1000@156.0.249.118 Standard DESTROY
2022-04-22 10:27:27.597387 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/1000@156.0.249.118) State DESTROY going to sleep
2022-04-22 10:27:27.717404 [NOTICE] switch_channel.c:1104 New Channel sofia/external/1000@156.0.249.118 [4722a4b7-f0ee-4c58-af52-e37028ee65c6]
2022-04-22 10:27:27.717404 [DEBUG] switch_core_state_machine.c:584 (sofia/external/1000@156.0.249.118) Running State Change CS_NEW (Cur 1 Tot 14687)
2022-04-22 10:27:27.717404 [DEBUG] sofia.c:9873 sofia/external/1000@156.0.249.118 receiving invite from 103.213.247.230:64128 version: 1.6.20 git 43a9feb 2018-05-07 18:56:11Z 64bit
2022-04-22 10:27:27.717404 [DEBUG] sofia.c:7084 Channel sofia/external/1000@156.0.249.118 entering state [received][100]
2022-04-22 10:27:27.717404 [DEBUG] sofia.c:7094 Remote SDP:
v=0
o=- 329918574 329919044 IN IP4 0.0.0.0
s=sipcall
c=IN IP4 0.0.0.0
t=0 0
m=audio 7628 RTP/AVP 100 6 0 8 3 18 5 101
a=rtpmap:100 speex/16000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-11
a=alt:1 1 : DF50DC48 0000006A 0.0.0.0 7628

2022-04-22 10:27:27.717404 [DEBUG] sofia.c:7486 (sofia/external/1000@156.0.249.118) State Change CS_NEW -> CS_INIT
2022-04-22 10:27:27.717404 [DEBUG] switch_core_state_machine.c:603 (sofia/external/1000@156.0.249.118) State NEW
2022-04-22 10:27:27.717404 [DEBUG] switch_core_state_machine.c:584 (sofia/external/1000@156.0.249.118) Running State Change CS_INIT (Cur 1 Tot 14687)
2022-04-22 10:27:27.717404 [DEBUG] switch_core_state_machine.c:627 (sofia/external/1000@156.0.249.118) State INIT
2022-04-22 10:27:27.717404 [DEBUG] mod_sofia.c:90 sofia/external/1000@156.0.249.118 SOFIA INIT
2022-04-22 10:27:27.717404 [DEBUG] switch_core_state_machine.c:40 sofia/external/1000@156.0.249.118 Standard INIT
2022-04-22 10:27:27.717404 [DEBUG] switch_core_state_machine.c:48 (sofia/external/1000@156.0.249.118) State Change CS_INIT -> CS_ROUTING
2022-04-22 10:27:27.717404 [DEBUG] switch_core_state_machine.c:627 (sofia/external/1000@156.0.249.118) State INIT going to sleep
2022-04-22 10:27:27.717404 [DEBUG] switch_core_state_machine.c:584 (sofia/external/1000@156.0.249.118) Running State Change CS_ROUTING (Cur 1 Tot 14687)
2022-04-22 10:27:27.717404 [DEBUG] switch_channel.c:2249 (sofia/external/1000@156.0.249.118) Callstate Change DOWN -> RINGING
2022-04-22 10:27:27.717404 [DEBUG] switch_core_state_machine.c:643 (sofia/external/1000@156.0.249.118) State ROUTING
2022-04-22 10:27:27.717404 [DEBUG] mod_sofia.c:143 sofia/external/1000@156.0.249.118 SOFIA ROUTING
2022-04-22 10:27:27.717404 [DEBUG] switch_core_state_machine.c:236 sofia/external/1000@156.0.249.118 Standard ROUTING
2022-04-22 10:27:27.717404 [INFO] mod_dialplan_xml.c:637 Processing 1000 <1000>->51815054790850 in context public
Dialplan: sofia/external/1000@156.0.249.118 parsing [public->unloop] continue=false
Dialplan: sofia/external/1000@156.0.249.118 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false
Dialplan: sofia/external/1000@156.0.249.118 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false
Dialplan: sofia/external/1000@156.0.249.118 parsing [public->outside_call] continue=true
Dialplan: sofia/external/1000@156.0.249.118 Absolute Condition [outside_call]
Dialplan: sofia/external/1000@156.0.249.118 Action set(outside_call=true) 
Dialplan: sofia/external/1000@156.0.249.118 Action export(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)}) 
Dialplan: sofia/external/1000@156.0.249.118 parsing [public->call_debug] continue=true
Dialplan: sofia/external/1000@156.0.249.118 Regex (FAIL) [call_debug] ${call_debug}(false) =~ /^true$/ break=never
Dialplan: sofia/external/1000@156.0.249.118 parsing [public->public_extensions] continue=false
Dialplan: sofia/external/1000@156.0.249.118 Regex (FAIL) [public_extensions] destination_number(51815054790850) =~ /^(10[01][0-9])$/ break=on-false
Dialplan: sofia/external/1000@156.0.249.118 parsing [public->public_did] continue=false
Dialplan: sofia/external/1000@156.0.249.118 Regex (FAIL) [public_did] destination_number(51815054790850) =~ /^(5551212)$/ break=on-false
Dialplan: sofia/external/1000@156.0.249.118 parsing [public->mydid] continue=false
Dialplan: sofia/external/1000@156.0.249.118 Regex (FAIL) [mydid] destination_number(51815054790850) =~ /^(23418888325)$/ break=on-false
2022-04-22 10:27:27.717404 [DEBUG] switch_core_state_machine.c:286 (sofia/external/1000@156.0.249.118) State Change CS_ROUTING -> CS_EXECUTE
2022-04-22 10:27:27.717404 [DEBUG] switch_core_state_machine.c:643 (sofia/external/1000@156.0.249.118) State ROUTING going to sleep
2022-04-22 10:27:27.717404 [DEBUG] switch_core_state_machine.c:584 (sofia/external/1000@156.0.249.118) Running State Change CS_EXECUTE (Cur 1 Tot 14687)
2022-04-22 10:27:27.717404 [DEBUG] switch_core_state_machine.c:650 (sofia/external/1000@156.0.249.118) State EXECUTE
2022-04-22 10:27:27.717404 [DEBUG] mod_sofia.c:198 sofia/external/1000@156.0.249.118 SOFIA EXECUTE
2022-04-22 10:27:27.717404 [DEBUG] switch_core_state_machine.c:328 sofia/external/1000@156.0.249.118 Standard EXECUTE
EXECUTE sofia/external/1000@156.0.249.118 set(outside_call=true)
2022-04-22 10:27:27.717404 [DEBUG] mod_dptools.c:1548 SET sofia/external/1000@156.0.249.118 [outside_call]=[true]
EXECUTE sofia/external/1000@156.0.249.118 export(RFC2822_DATE=Fri, 22 Apr 2022 10:27:27 +0100)
2022-04-22 10:27:27.717404 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [RFC2822_DATE]=[Fri, 22 Apr 2022 10:27:27 +0100]
2022-04-22 10:27:27.717404 [NOTICE] switch_core_state_machine.c:385 sofia/external/1000@156.0.249.118 has executed the last dialplan instruction, hanging up.
2022-04-22 10:27:27.717404 [NOTICE] switch_core_state_machine.c:387 Hangup sofia/external/1000@156.0.249.118 [CS_EXECUTE] [NORMAL_CLEARING]
2022-04-22 10:27:27.717404 [DEBUG] switch_core_state_machine.c:650 (sofia/external/1000@156.0.249.118) State EXECUTE going to sleep
2022-04-22 10:27:27.717404 [DEBUG] switch_core_state_machine.c:584 (sofia/external/1000@156.0.249.118) Running State Change CS_HANGUP (Cur 1 Tot 14687)
2022-04-22 10:27:27.717404 [DEBUG] switch_core_state_machine.c:850 (sofia/external/1000@156.0.249.118) Callstate Change RINGING -> HANGUP
2022-04-22 10:27:27.717404 [DEBUG] switch_core_state_machine.c:852 (sofia/external/1000@156.0.249.118) State HANGUP
2022-04-22 10:27:27.717404 [DEBUG] mod_sofia.c:438 Channel sofia/external/1000@156.0.249.118 hanging up, cause: NORMAL_CLEARING
2022-04-22 10:27:27.717404 [DEBUG] mod_sofia.c:577 Responding to INVITE with: 480
2022-04-22 10:27:27.717404 [DEBUG] switch_core_state_machine.c:60 sofia/external/1000@156.0.249.118 Standard HANGUP, cause: NORMAL_CLEARING
2022-04-22 10:27:27.717404 [DEBUG] switch_core_state_machine.c:852 (sofia/external/1000@156.0.249.118) State HANGUP going to sleep
2022-04-22 10:27:27.717404 [DEBUG] switch_core_state_machine.c:619 (sofia/external/1000@156.0.249.118) State Change CS_HANGUP -> CS_REPORTING
2022-04-22 10:27:27.717404 [DEBUG] switch_core_state_machine.c:584 (sofia/external/1000@156.0.249.118) Running State Change CS_REPORTING (Cur 1 Tot 14687)
2022-04-22 10:27:27.717404 [DEBUG] switch_core_state_machine.c:938 (sofia/external/1000@156.0.249.118) State REPORTING
2022-04-22 10:27:27.717404 [DEBUG] switch_core_state_machine.c:174 sofia/external/1000@156.0.249.118 Standard REPORTING, cause: NORMAL_CLEARING
2022-04-22 10:27:27.717404 [DEBUG] switch_core_state_machine.c:938 (sofia/external/1000@156.0.249.118) State REPORTING going to sleep
2022-04-22 10:27:27.717404 [DEBUG] switch_core_state_machine.c:610 (sofia/external/1000@156.0.249.118) State Change CS_REPORTING -> CS_DESTROY
2022-04-22 10:27:27.717404 [DEBUG] switch_core_session.c:1665 Session 14687 (sofia/external/1000@156.0.249.118) Locked, Waiting on external entities
2022-04-22 10:27:27.717404 [NOTICE] switch_core_session.c:1683 Session 14687 (sofia/external/1000@156.0.249.118) Ended
2022-04-22 10:27:27.717404 [NOTICE] switch_core_session.c:1687 Close Channel sofia/external/1000@156.0.249.118 [CS_DESTROY]
2022-04-22 10:27:27.717404 [DEBUG] switch_core_state_machine.c:741 (sofia/external/1000@156.0.249.118) Running State Change CS_DESTROY (Cur 0 Tot 14687)
2022-04-22 10:27:27.717404 [DEBUG] switch_core_state_machine.c:751 (sofia/external/1000@156.0.249.118) State DESTROY
2022-04-22 10:27:27.717404 [DEBUG] mod_sofia.c:343 sofia/external/1000@156.0.249.118 SOFIA DESTROY
2022-04-22 10:27:27.717404 [DEBUG] switch_core_state_machine.c:181 sofia/external/1000@156.0.249.118 Standard DESTROY
2022-04-22 10:27:27.717404 [DEBUG] switch_core_state_machine.c:751 (sofia/external/1000@156.0.249.118) State DESTROY going to sleep
2022-04-22 10:27:27.937411 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/6001@156.0.249.118 [cb1a2fab-955d-4875-9846-98c8ade21817]
2022-04-22 10:27:27.937411 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/6001@156.0.249.118) Running State Change CS_NEW (Cur 1 Tot 14688)
2022-04-22 10:27:27.937411 [DEBUG] sofia.c:9873 sofia/internal/6001@156.0.249.118 receiving invite from 45.93.16.40:49229 version: 1.6.20 git 43a9feb 2018-05-07 18:56:11Z 64bit
2022-04-22 10:27:27.937411 [DEBUG] sofia.c:10044 IP 45.93.16.40 Rejected by acl "domains". Falling back to Digest auth.
2022-04-22 10:27:27.937411 [DEBUG] switch_core_state_machine.c:603 (sofia/internal/6001@156.0.249.118) State NEW
2022-04-22 10:27:27.937411 [DEBUG] sofia.c:2334 detaching session cb1a2fab-955d-4875-9846-98c8ade21817
2022-04-22 10:27:29.057408 [WARNING] sofia_reg.c:2906 Can't find user [3001@156.0.249.118] from 20.31.130.193
You must define a domain called '156.0.249.118' in your directory and add a user with the id="3001" attribute
and you must configure your device to use the proper domain in it's authentication credentials.
2022-04-22 10:27:31.917389 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/1000@156.0.249.118 [c4c99391-152e-4d8e-a946-98e0935f59e6]
2022-04-22 10:27:31.917389 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1000@156.0.249.118) Running State Change CS_NEW (Cur 2 Tot 14689)
2022-04-22 10:27:31.917389 [DEBUG] sofia.c:9873 sofia/internal/1000@156.0.249.118 receiving invite from 103.213.247.230:60468 version: 1.6.20 git 43a9feb 2018-05-07 18:56:11Z 64bit
2022-04-22 10:27:31.917389 [DEBUG] sofia.c:10044 IP 103.213.247.230 Rejected by acl "domains". Falling back to Digest auth.
2022-04-22 10:27:31.917389 [DEBUG] switch_core_state_machine.c:603 (sofia/internal/1000@156.0.249.118) State NEW
2022-04-22 10:27:31.917389 [DEBUG] sofia.c:2334 detaching session c4c99391-152e-4d8e-a946-98e0935f59e6
2022-04-22 10:27:31.977382 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/0000000@156.0.249.118 [5669f982-632d-4255-9904-c5997a62d199]
2022-04-22 10:27:31.977382 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/0000000@156.0.249.118) Running State Change CS_NEW (Cur 3 Tot 14690)
2022-04-22 10:27:31.977382 [DEBUG] sofia.c:9873 sofia/internal/0000000@156.0.249.118 receiving invite from 20.224.243.51:64248 version: 1.6.20 git 43a9feb 2018-05-07 18:56:11Z 64bit
2022-04-22 10:27:31.977382 [DEBUG] sofia.c:10044 IP 20.224.243.51 Rejected by acl "domains". Falling back to Digest auth.
2022-04-22 10:27:31.977382 [DEBUG] switch_core_state_machine.c:603 (sofia/internal/0000000@156.0.249.118) State NEW
2022-04-22 10:27:31.977382 [DEBUG] sofia.c:2334 detaching session 5669f982-632d-4255-9904-c5997a62d199
2022-04-22 10:27:32.217394 [DEBUG] sofia.c:2442 Re-attaching to session c4c99391-152e-4d8e-a946-98e0935f59e6
2022-04-22 10:27:32.237384 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/10001@156.0.249.118 [1e994eed-0140-4a9e-9c4c-f64adce4b293]
2022-04-22 10:27:32.237384 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/10001@156.0.249.118) Running State Change CS_NEW (Cur 4 Tot 14691)
2022-04-22 10:27:32.237384 [DEBUG] sofia.c:9873 sofia/internal/10001@156.0.249.118 receiving invite from 45.93.16.41:60246 version: 1.6.20 git 43a9feb 2018-05-07 18:56:11Z 64bit
2022-04-22 10:27:32.237384 [DEBUG] sofia.c:10044 IP 45.93.16.41 Rejected by acl "domains". Falling back to Digest auth.
2022-04-22 10:27:32.237384 [DEBUG] switch_core_state_machine.c:603 (sofia/internal/10001@156.0.249.118) State NEW
2022-04-22 10:27:32.237384 [DEBUG] sofia.c:2334 detaching session 1e994eed-0140-4a9e-9c4c-f64adce4b293
2022-04-22 10:27:32.237384 [DEBUG] sofia.c:9873 sofia/internal/1000@156.0.249.118 receiving invite from 103.213.247.230:60468 version: 1.6.20 git 43a9feb 2018-05-07 18:56:11Z 64bit
2022-04-22 10:27:32.237384 [DEBUG] sofia.c:10044 IP 103.213.247.230 Rejected by acl "domains". Falling back to Digest auth.
2022-04-22 10:27:32.237384 [NOTICE] sofia.c:2332 Hangup sofia/internal/1000@156.0.249.118 [CS_NEW] [CALL_REJECTED]
2022-04-22 10:27:32.257382 [DEBUG] sofia.c:1453 Channel is already hungup.
2022-04-22 10:27:32.257382 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1000@156.0.249.118) Running State Change CS_HANGUP (Cur 4 Tot 14691)
2022-04-22 10:27:32.257382 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/1000@156.0.249.118) Callstate Change DOWN -> HANGUP
2022-04-22 10:27:32.257382 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/1000@156.0.249.118) State HANGUP
2022-04-22 10:27:32.257382 [DEBUG] mod_sofia.c:438 Channel sofia/internal/1000@156.0.249.118 hanging up, cause: CALL_REJECTED
2022-04-22 10:27:32.257382 [DEBUG] switch_core_state_machine.c:60 sofia/internal/1000@156.0.249.118 Standard HANGUP, cause: CALL_REJECTED
2022-04-22 10:27:32.257382 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/1000@156.0.249.118) State HANGUP going to sleep
2022-04-22 10:27:32.257382 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/1000@156.0.249.118) State Change CS_HANGUP -> CS_REPORTING
2022-04-22 10:27:32.257382 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1000@156.0.249.118) Running State Change CS_REPORTING (Cur 4 Tot 14691)
2022-04-22 10:27:32.257382 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/1000@156.0.249.118) State REPORTING
2022-04-22 10:27:32.257382 [DEBUG] switch_core_state_machine.c:174 sofia/internal/1000@156.0.249.118 Standard REPORTING, cause: CALL_REJECTED
2022-04-22 10:27:32.257382 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/1000@156.0.249.118) State REPORTING going to sleep
2022-04-22 10:27:32.257382 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/1000@156.0.249.118) State Change CS_REPORTING -> CS_DESTROY
2022-04-22 10:27:32.257382 [DEBUG] switch_core_session.c:1665 Session 14689 (sofia/internal/1000@156.0.249.118) Locked, Waiting on external entities
2022-04-22 10:27:32.257382 [NOTICE] switch_core_session.c:1683 Session 14689 (sofia/internal/1000@156.0.249.118) Ended
2022-04-22 10:27:32.257382 [NOTICE] switch_core_session.c:1687 Close Channel sofia/internal/1000@156.0.249.118 [CS_DESTROY]
2022-04-22 10:27:32.257382 [DEBUG] switch_core_state_machine.c:741 (sofia/internal/1000@156.0.249.118) Running State Change CS_DESTROY (Cur 3 Tot 14691)
2022-04-22 10:27:32.257382 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/1000@156.0.249.118) State DESTROY
2022-04-22 10:27:32.257382 [DEBUG] mod_sofia.c:343 sofia/internal/1000@156.0.249.118 SOFIA DESTROY
2022-04-22 10:27:32.257382 [DEBUG] switch_core_state_machine.c:181 sofia/internal/1000@156.0.249.118 Standard DESTROY
2022-04-22 10:27:32.257382 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/1000@156.0.249.118) State DESTROY going to sleep
2022-04-22 10:27:33.677382 [NOTICE] switch_channel.c:1104 New Channel sofia/external/1000@156.0.249.118 [39a72c82-970f-4e4a-8a7b-82311f781d21]
2022-04-22 10:27:33.677382 [DEBUG] switch_core_state_machine.c:584 (sofia/external/1000@156.0.249.118) Running State Change CS_NEW (Cur 4 Tot 14692)
2022-04-22 10:27:33.677382 [DEBUG] sofia.c:9873 sofia/external/1000@156.0.249.118 receiving invite from 103.213.247.230:60976 version: 1.6.20 git 43a9feb 2018-05-07 18:56:11Z 64bit
2022-04-22 10:27:33.677382 [DEBUG] sofia.c:7084 Channel sofia/external/1000@156.0.249.118 entering state [received][100]
2022-04-22 10:27:33.677382 [DEBUG] sofia.c:7094 Remote SDP:
v=0
o=- 329918574 329919044 IN IP4 0.0.0.0
s=sipcall
c=IN IP4 0.0.0.0
t=0 0
m=audio 7628 RTP/AVP 100 6 0 8 3 18 5 101
a=rtpmap:100 speex/16000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-11
a=alt:1 1 : DF50DC48 0000006A 0.0.0.0 7628

2022-04-22 10:27:33.677382 [DEBUG] sofia.c:7486 (sofia/external/1000@156.0.249.118) State Change CS_NEW -> CS_INIT
2022-04-22 10:27:33.677382 [DEBUG] switch_core_state_machine.c:603 (sofia/external/1000@156.0.249.118) State NEW
2022-04-22 10:27:33.677382 [DEBUG] switch_core_state_machine.c:584 (sofia/external/1000@156.0.249.118) Running State Change CS_INIT (Cur 4 Tot 14692)
2022-04-22 10:27:33.677382 [DEBUG] switch_core_state_machine.c:627 (sofia/external/1000@156.0.249.118) State INIT
2022-04-22 10:27:33.677382 [DEBUG] mod_sofia.c:90 sofia/external/1000@156.0.249.118 SOFIA INIT
2022-04-22 10:27:33.677382 [DEBUG] switch_core_state_machine.c:40 sofia/external/1000@156.0.249.118 Standard INIT
2022-04-22 10:27:33.677382 [DEBUG] switch_core_state_machine.c:48 (sofia/external/1000@156.0.249.118) State Change CS_INIT -> CS_ROUTING
2022-04-22 10:27:33.677382 [DEBUG] switch_core_state_machine.c:627 (sofia/external/1000@156.0.249.118) State INIT going to sleep
2022-04-22 10:27:33.677382 [DEBUG] switch_core_state_machine.c:584 (sofia/external/1000@156.0.249.118) Running State Change CS_ROUTING (Cur 4 Tot 14692)
2022-04-22 10:27:33.677382 [DEBUG] switch_channel.c:2249 (sofia/external/1000@156.0.249.118) Callstate Change DOWN -> RINGING
2022-04-22 10:27:33.677382 [DEBUG] switch_core_state_machine.c:643 (sofia/external/1000@156.0.249.118) State ROUTING
2022-04-22 10:27:33.677382 [DEBUG] mod_sofia.c:143 sofia/external/1000@156.0.249.118 SOFIA ROUTING
2022-04-22 10:27:33.677382 [DEBUG] switch_core_state_machine.c:236 sofia/external/1000@156.0.249.118 Standard ROUTING
2022-04-22 10:27:33.677382 [INFO] mod_dialplan_xml.c:637 Processing 1000 <1000>->52815054790850 in context public
Dialplan: sofia/external/1000@156.0.249.118 parsing [public->unloop] continue=false
Dialplan: sofia/external/1000@156.0.249.118 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false
Dialplan: sofia/external/1000@156.0.249.118 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false
Dialplan: sofia/external/1000@156.0.249.118 parsing [public->outside_call] continue=true
Dialplan: sofia/external/1000@156.0.249.118 Absolute Condition [outside_call]
Dialplan: sofia/external/1000@156.0.249.118 Action set(outside_call=true) 
Dialplan: sofia/external/1000@156.0.249.118 Action export(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)}) 
Dialplan: sofia/external/1000@156.0.249.118 parsing [public->call_debug] continue=true
Dialplan: sofia/external/1000@156.0.249.118 Regex (FAIL) [call_debug] ${call_debug}(false) =~ /^true$/ break=never
Dialplan: sofia/external/1000@156.0.249.118 parsing [public->public_extensions] continue=false
Dialplan: sofia/external/1000@156.0.249.118 Regex (FAIL) [public_extensions] destination_number(52815054790850) =~ /^(10[01][0-9])$/ break=on-false
Dialplan: sofia/external/1000@156.0.249.118 parsing [public->public_did] continue=false
Dialplan: sofia/external/1000@156.0.249.118 Regex (FAIL) [public_did] destination_number(52815054790850) =~ /^(5551212)$/ break=on-false
Dialplan: sofia/external/1000@156.0.249.118 parsing [public->mydid] continue=false
Dialplan: sofia/external/1000@156.0.249.118 Regex (FAIL) [mydid] destination_number(52815054790850) =~ /^(23418888325)$/ break=on-false
2022-04-22 10:27:33.677382 [DEBUG] switch_core_state_machine.c:286 (sofia/external/1000@156.0.249.118) State Change CS_ROUTING -> CS_EXECUTE
2022-04-22 10:27:33.677382 [DEBUG] switch_core_state_machine.c:643 (sofia/external/1000@156.0.249.118) State ROUTING going to sleep
2022-04-22 10:27:33.677382 [DEBUG] switch_core_state_machine.c:584 (sofia/external/1000@156.0.249.118) Running State Change CS_EXECUTE (Cur 4 Tot 14692)
2022-04-22 10:27:33.677382 [DEBUG] switch_core_state_machine.c:650 (sofia/external/1000@156.0.249.118) State EXECUTE
2022-04-22 10:27:33.677382 [DEBUG] mod_sofia.c:198 sofia/external/1000@156.0.249.118 SOFIA EXECUTE
2022-04-22 10:27:33.677382 [DEBUG] switch_core_state_machine.c:328 sofia/external/1000@156.0.249.118 Standard EXECUTE
EXECUTE sofia/external/1000@156.0.249.118 set(outside_call=true)
2022-04-22 10:27:33.677382 [DEBUG] mod_dptools.c:1548 SET sofia/external/1000@156.0.249.118 [outside_call]=[true]
EXECUTE sofia/external/1000@156.0.249.118 export(RFC2822_DATE=Fri, 22 Apr 2022 10:27:33 +0100)
2022-04-22 10:27:33.677382 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [RFC2822_DATE]=[Fri, 22 Apr 2022 10:27:33 +0100]
2022-04-22 10:27:33.677382 [NOTICE] switch_core_state_machine.c:385 sofia/external/1000@156.0.249.118 has executed the last dialplan instruction, hanging up.
2022-04-22 10:27:33.677382 [NOTICE] switch_core_state_machine.c:387 Hangup sofia/external/1000@156.0.249.118 [CS_EXECUTE] [NORMAL_CLEARING]
2022-04-22 10:27:33.677382 [DEBUG] switch_core_state_machine.c:650 (sofia/external/1000@156.0.249.118) State EXECUTE going to sleep
2022-04-22 10:27:33.677382 [DEBUG] switch_core_state_machine.c:584 (sofia/external/1000@156.0.249.118) Running State Change CS_HANGUP (Cur 4 Tot 14692)
2022-04-22 10:27:33.677382 [DEBUG] switch_core_state_machine.c:850 (sofia/external/1000@156.0.249.118) Callstate Change RINGING -> HANGUP
2022-04-22 10:27:33.677382 [DEBUG] switch_core_state_machine.c:852 (sofia/external/1000@156.0.249.118) State HANGUP
2022-04-22 10:27:33.677382 [DEBUG] mod_sofia.c:438 Channel sofia/external/1000@156.0.249.118 hanging up, cause: NORMAL_CLEARING
2022-04-22 10:27:33.677382 [DEBUG] mod_sofia.c:577 Responding to INVITE with: 480
2022-04-22 10:27:33.677382 [DEBUG] switch_core_state_machine.c:60 sofia/external/1000@156.0.249.118 Standard HANGUP, cause: NORMAL_CLEARING
2022-04-22 10:27:33.677382 [DEBUG] switch_core_state_machine.c:852 (sofia/external/1000@156.0.249.118) State HANGUP going to sleep
2022-04-22 10:27:33.677382 [DEBUG] switch_core_state_machine.c:619 (sofia/external/1000@156.0.249.118) State Change CS_HANGUP -> CS_REPORTING
2022-04-22 10:27:33.677382 [DEBUG] switch_core_state_machine.c:584 (sofia/external/1000@156.0.249.118) Running State Change CS_REPORTING (Cur 4 Tot 14692)
2022-04-22 10:27:33.677382 [DEBUG] switch_core_state_machine.c:938 (sofia/external/1000@156.0.249.118) State REPORTING
2022-04-22 10:27:33.677382 [DEBUG] switch_core_state_machine.c:174 sofia/external/1000@156.0.249.118 Standard REPORTING, cause: NORMAL_CLEARING
2022-04-22 10:27:33.677382 [DEBUG] switch_core_state_machine.c:938 (sofia/external/1000@156.0.249.118) State REPORTING going to sleep
2022-04-22 10:27:33.677382 [DEBUG] switch_core_state_machine.c:610 (sofia/external/1000@156.0.249.118) State Change CS_REPORTING -> CS_DESTROY
2022-04-22 10:27:33.677382 [DEBUG] switch_core_session.c:1665 Session 14692 (sofia/external/1000@156.0.249.118) Locked, Waiting on external entities
2022-04-22 10:27:33.677382 [NOTICE] switch_core_session.c:1683 Session 14692 (sofia/external/1000@156.0.249.118) Ended
2022-04-22 10:27:33.677382 [NOTICE] switch_core_session.c:1687 Close Channel sofia/external/1000@156.0.249.118 [CS_DESTROY]
2022-04-22 10:27:33.677382 [DEBUG] switch_core_state_machine.c:741 (sofia/external/1000@156.0.249.118) Running State Change CS_DESTROY (Cur 3 Tot 14692)
2022-04-22 10:27:33.677382 [DEBUG] switch_core_state_machine.c:751 (sofia/external/1000@156.0.249.118) State DESTROY
2022-04-22 10:27:33.677382 [DEBUG] mod_sofia.c:343 sofia/external/1000@156.0.249.118 SOFIA DESTROY
2022-04-22 10:27:33.677382 [DEBUG] switch_core_state_machine.c:181 sofia/external/1000@156.0.249.118 Standard DESTROY
2022-04-22 10:27:33.677382 [DEBUG] switch_core_state_machine.c:751 (sofia/external/1000@156.0.249.118) State DESTROY going to sleep
2022-04-22 10:27:37.377406 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/1000@156.0.249.118 [3fdb0e42-b48e-45bb-9c40-bf27838319ab]
2022-04-22 10:27:37.377406 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1000@156.0.249.118) Running State Change CS_NEW (Cur 4 Tot 14693)
2022-04-22 10:27:37.377406 [DEBUG] sofia.c:9873 sofia/internal/1000@156.0.249.118 receiving invite from 103.213.247.230:62219 version: 1.6.20 git 43a9feb 2018-05-07 18:56:11Z 64bit
2022-04-22 10:27:37.377406 [DEBUG] sofia.c:10044 IP 103.213.247.230 Rejected by acl "domains". Falling back to Digest auth.
2022-04-22 10:27:37.377406 [DEBUG] switch_core_state_machine.c:603 (sofia/internal/1000@156.0.249.118) State NEW
2022-04-22 10:27:37.377406 [DEBUG] sofia.c:2334 detaching session 3fdb0e42-b48e-45bb-9c40-bf27838319ab
2022-04-22 10:27:37.737383 [DEBUG] sofia.c:2442 Re-attaching to session 3fdb0e42-b48e-45bb-9c40-bf27838319ab
2022-04-22 10:27:37.737383 [DEBUG] sofia.c:9873 sofia/internal/1000@156.0.249.118 receiving invite from 103.213.247.230:62219 version: 1.6.20 git 43a9feb 2018-05-07 18:56:11Z 64bit
2022-04-22 10:27:37.737383 [DEBUG] sofia.c:10044 IP 103.213.247.230 Rejected by acl "domains". Falling back to Digest auth.
2022-04-22 10:27:37.737383 [NOTICE] sofia.c:2332 Hangup sofia/internal/1000@156.0.249.118 [CS_NEW] [CALL_REJECTED]
2022-04-22 10:27:37.757390 [DEBUG] sofia.c:1453 Channel is already hungup.
2022-04-22 10:27:37.757390 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1000@156.0.249.118) Running State Change CS_HANGUP (Cur 4 Tot 14693)
2022-04-22 10:27:37.757390 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/1000@156.0.249.118) Callstate Change DOWN -> HANGUP
2022-04-22 10:27:37.757390 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/1000@156.0.249.118) State HANGUP
2022-04-22 10:27:37.757390 [DEBUG] mod_sofia.c:438 Channel sofia/internal/1000@156.0.249.118 hanging up, cause: CALL_REJECTED
2022-04-22 10:27:37.757390 [DEBUG] switch_core_state_machine.c:60 sofia/internal/1000@156.0.249.118 Standard HANGUP, cause: CALL_REJECTED
2022-04-22 10:27:37.757390 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/1000@156.0.249.118) State HANGUP going to sleep
2022-04-22 10:27:37.757390 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/1000@156.0.249.118) State Change CS_HANGUP -> CS_REPORTING
2022-04-22 10:27:37.757390 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1000@156.0.249.118) Running State Change CS_REPORTING (Cur 4 Tot 14693)
2022-04-22 10:27:37.757390 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/1000@156.0.249.118) State REPORTING
2022-04-22 10:27:37.757390 [DEBUG] switch_core_state_machine.c:174 sofia/internal/1000@156.0.249.118 Standard REPORTING, cause: CALL_REJECTED
2022-04-22 10:27:37.757390 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/1000@156.0.249.118) State REPORTING going to sleep
2022-04-22 10:27:37.757390 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/1000@156.0.249.118) State Change CS_REPORTING -> CS_DESTROY
2022-04-22 10:27:37.757390 [DEBUG] switch_core_session.c:1665 Session 14693 (sofia/internal/1000@156.0.249.118) Locked, Waiting on external entities
2022-04-22 10:27:37.757390 [NOTICE] switch_core_session.c:1683 Session 14693 (sofia/internal/1000@156.0.249.118) Ended
2022-04-22 10:27:37.757390 [NOTICE] switch_core_session.c:1687 Close Channel sofia/internal/1000@156.0.249.118 [CS_DESTROY]
2022-04-22 10:27:37.757390 [DEBUG] switch_core_state_machine.c:741 (sofia/internal/1000@156.0.249.118) Running State Change CS_DESTROY (Cur 3 Tot 14693)
2022-04-22 10:27:37.757390 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/1000@156.0.249.118) State DESTROY
2022-04-22 10:27:37.757390 [DEBUG] mod_sofia.c:343 sofia/internal/1000@156.0.249.118 SOFIA DESTROY
2022-04-22 10:27:37.757390 [DEBUG] switch_core_state_machine.c:181 sofia/internal/1000@156.0.249.118 Standard DESTROY
2022-04-22 10:27:37.757390 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/1000@156.0.249.118) State DESTROY going to sleep