good afternoon I have problems with incoming calls for the call rings and when picking up the phone sends to the mailbox,
2020-12-03 17:00:32.011432 [NOTICE] switch_channel.c:1118 New Channel sofia/internal/4123343347@10.20.0.10 [96139f7c-c058-4cdf-be92-165038b078e1]
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
2020-12-03 17:00:32.011432 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/4123343347@10.20.0.10) Running State Change CS_NEW (Cur 1 Tot 89)
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2020-12-03 17:00:32.011432 [DEBUG] sofia.c:10279 sofia/internal/4123343347@10.20.0.10 receiving invite from 10.20.0.10:5060 version: 1.10.3 -release-15-129de34d84 64bit
2020-12-03 17:00:32.011432 [DEBUG] sofia.c:10373 verifying acl "domains" for ip/port 10.20.0.10:0.
2020-12-03 17:00:32.011432 [DEBUG] sofia.c:10402 IP 10.20.0.10 Approved by acl "domains[]". Access Granted.
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2020-12-03 17:00:32.011432 [DEBUG] sofia.c:7325 Channel sofia/internal/4123343347@10.20.0.10 entering state [received][100]
2020-12-03 17:00:32.011432 [DEBUG] sofia.c:7335 Remote SDP:
v=0
o=root 1762744854 1762744854 IN IP4 10.20.0.10
s=Asterisk PBX 11.25.3
c=IN IP4 10.20.0.10
t=0 0
m=audio 11590 RTP/AVP 8 0 3 4 112 5 7 18 110 97 111 9 102 115 116 117 96 108 109 113 10 118 119 107 101
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:3 GSM/8000
a=rtpmap:4 G723/8000
a=fmtp:4 annexa=no
a=rtpmap:112 AAL2-G726-32/8000
a=rtpmap:5 DVI4/8000
a=rtpmap:7 LPC/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:110 speex/8000
a=rtpmap:97 iLBC/8000
a=rtpmap:111 G726-32/8000
a=rtpmap:9 G722/8000
a=rtpmap:102 G7221/16000
a=fmtp:102 bitrate=32000
a=rtpmap:115 G7221/32000
a=fmtp:115 bitrate=48000
a=rtpmap:116 G719/48000
a=fmtp:116 bitrate=64000
a=rtpmap:117 speex/16000
a=rtpmap:96 SILK/8000
a=fmtp:96 useinbandfec=1
a=rtpmap:108 SILK/12000
a=fmtp:108 useinbandfec=1
a=rtpmap:109 SILK/16000
a=fmtp:109 useinbandfec=1
a=rtpmap:113 SILK/24000
a=fmtp:113 useinbandfec=1
a=rtpmap:10 L16/8000
a=rtpmap:118 L16/16000
a=rtpmap:119 speex/32000
a=rtpmap:107 opus/48000/2
a=fmtp:107 maxplaybackrate=16000; stereo=0; sprop-stereo=0; useinbandfec=0
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=maxptime:60
a=ptime:20
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5647 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5647 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [GSM:3:8000:20:13200:1]/[G722:9:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [GSM:3:8000:20:13200:1]/[PCMU:0:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [GSM:3:8000:20:13200:1]/[PCMA:8:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [G723:4:8000:20:6300:1]/[G722:9:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [G723:4:8000:20:6300:1]/[PCMU:0:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [G723:4:8000:20:6300:1]/[PCMA:8:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [AAL2-G726-32:112:8000:20:0:1]/[G722:9:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [AAL2-G726-32:112:8000:20:0:1]/[PCMU:0:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [AAL2-G726-32:112:8000:20:0:1]/[PCMA:8:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [DVI4:5:8000:20:0:1]/[G722:9:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [DVI4:5:8000:20:0:1]/[PCMU:0:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [DVI4:5:8000:20:0:1]/[PCMA:8:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [LPC:7:8000:20:2400:1]/[G722:9:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [LPC:7:8000:20:2400:1]/[PCMU:0:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [LPC:7:8000:20:2400:1]/[PCMA:8:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [G729:18:8000:20:8000:1]/[G722:9:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMU:0:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMA:8:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [speex:110:8000:20:0:1]/[G722:9:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [speex:110:8000:20:0:1]/[PCMU:0:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [speex:110:8000:20:0:1]/[PCMA:8:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [iLBC:97:8000:30:13330:1]/[G722:9:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [iLBC:97:8000:30:13330:1]/[PCMU:0:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [iLBC:97:8000:30:13330:1]/[PCMA:8:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [G726-32:111:8000:20:0:1]/[G722:9:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [G726-32:111:8000:20:0:1]/[PCMU:0:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [G726-32:111:8000:20:0:1]/[PCMA:8:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [G722:9:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5647 Audio Codec Compare [G722:9:8000:20:64000:1] ++++ is saved as a match
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [G7221:102:16000:20:0:1]/[G722:9:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [G7221:102:16000:20:0:1]/[PCMU:0:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [G7221:102:16000:20:0:1]/[PCMA:8:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [G7221:115:32000:20:0:1]/[G722:9:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [G7221:115:32000:20:0:1]/[PCMU:0:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [G7221:115:32000:20:0:1]/[PCMA:8:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [G719:116:48000:20:0:1]/[G722:9:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [G719:116:48000:20:0:1]/[PCMU:0:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [G719:116:48000:20:0:1]/[PCMA:8:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [speex:117:16000:20:0:1]/[G722:9:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [speex:117:16000:20:0:1]/[PCMU:0:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [speex:117:16000:20:0:1]/[PCMA:8:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [SILK:96:8000:20:0:1]/[G722:9:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [SILK:96:8000:20:0:1]/[PCMU:0:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [SILK:96:8000:20:0:1]/[PCMA:8:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [SILK:108:12000:20:0:1]/[G722:9:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [SILK:108:12000:20:0:1]/[PCMU:0:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [SILK:108:12000:20:0:1]/[PCMA:8:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [SILK:109:16000:20:0:1]/[G722:9:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [SILK:109:16000:20:0:1]/[PCMU:0:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [SILK:109:16000:20:0:1]/[PCMA:8:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [SILK:113:24000:20:0:1]/[G722:9:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [SILK:113:24000:20:0:1]/[PCMU:0:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [SILK:113:24000:20:0:1]/[PCMA:8:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [L16:10:8000:20:0:1]/[G722:9:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [L16:10:8000:20:0:1]/[PCMU:0:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [L16:10:8000:20:0:1]/[PCMA:8:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [L16:118:16000:20:0:1]/[G722:9:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [L16:118:16000:20:0:1]/[PCMU:0:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [L16:118:16000:20:0:1]/[PCMA:8:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [speex:119:32000:20:0:1]/[G722:9:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [speex:119:32000:20:0:1]/[PCMU:0:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [speex:119:32000:20:0:1]/[PCMA:8:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [opus:107:48000:20:0:2]/[G722:9:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [opus:107:48000:20:0:2]/[PCMU:0:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [opus:107:48000:20:0:2]/[PCMA:8:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5508 Set telephone-event payload to 101@8000
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:3837 Set Codec sofia/internal/4123343347@10.20.0.10 G722/8000 20 ms 160 samples 64000 bits 1 channels
2020-12-03 17:00:32.011432 [DEBUG] switch_core_codec.c:111 sofia/internal/4123343347@10.20.0.10 Original read codec set to G722:9
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5851 Set telephone-event payload to 101@8000
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5909 sofia/internal/4123343347@10.20.0.10 Set 2833 dtmf send payload to 101 recv payload to 101
2020-12-03 17:00:32.011432 [DEBUG] sofia.c:7759 (sofia/internal/4123343347@10.20.0.10) State Change CS_NEW -> CS_INIT
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2020-12-03 17:00:32.011432 [DEBUG] switch_core_state_machine.c:604 (sofia/internal/4123343347@10.20.0.10) State NEW
2020-12-03 17:00:32.011432 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/4123343347@10.20.0.10) Running State Change CS_INIT (Cur 1 Tot 89)
2020-12-03 17:00:32.011432 [DEBUG] switch_core_state_machine.c:628 (sofia/internal/4123343347@10.20.0.10) State INIT
2020-12-03 17:00:32.011432 [DEBUG] mod_sofia.c:93 sofia/internal/4123343347@10.20.0.10 SOFIA INIT
2020-12-03 17:00:32.011432 [DEBUG] switch_core_state_machine.c:40 sofia/internal/4123343347@10.20.0.10 Standard INIT
2020-12-03 17:00:32.011432 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/4123343347@10.20.0.10) State Change CS_INIT -> CS_ROUTING
2020-12-03 17:00:32.011432 [DEBUG] switch_core_state_machine.c:628 (sofia/internal/4123343347@10.20.0.10) State INIT going to sleep
2020-12-03 17:00:32.011432 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/4123343347@10.20.0.10) Running State Change CS_ROUTING (Cur 1 Tot 89)
2020-12-03 17:00:32.011432 [DEBUG] switch_channel.c:2332 (sofia/internal/4123343347@10.20.0.10) Callstate Change DOWN -> RINGING
2020-12-03 17:00:32.011432 [DEBUG] switch_core_state_machine.c:644 (sofia/internal/4123343347@10.20.0.10) State ROUTING
nua.c:879 nua_respond() nua: nua_respond: entering
nua_stack.c:573 nua_stack_signal() nua(0x7f53cc038ba0): recv signal r_respond 100 Trying
nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:403 soa_set_params() soa_set_params(static::0x7f53cc02db50, ...) called
tport.c:3275 tport_tsend() tport_tsend(0x7f53cc004e80) tpn = UDP/10.20.0.10:5060
tport.c:4064 tport_resolve() tport_resolve addrinfo = 10.20.0.10:5060
tport.c:4698 tport_by_addrinfo() tport_by_addrinfo(0x7f53cc004e80): not found by name UDP/10.20.0.10:5060
nua_stack.c:529 nua_signal() nua(0x7f53cc038ba0): sent signal r_respond
2020-12-03 17:00:32.011432 [DEBUG] mod_sofia.c:154 sofia/internal/4123343347@10.20.0.10 SOFIA ROUTING
2020-12-03 17:00:32.011432 [DEBUG] switch_core_state_machine.c:236 sofia/internal/4123343347@10.20.0.10 Standard ROUTING
2020-12-03 17:00:32.011432 [INFO] mod_dialplan_xml.c:637 Processing 4123343347 <4123343347>->5661 in context public
tport.c:3612 tport_vsend() tport_vsend(0x7f53cc004e80): 304 bytes of 304 to udp/10.20.0.10:5060
tport.c:3510 tport_send_msg() tport_vsend returned 304
nta.c:6802 incoming_reply() nta: sent 100 Trying for INVITE (102)
Dialplan: sofia/internal/4123343347@10.20.0.10 parsing [public->caller-details] continue=true
Dialplan: sofia/internal/4123343347@10.20.0.10 Regex (PASS) [caller-details] () =~ // break=never
Dialplan: sofia/internal/4123343347@10.20.0.10 Action export(call_direction=inbound) INLINE
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 export(call_direction=inbound)
2020-12-03 17:00:32.031369 [DEBUG] switch_channel.c:1310 EXPORT (export_vars) [call_direction]=[inbound]
Dialplan: sofia/internal/4123343347@10.20.0.10 Action set(caller_destination=${sip_to_user}) INLINE
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 set(caller_destination=5661)
2020-12-03 17:00:32.031369 [DEBUG] mod_dptools.c:1672 SET sofia/internal/4123343347@10.20.0.10 [caller_destination]=[5661]
Dialplan: sofia/internal/4123343347@10.20.0.10 Action set(caller_id_name=${caller_id_name}) INLINE
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 set(caller_id_name=4123343347)
2020-12-03 17:00:32.031369 [DEBUG] mod_dptools.c:1672 SET sofia/internal/4123343347@10.20.0.10 [caller_id_name]=[4123343347]
Dialplan: sofia/internal/4123343347@10.20.0.10 Action set(caller_id_number=${caller_id_number})
Dialplan: sofia/internal/4123343347@10.20.0.10 parsing [public->5xxx] continue=true
Dialplan: sofia/internal/4123343347@10.20.0.10 Regex (PASS) [5xxx] destination_number(5661) =~ /^(5[4-7][0-9][0-9])$/ break=on-false
Dialplan: sofia/internal/4123343347@10.20.0.10 Action export(call_direction=inbound) INLINE
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 export(call_direction=inbound)
2020-12-03 17:00:32.031369 [DEBUG] switch_channel.c:1310 EXPORT (export_vars) [call_direction]=[inbound]
Dialplan: sofia/internal/4123343347@10.20.0.10 Action set(domain_uuid=c64bd80d-c20f-4bc8-b43c-41c7e9c405c5) INLINE
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 set(domain_uuid=c64bd80d-c20f-4bc8-b43c-41c7e9c405c5)
2020-12-03 17:00:32.031369 [DEBUG] mod_dptools.c:1672 SET sofia/internal/4123343347@10.20.0.10 [domain_uuid]=[c64bd80d-c20f-4bc8-b43c-41c7e9c405c5]
Dialplan: sofia/internal/4123343347@10.20.0.10 Action set(domain_name=10.20.0.1) INLINE
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 set(domain_name=10.20.0.1)
2020-12-03 17:00:32.031369 [DEBUG] mod_dptools.c:1672 SET sofia/internal/4123343347@10.20.0.10 [domain_name]=[10.20.0.1]
Dialplan: sofia/internal/4123343347@10.20.0.10 Action transfer(5661 XML default)
Dialplan: sofia/internal/4123343347@10.20.0.10 parsing [public->not-found] continue=false
Dialplan: sofia/internal/4123343347@10.20.0.10 Regex (PASS) [not-found] () =~ // break=on-false
Dialplan: sofia/internal/4123343347@10.20.0.10 Action export(call_direction=inbound) INLINE
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 export(call_direction=inbound)
2020-12-03 17:00:32.031369 [DEBUG] switch_channel.c:1310 EXPORT (export_vars) [call_direction]=[inbound]
Dialplan: sofia/internal/4123343347@10.20.0.10 Action set(call_direction=inbound) INLINE
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 set(call_direction=inbound)
2020-12-03 17:00:32.031369 [DEBUG] mod_dptools.c:1672 SET sofia/internal/4123343347@10.20.0.10 [call_direction]=[inbound]
Dialplan: sofia/internal/4123343347@10.20.0.10 Action log(WARNING [inbound routes] 404 not found ${sip_network_ip})
2020-12-03 17:00:32.031369 [DEBUG] switch_core_state_machine.c:287 (sofia/internal/4123343347@10.20.0.10) State Change CS_ROUTING -> CS_EXECUTE
2020-12-03 17:00:32.031369 [DEBUG] switch_core_state_machine.c:644 (sofia/internal/4123343347@10.20.0.10) State ROUTING going to sleep
2020-12-03 17:00:32.031369 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/4123343347@10.20.0.10) Running State Change CS_EXECUTE (Cur 1 Tot 89)
2020-12-03 17:00:32.031369 [DEBUG] switch_core_state_machine.c:651 (sofia/internal/4123343347@10.20.0.10) State EXECUTE
2020-12-03 17:00:32.031369 [DEBUG] mod_sofia.c:209 sofia/internal/4123343347@10.20.0.10 SOFIA EXECUTE
2020-12-03 17:00:32.031369 [DEBUG] switch_core_state_machine.c:329 sofia/internal/4123343347@10.20.0.10 Standard EXECUTE
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 set(caller_id_number=4123343347)
2020-12-03 17:00:32.031369 [DEBUG] mod_dptools.c:1672 SET sofia/internal/4123343347@10.20.0.10 [caller_id_number]=[4123343347]
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 transfer(5661 XML default)
2020-12-03 17:00:32.031369 [DEBUG] switch_ivr.c:2243 (sofia/internal/4123343347@10.20.0.10) State Change CS_EXECUTE -> CS_ROUTING
2020-12-03 17:00:32.031369 [NOTICE] switch_ivr.c:2250 Transfer sofia/internal/4123343347@10.20.0.10 to XML[5661@default]
2020-12-03 17:00:32.031369 [DEBUG] switch_core_state_machine.c:651 (sofia/internal/4123343347@10.20.0.10) State EXECUTE going to sleep
2020-12-03 17:00:32.031369 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/4123343347@10.20.0.10) Running State Change CS_ROUTING (Cur 1 Tot 89)
2020-12-03 17:00:32.031369 [DEBUG] switch_core_state_machine.c:644 (sofia/internal/4123343347@10.20.0.10) State ROUTING
2020-12-03 17:00:32.031369 [DEBUG] mod_sofia.c:145 Call appears to be already acknowledged
2020-12-03 17:00:32.031369 [DEBUG] mod_sofia.c:154 sofia/internal/4123343347@10.20.0.10 SOFIA ROUTING
2020-12-03 17:00:32.031369 [DEBUG] switch_core_state_machine.c:236 sofia/internal/4123343347@10.20.0.10 Standard ROUTING
2020-12-03 17:00:32.031369 [INFO] mod_dialplan_xml.c:637 Processing 4123343347 <4123343347>->5661 in context default
Dialplan: sofia/internal/4123343347@10.20.0.10 parsing [default->user_exists] continue=true
Dialplan: sofia/internal/4123343347@10.20.0.10 Regex (FAIL) [user_exists] ${loopback_leg}() =~ /^B$/ break=never
Dialplan: sofia/internal/4123343347@10.20.0.10 Regex (PASS) [user_exists] () =~ // break=on-false
Dialplan: sofia/internal/4123343347@10.20.0.10 Action set(user_exists=${user_exists id ${destination_number} ${domain_name}}) INLINE
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 set(user_exists=true)
2020-12-03 17:00:32.051345 [DEBUG] mod_dptools.c:1672 SET sofia/internal/4123343347@10.20.0.10 [user_exists]=[true]
Dialplan: sofia/internal/4123343347@10.20.0.10 Action set(from_user_exists=${user_exists id ${sip_from_user} ${sip_from_host}}) INLINE
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 set(from_user_exists=false)
2020-12-03 17:00:32.071352 [DEBUG] mod_dptools.c:1672 SET sofia/internal/4123343347@10.20.0.10 [from_user_exists]=[false]
Dialplan: sofia/internal/4123343347@10.20.0.10 Regex (PASS) [user_exists] ${user_exists}(true) =~ /^true$/ break=on-false
Dialplan: sofia/internal/4123343347@10.20.0.10 Action set(extension_uuid=${user_data ${destination_number}@${domain_name} var extension_uuid}) INLINE
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 set(extension_uuid=b2c8add0-8d18-4f50-ac20-67a36d1e7bd4)
2020-12-03 17:00:32.071352 [DEBUG] mod_dptools.c:1672 SET sofia/internal/4123343347@10.20.0.10 [extension_uuid]=[b2c8add0-8d18-4f50-ac20-67a36d1e7bd4]
Dialplan: sofia/internal/4123343347@10.20.0.10 Action set(hold_music=${user_data ${destination_number}@${domain_name} var hold_music}) INLINE
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 set(hold_music=)
2020-12-03 17:00:32.091346 [DEBUG] mod_dptools.c:1672 SET sofia/internal/4123343347@10.20.0.10 [hold_music]=[UNDEF]
Dialplan: sofia/internal/4123343347@10.20.0.10 Action set(forward_all_enabled=${user_data ${destination_number}@${domain_name} var forward_all_enabled}) INLINE
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 set(forward_all_enabled=)
2020-12-03 17:00:32.091346 [DEBUG] mod_dptools.c:1672 SET sofia/internal/4123343347@10.20.0.10 [forward_all_enabled]=[UNDEF]
Dialplan: sofia/internal/4123343347@10.20.0.10 Action set(forward_all_destination=${user_data ${destination_number}@${domain_name} var forward_all_destination}) INLINE
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 set(forward_all_destination=)
2020-12-03 17:00:32.111394 [DEBUG] mod_dptools.c:1672 SET sofia/internal/4123343347@10.20.0.10 [forward_all_destination]=[UNDEF]
Dialplan: sofia/internal/4123343347@10.20.0.10 Action set(forward_busy_enabled=${user_data ${destination_number}@${domain_name} var forward_busy_enabled}) INLINE
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 set(forward_busy_enabled=)
2020-12-03 17:00:32.111394 [DEBUG] mod_dptools.c:1672 SET sofia/internal/4123343347@10.20.0.10 [forward_busy_enabled]=[UNDEF]
Dialplan: sofia/internal/4123343347@10.20.0.10 Action set(forward_busy_destination=${user_data ${destination_number}@${domain_name} var forward_busy_destination}) INLINE
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 set(forward_busy_destination=)
2020-12-03 17:00:32.111394 [DEBUG] mod_dptools.c:1672 SET sofia/internal/4123343347@10.20.0.10 [forward_busy_destination]=[UNDEF]
Dialplan: sofia/internal/4123343347@10.20.0.10 Action set(forward_no_answer_enabled=${user_data ${destination_number}@${domain_name} var forward_no_answer_enabled}) INLINE
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 set(forward_no_answer_enabled=)
2020-12-03 17:00:32.131351 [DEBUG] mod_dptools.c:1672 SET sofia/internal/4123343347@10.20.0.10 [forward_no_answer_enabled]=[UNDEF]
Dialplan: sofia/internal/4123343347@10.20.0.10 Action set(forward_no_answer_destination=${user_data ${destination_number}@${domain_name} var forward_no_answer_destination}) INLINE
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 set(forward_no_answer_destination=)
2020-12-03 17:00:32.131351 [DEBUG] mod_dptools.c:1672 SET sofia/internal/4123343347@10.20.0.10 [forward_no_answer_destination]=[UNDEF]
Dialplan: sofia/internal/4123343347@10.20.0.10 Action set(forward_user_not_registered_enabled=${user_data ${destination_number}@${domain_name} var forward_user_not_registered_enabled}) INLINE
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 set(forward_user_not_registered_enabled=)
2020-12-03 17:00:32.131351 [DEBUG] mod_dptools.c:1672 SET sofia/internal/4123343347@10.20.0.10 [forward_user_not_registered_enabled]=[UNDEF]
Dialplan: sofia/internal/4123343347@10.20.0.10 Action set(forward_user_not_registered_destination=${user_data ${destination_number}@${domain_name} var forward_user_not_registered_destination}) INLINE
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 set(forward_user_not_registered_destination=)
2020-12-03 17:00:32.151351 [DEBUG] mod_dptools.c:1672 SET sofia/internal/4123343347@10.20.0.10 [forward_user_not_registered_destination]=[UNDEF]
Dialplan: sofia/internal/4123343347@10.20.0.10 Action set(forward_all_enabled=${user_data ${destination_number}@${domain_name} var forward_all_enabled}) INLINE
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 set(forward_all_enabled=)
2020-12-03 17:00:32.151351 [DEBUG] mod_dptools.c:1672 SET sofia/internal/4123343347@10.20.0.10 [forward_all_enabled]=[UNDEF]
Dialplan: sofia/internal/4123343347@10.20.0.10 Action set(follow_me_enabled=${user_data ${destination_number}@${domain_name} var follow_me_enabled}) INLINE
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 set(follow_me_enabled=)
2020-12-03 17:00:32.151351 [DEBUG] mod_dptools.c:1672 SET sofia/internal/4123343347@10.20.0.10 [follow_me_enabled]=[UNDEF]
Dialplan: sofia/internal/4123343347@10.20.0.10 Action set(do_not_disturb=${user_data ${destination_number}@${domain_name} var do_not_disturb}) INLINE
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 set(do_not_disturb=)
2020-12-03 17:00:32.171394 [DEBUG] mod_dptools.c:1672 SET sofia/internal/4123343347@10.20.0.10 [do_not_disturb]=[UNDEF]
Dialplan: sofia/internal/4123343347@10.20.0.10 Action set(call_timeout=${user_data ${destination_number}@${domain_name} var call_timeout}) INLINE
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 set(call_timeout=30)
2020-12-03 17:00:32.171394 [DEBUG] mod_dptools.c:1672 SET sofia/internal/4123343347@10.20.0.10 [call_timeout]=[30]
Dialplan: sofia/internal/4123343347@10.20.0.10 Action set(missed_call_app=${user_data ${destination_number}@${domain_name} var missed_call_app}) INLINE
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 set(missed_call_app=)
2020-12-03 17:00:32.171394 [DEBUG] mod_dptools.c:1672 SET sofia/internal/4123343347@10.20.0.10 [missed_call_app]=[UNDEF]
Dialplan: sofia/internal/4123343347@10.20.0.10 Action set(missed_call_data=${user_data ${destination_number}@${domain_name} var missed_call_data}) INLINE
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 set(missed_call_data=)
2020-12-03 17:00:32.191396 [DEBUG] mod_dptools.c:1672 SET sofia/internal/4123343347@10.20.0.10 [missed_call_data]=[UNDEF]
Dialplan: sofia/internal/4123343347@10.20.0.10 Action set(toll_allow=${user_data ${destination_number}@${domain_name} var toll_allow}) INLINE
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 set(toll_allow=)
2020-12-03 17:00:32.191396 [DEBUG] mod_dptools.c:1672 SET sofia/internal/4123343347@10.20.0.10 [toll_allow]=[UNDEF]
Dialplan: sofia/internal/4123343347@10.20.0.10 Action set(call_screen_enabled=${user_data ${destination_number}@${domain_name} var call_screen_enabled}) INLINE
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 set(call_screen_enabled=false)
2020-12-03 17:00:32.191396 [DEBUG] mod_dptools.c:1672 SET sofia/internal/4123343347@10.20.0.10 [call_screen_enabled]=[false]
Dialplan: sofia/internal/4123343347@10.20.0.10 Action set(user_record=${user_data ${destination_number}@${domain_name} var user_record}) INLINE
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 set(user_record=)
2020-12-03 17:00:32.211318 [DEBUG] mod_dptools.c:1672 SET sofia/internal/4123343347@10.20.0.10 [user_record]=[UNDEF]
Dialplan: sofia/internal/4123343347@10.20.0.10 parsing [default->global-variables] continue=true
Dialplan: sofia/internal/4123343347@10.20.0.10 Regex (PASS) [global-variables] () =~ // break=on-false
Dialplan: sofia/internal/4123343347@10.20.0.10 Action set(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
Dialplan: sofia/internal/4123343347@10.20.0.10 parsing [default->is_loopback] continue=true
Dialplan: sofia/internal/4123343347@10.20.0.10 Regex (FAIL) [is_loopback] ${is_follow_me_loopback}() =~ /true/ break=on-false
Dialplan: sofia/internal/4123343347@10.20.0.10 parsing [default->intercept-ext-polycom] continue=false
Dialplan: sofia/internal/4123343347@10.20.0.10 Regex (FAIL) [intercept-ext-polycom] destination_number(5661) =~ /^\*97(\d+)$/ break=on-false
Dialplan: sofia/internal/4123343347@10.20.0.10 parsing [default->extension-to-voicemail] continue=false
Dialplan: sofia/internal/4123343347@10.20.0.10 Regex (PASS) [extension-to-voicemail] ${user_exists}(true) =~ /^true$/ break=on-false
Dialplan: sofia/internal/4123343347@10.20.0.10 Regex (PASS) [extension-to-voicemail] username(4123343347) =~ /^4123343347$/ break=on-false
Dialplan: sofia/internal/4123343347@10.20.0.10 Regex (FAIL) [extension-to-voicemail] destination_number(5661) =~ /^4123343347$/ break=on-false
Dialplan: sofia/internal/4123343347@10.20.0.10 parsing [default->follow-me-destinations] continue=false
Dialplan: sofia/internal/4123343347@10.20.0.10 Regex (PASS) [follow-me-destinations] ${user_exists}(true) =~ /^true$/ break=on-false
Dialplan: sofia/internal/4123343347@10.20.0.10 Regex (FAIL) [follow-me-destinations] ${follow_me_enabled}() =~ /^true$/ break=on-false
Dialplan: sofia/internal/4123343347@10.20.0.10 parsing [default->call-forward-all] continue=
Dialplan: sofia/internal/4123343347@10.20.0.10 Regex (PASS) [call-forward-all] ${user_exists}(true) =~ /true/ break=on-false
Dialplan: sofia/internal/4123343347@10.20.0.10 Regex (FAIL) [call-forward-all] ${forward_all_enabled}() =~ /true/ break=on-false
Dialplan: sofia/internal/4123343347@10.20.0.10 parsing [default->call-forward-not-registered] continue=
Dialplan: sofia/internal/4123343347@10.20.0.10 Regex (PASS) [call-forward-not-registered] ${user_exists}(true) =~ /true/ break=on-false
Dialplan: sofia/internal/4123343347@10.20.0.10 Regex (FAIL) [call-forward-not-registered] ${forward_user_not_registered_enabled}() =~ /true/ break=on-false
Dialplan: sofia/internal/4123343347@10.20.0.10 parsing [default->talking clock date and time] continue=
Dialplan: sofia/internal/4123343347@10.20.0.10 Regex (FAIL) [talking clock date and time] destination_number(5661) =~ /^\*9172$/ break=on-false
Dialplan: sofia/internal/4123343347@10.20.0.10 parsing [default->talking clock time] continue=
Dialplan: sofia/internal/4123343347@10.20.0.10 Regex (FAIL) [talking clock time] destination_number(5661) =~ /^\*9170$/ break=on-false
Dialplan: sofia/internal/4123343347@10.20.0.10 parsing [default->talking clock date] continue=
Dialplan: sofia/internal/4123343347@10.20.0.10 Regex (FAIL) [talking clock date] destination_number(5661) =~ /^\*9171$/ break=on-false
Dialplan: sofia/internal/4123343347@10.20.0.10 parsing [default->local_extension] continue=true
Dialplan: sofia/internal/4123343347@10.20.0.10 Regex (PASS) [local_extension] ${user_exists}(true) =~ /true/ break=on-false
Dialplan: sofia/internal/4123343347@10.20.0.10 Action export(dialed_extension=${destination_number}) INLINE
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 export(dialed_extension=5661)
2020-12-03 17:00:32.211318 [DEBUG] switch_channel.c:1310 EXPORT (export_vars) [dialed_extension]=[5661]
Dialplan: sofia/internal/4123343347@10.20.0.10 Action limit(hash ${domain_name} ${destination_number} ${limit_max} ${limit_destination})
Dialplan: sofia/internal/4123343347@10.20.0.10 Regex (PASS) [local_extension] () =~ // break=on-false
Dialplan: sofia/internal/4123343347@10.20.0.10 Action set(hangup_after_bridge=true)
Dialplan: sofia/internal/4123343347@10.20.0.10 Action set(continue_on_fail=true)
Dialplan: sofia/internal/4123343347@10.20.0.10 Action hash(insert/${domain_name}-call_return/${dialed_extension}/${caller_id_number})
Dialplan: sofia/internal/4123343347@10.20.0.10 Action hash(insert/${domain_name}-last_dial_ext/${dialed_extension}/${uuid})
Dialplan: sofia/internal/4123343347@10.20.0.10 Action set(called_party_call_group=${user_data(${dialed_extension}@${domain_name} var call_group)})
Dialplan: sofia/internal/4123343347@10.20.0.10 Action hash(insert/${domain_name}-last_dial/${called_party_call_group}/${uuid})
Dialplan: sofia/internal/4123343347@10.20.0.10 Action set(api_hangup_hook=lua app.lua hangup)
Dialplan: sofia/internal/4123343347@10.20.0.10 Action export(domain_name=${domain_name})
Dialplan: sofia/internal/4123343347@10.20.0.10 Action bridge(user/${destination_number}@${domain_name})
Dialplan: sofia/internal/4123343347@10.20.0.10 Action lua(app.lua failure_handler)
Dialplan: sofia/internal/4123343347@10.20.0.10 parsing [default->voicemail] continue=false
Dialplan: sofia/internal/4123343347@10.20.0.10 Regex (PASS) [voicemail] ${user_exists}(true) =~ /true/ break=on-false
Dialplan: sofia/internal/4123343347@10.20.0.10 Action set(record_append=false) INLINE
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 set(record_append=false)
2020-12-03 17:00:32.211318 [DEBUG] mod_dptools.c:1672 SET sofia/internal/4123343347@10.20.0.10 [record_append]=[false]
Dialplan: sofia/internal/4123343347@10.20.0.10 Action set(voicemail_action=save) INLINE
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 set(voicemail_action=save)
2020-12-03 17:00:32.211318 [DEBUG] mod_dptools.c:1672 SET sofia/internal/4123343347@10.20.0.10 [voicemail_action]=[save]
Dialplan: sofia/internal/4123343347@10.20.0.10 Action set(voicemail_id=${destination_number}) INLINE
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 set(voicemail_id=5661)
2020-12-03 17:00:32.211318 [DEBUG] mod_dptools.c:1672 SET sofia/internal/4123343347@10.20.0.10 [voicemail_id]=[5661]
Dialplan: sofia/internal/4123343347@10.20.0.10 Action set(voicemail_profile=default) INLINE
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 set(voicemail_profile=default)
2020-12-03 17:00:32.211318 [DEBUG] mod_dptools.c:1672 SET sofia/internal/4123343347@10.20.0.10 [voicemail_profile]=[default]
Dialplan: sofia/internal/4123343347@10.20.0.10 Action lua(app.lua voicemail)
2020-12-03 17:00:32.211318 [DEBUG] switch_core_state_machine.c:287 (sofia/internal/4123343347@10.20.0.10) State Change CS_ROUTING -> CS_EXECUTE
2020-12-03 17:00:32.211318 [DEBUG] switch_core_state_machine.c:644 (sofia/internal/4123343347@10.20.0.10) State ROUTING going to sleep
2020-12-03 17:00:32.211318 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/4123343347@10.20.0.10) Running State Change CS_EXECUTE (Cur 1 Tot 89)
2020-12-03 17:00:32.211318 [DEBUG] switch_core_state_machine.c:651 (sofia/internal/4123343347@10.20.0.10) State EXECUTE
2020-12-03 17:00:32.211318 [DEBUG] mod_sofia.c:209 sofia/internal/4123343347@10.20.0.10 SOFIA EXECUTE
2020-12-03 17:00:32.211318 [DEBUG] switch_core_state_machine.c:329 sofia/internal/4123343347@10.20.0.10 Standard EXECUTE
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 set(RFC2822_DATE=Thu, 03 Dec 2020 17:00:32 -0400)
2020-12-03 17:00:32.211318 [DEBUG] mod_dptools.c:1672 SET sofia/internal/4123343347@10.20.0.10 [RFC2822_DATE]=[Thu, 03 Dec 2020 17:00:32 -0400]
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 limit(hash 10.20.0.1 5661 )
2020-12-03 17:00:32.211318 [DEBUG] switch_limit.c:124 incr called: 10.20.0.1_5661 max:-1, interval:0
2020-12-03 17:00:32.211318 [DEBUG] mod_hash.c:194 Usage for 10.20.0.1_5661 is now 1
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 set(hangup_after_bridge=true)
2020-12-03 17:00:32.211318 [DEBUG] mod_dptools.c:1672 SET sofia/internal/4123343347@10.20.0.10 [hangup_after_bridge]=[true]
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 set(continue_on_fail=true)
2020-12-03 17:00:32.211318 [DEBUG] mod_dptools.c:1672 SET sofia/internal/4123343347@10.20.0.10 [continue_on_fail]=[true]
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 hash(insert/10.20.0.1-call_return/5661/4123343347)
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 hash(insert/10.20.0.1-last_dial_ext/5661/96139f7c-c058-4cdf-be92-165038b078e1)
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 set(called_party_call_group=)
2020-12-03 17:00:32.211318 [DEBUG] mod_dptools.c:1672 SET sofia/internal/4123343347@10.20.0.10 [called_party_call_group]=[UNDEF]
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 hash(insert/10.20.0.1-last_dial//96139f7c-c058-4cdf-be92-165038b078e1)
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 set(api_hangup_hook=lua app.lua hangup)
2020-12-03 17:00:32.211318 [DEBUG] mod_dptools.c:1672 SET sofia/internal/4123343347@10.20.0.10 [api_hangup_hook]=[lua app.lua hangup]
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 export(domain_name=10.20.0.1)
2020-12-03 17:00:32.211318 [DEBUG] switch_channel.c:1310 EXPORT (export_vars) [domain_name]=[10.20.0.1]
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 bridge(user/5661@10.20.0.1)
nta.c:1296 agent_timer() nta: timer set next to 27461 ms
2020-12-03 17:00:32.211318 [DEBUG] switch_channel.c:1264 sofia/internal/4123343347@10.20.0.10 EXPORTING[export_vars] [call_direction]=[inbound] to event
2020-12-03 17:00:32.211318 [DEBUG] switch_channel.c:1264 sofia/internal/4123343347@10.20.0.10 EXPORTING[export_vars] [call_direction]=[inbound] to event
2020-12-03 17:00:32.211318 [DEBUG] switch_channel.c:1264 sofia/internal/4123343347@10.20.0.10 EXPORTING[export_vars] [call_direction]=[inbound] to event
2020-12-03 17:00:32.211318 [DEBUG] switch_channel.c:1264 sofia/internal/4123343347@10.20.0.10 EXPORTING[export_vars] [dialed_extension]=[5661] to event
2020-12-03 17:00:32.211318 [DEBUG] switch_channel.c:1264 sofia/internal/4123343347@10.20.0.10 EXPORTING[export_vars] [domain_name]=[10.20.0.1] to event
2020-12-03 17:00:32.211318 [DEBUG] switch_ivr_originate.c:2242 Parsing global variables
2020-12-03 17:00:32.211318 [DEBUG] switch_channel.c:1264 sofia/internal/4123343347@10.20.0.10 EXPORTING[export_vars] [call_direction]=[inbound] to event
2020-12-03 17:00:32.211318 [DEBUG] switch_channel.c:1264 sofia/internal/4123343347@10.20.0.10 EXPORTING[export_vars] [call_direction]=[inbound] to event
2020-12-03 17:00:32.211318 [DEBUG] switch_channel.c:1264 sofia/internal/4123343347@10.20.0.10 EXPORTING[export_vars] [call_direction]=[inbound] to event
2020-12-03 17:00:32.211318 [DEBUG] switch_channel.c:1264 sofia/internal/4123343347@10.20.0.10 EXPORTING[export_vars] [dialed_extension]=[5661] to event
2020-12-03 17:00:32.211318 [DEBUG] switch_channel.c:1264 sofia/internal/4123343347@10.20.0.10 EXPORTING[export_vars] [domain_name]=[10.20.0.1] to event
2020-12-03 17:00:32.211318 [DEBUG] switch_ivr_originate.c:2242 Parsing global variables
2020-12-03 17:00:32.211318 [NOTICE] switch_channel.c:1118 New Channel sofia/internal/5661@10.20.40.17:5060 [863a78f6-2e05-4e71-a5bd-c56feed57abc]
2020-12-03 17:00:32.211318 [DEBUG] mod_sofia.c:5089 (sofia/internal/5661@10.20.40.17:5060) State Change CS_NEW -> CS_INIT
2020-12-03 17:00:32.211318 [DEBUG] switch_ivr_originate.c:3111 sofia/internal/5661@10.20.40.17:5060 Setting leg timeout to 30
2020-12-03 17:00:32.231339 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/5661@10.20.40.17:5060) Running State Change CS_INIT (Cur 2 Tot 90)
2020-12-03 17:00:32.231339 [DEBUG] switch_core_state_machine.c:628 (sofia/internal/5661@10.20.40.17:5060) State INIT
2020-12-03 17:00:32.231339 [DEBUG] mod_sofia.c:93 sofia/internal/5661@10.20.40.17:5060 SOFIA INIT
nua_common.c:108 nh_create_handle() nua: nh_create_handle: entering
nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering
2020-12-03 17:00:32.231339 [DEBUG] sofia_glue.c:1618 sofia/internal/5661@10.20.40.17:5060 sending invite version: 1.10.3 -release-15-129de34d84 64bit
Local SDP:
v=0
o=FreeSWITCH 1606999076 1606999077 IN IP4 10.20.0.1
s=FreeSWITCH
c=IN IP4 10.20.0.1
t=0 0
m=audio 30156 RTP/AVP 9 0 8 101 13
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=rtpmap:13 CN/8000
a=ptime:20
a=sendrecv
nua.c:633 nua_invite() nua: nua_invite: entering
nua_stack.c:529 nua_signal() nua(0x7f53f006ee70): sent signal r_invite
2020-12-03 17:00:32.231339 [DEBUG] switch_core_state_machine.c:40 sofia/internal/5661@10.20.40.17:5060 Standard INIT
2020-12-03 17:00:32.231339 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/5661@10.20.40.17:5060) State Change CS_INIT -> CS_ROUTING
2020-12-03 17:00:32.231339 [DEBUG] switch_core_state_machine.c:628 (sofia/internal/5661@10.20.40.17:5060) State INIT going to sleep
nua_stack.c:569 nua_stack_signal() nua(0x7f53f006ee70): recv signal r_invite
nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:280 soa_clone() soa_clone(static::0x7f53cc001b90, 0x7f53cc001390, 0x7f53f006ee70) called
soa.c:403 soa_set_params() soa_set_params(static::0x7f53cc00cbf0, ...) called
soa.c:403 soa_set_params() soa_set_params(static::0x7f53cc00cbf0, ...) called
soa.c:1052 soa_set_user_sdp() soa_set_user_sdp(static::0x7f53cc00cbf0, (nil), 0x7f53f0047e22, -1) called
soa.c:890 soa_set_capability_sdp() soa_set_capability_sdp(static::0x7f53cc00cbf0, (nil), 0x7f53f0047e22, -1) called
nua_dialog.c:338 nua_dialog_usage_add() nua(0x7f53f006ee70): adding session usage
nta.c:4422 nta_leg_tcreate() nta_leg_tcreate(0x7f53cc015ae0)
2020-12-03 17:00:32.231339 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/5661@10.20.40.17:5060) Running State Change CS_ROUTING (Cur 2 Tot 90)
soa.c:1302 soa_init_offer_answer() soa_init_offer_answer(static::0x7f53cc00cbf0) called
soa.c:1426 soa_generate_offer() soa_generate_offer(static::0x7f53cc00cbf0, 0) called
soa_static.c:1148 offer_answer_step() soa_static_offer_answer_action(0x7f53cc00cbf0, soa_generate_offer): called
soa_static.c:1189 offer_answer_step() soa_static(0x7f53cc00cbf0, soa_generate_offer): generating local description
soa_static.c:1217 offer_answer_step() soa_static(0x7f53cc00cbf0, soa_generate_offer): upgrade with local description
soa_static.c:1029 soa_sdp_mode_set() soa_sdp_mode_set(0x7f541440a860, (nil), ""): called
soa_static.c:1446 offer_answer_step() soa_static(0x7f53cc00cbf0, soa_generate_offer): storing local description
soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x7f53cc00cbf0, [(nil)], [0x7f541440c9e8], [0x7f541440c9e4]) called
nta.c:2670 nta_tpn_by_url() nta: selecting scheme sip
2020-12-03 17:00:32.231339 [DEBUG] switch_core_state_machine.c:644 (sofia/internal/5661@10.20.40.17:5060) State ROUTING
2020-12-03 17:00:32.231339 [DEBUG] mod_sofia.c:154 sofia/internal/5661@10.20.40.17:5060 SOFIA ROUTING
2020-12-03 17:00:32.231339 [DEBUG] switch_ivr_originate.c:67 (sofia/internal/5661@10.20.40.17:5060) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2020-12-03 17:00:32.231339 [DEBUG] switch_core_state_machine.c:644 (sofia/internal/5661@10.20.40.17:5060) State ROUTING going to sleep
tport.c:3275 tport_tsend() tport_tsend(0x7f53cc004e80) tpn = udp/10.20.40.17:5060
tport.c:4064 tport_resolve() tport_resolve addrinfo = 10.20.40.17:5060
tport.c:4698 tport_by_addrinfo() tport_by_addrinfo(0x7f53cc004e80): not found by name udp/10.20.40.17:5060
tport.c:3612 tport_vsend() tport_vsend(0x7f53cc004e80): 1252 bytes of 1252 to udp/10.20.40.17:5060
2020-12-03 17:00:32.231339 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/5661@10.20.40.17:5060) Running State Change CS_CONSUME_MEDIA (Cur 2 Tot 90)
tport.c:3510 tport_send_msg() tport_vsend returned 1252
nta.c:8315 outgoing_send() nta: sent INVITE (28960824) to udp/10.20.40.17:5060
tport.c:4178 tport_pend() tport_pend(0x7f53cc004e80): pending 0x7f53cc041210 for udp/10.20.0.1:5060 (already 0)
nta.c:1348 set_timeout() nta: timer shortened to 1000 ms
nua_session.c:4140 signal_call_state_change() nua(0x7f53f006ee70): call state changed: init -> calling, sent offer
soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x7f53cc00cbf0, [0x7f541440c9c8], [0x7f541440c9d0], [(nil)]) called
nua_stack.c:269 nua_stack_event() nua(0x7f53f006ee70): event i_state INVITE sent
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2020-12-03 17:00:32.231339 [DEBUG] sofia.c:7325 Channel sofia/internal/5661@10.20.40.17:5060 entering state [calling][0]
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2020-12-03 17:00:32.231339 [DEBUG] switch_core_state_machine.c:663 (sofia/internal/5661@10.20.40.17:5060) State CONSUME_MEDIA
2020-12-03 17:00:32.231339 [DEBUG] switch_core_state_machine.c:663 (sofia/internal/5661@10.20.40.17:5060) State CONSUME_MEDIA going to sleep
tport.c:2759 tport_wakeup_pri() tport_wakeup_pri(0x7f53cc004e80): events IN
tport.c:2882 tport_recv_event() tport_recv_event(0x7f53cc004e80)
tport.c:3223 tport_recv_iovec() tport_recv_iovec(0x7f53cc004e80) msg 0x7f53cc125a90 from (udp/10.20.0.1:5060) has 319 bytes, veclen = 1
tport.c:3041 tport_deliver() tport_deliver(0x7f53cc004e80): msg 0x7f53cc125a90 (319 bytes) from udp/10.20.40.17:5060/sip next=(nil)
nta.c:3304 agent_recv_response() nta: received 100 Trying for INVITE (28960824)
nta.c:3371 agent_recv_response() nta: 100 Trying is going to a transaction
nta.c:9584 outgoing_estimate_delay() nta_outgoing: RTT is 104.797 ms
tport.c:4240 tport_release() tport_release(0x7f53cc004e80): 0x7f53cc041210 by 0x7f53cc05e3b0 with 0x7f53cc125a90 (preliminary)
nta.c:1296 agent_timer() nta: timer set next to 26448 ms
tport.c:2759 tport_wakeup_pri() tport_wakeup_pri(0x7f53cc004e80): events IN
tport.c:2882 tport_recv_event() tport_recv_event(0x7f53cc004e80)
tport.c:3223 tport_recv_iovec() tport_recv_iovec(0x7f53cc004e80) msg 0x7f53cc125a90 from (udp/10.20.0.1:5060) has 414 bytes, veclen = 1
tport.c:3041 tport_deliver() tport_deliver(0x7f53cc004e80): msg 0x7f53cc125a90 (414 bytes) from udp/10.20.60.11:5060/sip next=(nil)
nta.c:2885 agent_recv_request() nta: received REGISTER sip:10.20.0.1 SIP/2.0 (CSeq 78275)
nta.c:3253 agent_aliases() nta: canonizing sip:10.20.0.1 with contact
nta.c:3090 agent_recv_request() nta: REGISTER (78275) going to a default leg
nua_server.c:102 nua_stack_process_request() nua: nua_stack_process_request: entering
nua_stack.c:901 nh_create() nua: nh_create: entering
nua_common.c:108 nh_create_handle() nua: nh_create_handle: entering
nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:280 soa_clone() soa_clone(static::0x7f53cc001b90, 0x7f53cc001390, 0x7f53cc0e4350) called
soa.c:403 soa_set_params() soa_set_params(static::0x7f53cc055cb0, ...) called
nua_stack.c:271 nua_stack_event() nua(0x7f53cc0e4350): event i_register 100 Trying
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:879 nua_respond() nua: nua_respond: entering
nua_stack.c:529 nua_signal() nua(0x7f53cc0e4350): sent signal r_respond
2020-12-03 17:00:33.331423 [WARNING] sofia_reg.c:1794 SIP auth challenge (REGISTER) on sofia profile 'internal' for [5476@10.20.0.1] from ip 10.20.60.11
nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
nua_stack.c:529 nua_signal() nua(0x7f53cc0e4350): sent signal r_destroy
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
nua_stack.c:573 nua_stack_signal() nua(0x7f53cc0e4350): recv signal r_respond 401 Unauthorized
nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:403 soa_set_params() soa_set_params(static::0x7f53cc055cb0, ...) called
tport.c:3275 tport_tsend() tport_tsend(0x7f53cc004e80) tpn = UDP/10.20.60.11:5060
tport.c:4064 tport_resolve() tport_resolve addrinfo = 10.20.60.11:5060
tport.c:4698 tport_by_addrinfo() tport_by_addrinfo(0x7f53cc004e80): not found by name UDP/10.20.60.11:5060
tport.c:3612 tport_vsend() tport_vsend(0x7f53cc004e80): 578 bytes of 578 to udp/10.20.60.11:5060
tport.c:3510 tport_send_msg() tport_vsend returned 578
nta.c:6802 incoming_reply() nta: sent 401 Unauthorized for REGISTER (78275)
nua_stack.c:569 nua_stack_signal() nua(0x7f53cc0e4350): recv signal r_destroy
nta.c:4475 nta_leg_destroy() nta_leg_destroy((nil))
soa.c:356 soa_destroy() soa_destroy(static::0x7f53cc055cb0) called
tport.c:2759 tport_wakeup_pri() tport_wakeup_pri(0x7f53cc004e80): events IN
tport.c:2882 tport_recv_event() tport_recv_event(0x7f53cc004e80)
tport.c:3223 tport_recv_iovec() tport_recv_iovec(0x7f53cc004e80) msg 0x7f53cc02b4d0 from (udp/10.20.0.1:5060) has 641 bytes, veclen = 1
tport.c:3041 tport_deliver() tport_deliver(0x7f53cc004e80): msg 0x7f53cc02b4d0 (641 bytes) from udp/10.20.60.11:5060/sip next=(nil)
nta.c:2885 agent_recv_request() nta: received REGISTER sip:10.20.0.1 SIP/2.0 (CSeq 78276)
nta.c:3253 agent_aliases() nta: canonizing sip:10.20.0.1 with contact
nta.c:3090 agent_recv_request() nta: REGISTER (78276) going to a default leg
nua_server.c:102 nua_stack_process_request() nua: nua_stack_process_request: entering
nua_stack.c:901 nh_create() nua: nh_create: entering
nua_common.c:108 nh_create_handle() nua: nh_create_handle: entering
nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:280 soa_clone() soa_clone(static::0x7f53cc001b90, 0x7f53cc001390, 0x7f53cc00d520) called
soa.c:403 soa_set_params() soa_set_params(static::0x7f53cc055cb0, ...) called
nua_stack.c:271 nua_stack_event() nua(0x7f53cc00d520): event i_register 100 Trying
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:879 nua_respond() nua: nua_respond: entering
nua_stack.c:529 nua_signal() nua(0x7f53cc00d520): sent signal r_respond
nua_stack.c:573 nua_stack_signal() nua(0x7f53cc00d520): recv signal r_respond 200 OK
nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:403 soa_set_params() soa_set_params(static::0x7f53cc055cb0, ...) called
nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
nua_stack.c:529 nua_signal() nua(0x7f53cc00d520): sent signal r_destroy
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
tport.c:3275 tport_tsend() tport_tsend(0x7f53cc004e80) tpn = UDP/10.20.60.11:5060
tport.c:4064 tport_resolve() tport_resolve addrinfo = 10.20.60.11:5060
tport.c:4698 tport_by_addrinfo() tport_by_addrinfo(0x7f53cc004e80): not found by name UDP/10.20.60.11:5060
tport.c:3612 tport_vsend() tport_vsend(0x7f53cc004e80): 538 bytes of 538 to udp/10.20.60.11:5060
tport.c:3510 tport_send_msg() tport_vsend returned 538
nta.c:6802 incoming_reply() nta: sent 200 OK for REGISTER (78276)
nua_stack.c:569 nua_stack_signal() nua(0x7f53cc00d520): recv signal r_destroy
nta.c:4475 nta_leg_destroy() nta_leg_destroy((nil))
soa.c:356 soa_destroy() soa_destroy(static::0x7f53cc055cb0) called
tport.c:2759 tport_wakeup_pri() tport_wakeup_pri(0x7f53cc004e80): events IN
tport.c:2882 tport_recv_event() tport_recv_event(0x7f53cc004e80)
tport.c:3223 tport_recv_iovec() tport_recv_iovec(0x7f53cc004e80) msg 0x7f53cc047480 from (udp/10.20.0.1:5060) has 408 bytes, veclen = 1
tport.c:3041 tport_deliver() tport_deliver(0x7f53cc004e80): msg 0x7f53cc047480 (408 bytes) from udp/10.20.50.1:5060/sip next=(nil)
nta.c:2885 agent_recv_request() nta: received REGISTER sip:10.20.0.1 SIP/2.0 (CSeq 31)
nta.c:3253 agent_aliases() nta: canonizing sip:10.20.0.1 with contact
nta.c:3090 agent_recv_request() nta: REGISTER (31) going to a default leg
nua_server.c:102 nua_stack_process_request() nua: nua_stack_process_request: entering
nua_stack.c:901 nh_create() nua: nh_create: entering
nua_common.c:108 nh_create_handle() nua: nh_create_handle: entering
nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:280 soa_clone() soa_clone(static::0x7f53cc001b90, 0x7f53cc001390, 0x7f53cc129340) called
soa.c:403 soa_set_params() soa_set_params(static::0x7f53cc1364f0, ...) called
nua_stack.c:271 nua_stack_event() nua(0x7f53cc129340): event i_register 100 Trying
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:879 nua_respond() nua: nua_respond: entering
nua_stack.c:573 nua_stack_signal() nua(0x7f53cc129340): recv signal r_respond 401 Unauthorized
nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:403 soa_set_params() soa_set_params(static::0x7f53cc1364f0, ...) called
tport.c:3275 tport_tsend() tport_tsend(0x7f53cc004e80) tpn = UDP/10.20.50.1:5060
nua_stack.c:529 nua_signal() nua(0x7f53cc129340): sent signal r_respond
tport.c:4064 tport_resolve() tport_resolve addrinfo = 10.20.50.1:5060
tport.c:4698 tport_by_addrinfo() tport_by_addrinfo(0x7f53cc004e80): not found by name UDP/10.20.50.1:5060
2020-12-03 17:00:34.431401 [WARNING] sofia_reg.c:1794 SIP auth challenge (REGISTER) on sofia profile 'internal' for [5602@10.20.0.1] from ip 10.20.50.1
nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
nua_stack.c:529 nua_signal() nua(0x7f53cc129340): sent signal r_destroy
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
tport.c:3612 tport_vsend() tport_vsend(0x7f53cc004e80): 572 bytes of 572 to udp/10.20.50.1:5060
tport.c:3510 tport_send_msg() tport_vsend returned 572
nta.c:6802 incoming_reply() nta: sent 401 Unauthorized for REGISTER (31)
nua_stack.c:569 nua_stack_signal() nua(0x7f53cc129340): recv signal r_destroy
nta.c:4475 nta_leg_destroy() nta_leg_destroy((nil))
soa.c:356 soa_destroy() soa_destroy(static::0x7f53cc1364f0) called
tport.c:2759 tport_wakeup_pri() tport_wakeup_pri(0x7f53cc004e80): events IN
tport.c:2882 tport_recv_event() tport_recv_event(0x7f53cc004e80)
tport.c:3223 tport_recv_iovec() tport_recv_iovec(0x7f53cc004e80) msg 0x7f53cc102050 from (udp/10.20.0.1:5060) has 634 bytes, veclen = 1
tport.c:3041 tport_deliver() tport_deliver(0x7f53cc004e80): msg 0x7f53cc102050 (634 bytes) from udp/10.20.50.1:5060/sip next=(nil)
nta.c:2885 agent_recv_request() nta: received REGISTER sip:10.20.0.1 SIP/2.0 (CSeq 32)
nta.c:3253 agent_aliases() nta: canonizing sip:10.20.0.1 with contact
nta.c:3090 agent_recv_request() nta: REGISTER (32) going to a default leg
nua_server.c:102 nua_stack_process_request() nua: nua_stack_process_request: entering
nua_stack.c:901 nh_create() nua: nh_create: entering
nua_common.c:108 nh_create_handle() nua: nh_create_handle: entering
nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:280 soa_clone() soa_clone(static::0x7f53cc001b90, 0x7f53cc001390, 0x7f53cc0f6c80) called
soa.c:403 soa_set_params() soa_set_params(static::0x7f53cc129260, ...) called
nua_stack.c:271 nua_stack_event() nua(0x7f53cc0f6c80): event i_register 100 Trying
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:879 nua_respond() nua: nua_respond: entering
nua_stack.c:573 nua_stack_signal() nua(0x7f53cc0f6c80): recv signal r_respond 200 OK
nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering
nua_stack.c:529 nua_signal() nua(0x7f53cc0f6c80): sent signal r_respond
soa.c:403 soa_set_params() soa_set_params(static::0x7f53cc129260, ...) called
tport.c:3275 tport_tsend() tport_tsend(0x7f53cc004e80) tpn = UDP/10.20.50.1:5060
tport.c:4064 tport_resolve() tport_resolve addrinfo = 10.20.50.1:5060
tport.c:4698 tport_by_addrinfo() tport_by_addrinfo(0x7f53cc004e80): not found by name UDP/10.20.50.1:5060
nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
tport.c:3612 tport_vsend() tport_vsend(0x7f53cc004e80): 532 bytes of 532 to udp/10.20.50.1:5060
tport.c:3510 tport_send_msg() tport_vsend returned 532
nua_stack.c:529 nua_signal() nua(0x7f53cc0f6c80): sent signal r_destroy
nta.c:6802 incoming_reply() nta: sent 200 OK for REGISTER (32)
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
nua_stack.c:569 nua_stack_signal() nua(0x7f53cc0f6c80): recv signal r_destroy
nta.c:4475 nta_leg_destroy() nta_leg_destroy((nil))
soa.c:356 soa_destroy() soa_destroy(static::0x7f53cc129260) called
tport.c:2759 tport_wakeup_pri() tport_wakeup_pri(0x7f53cc004e80): events IN
tport.c:2882 tport_recv_event() tport_recv_event(0x7f53cc004e80)
tport.c:3223 tport_recv_iovec() tport_recv_iovec(0x7f53cc004e80) msg 0x7f53cc12de20 from (udp/10.20.0.1:5060) has 746 bytes, veclen = 1
tport.c:3041 tport_deliver() tport_deliver(0x7f53cc004e80): msg 0x7f53cc12de20 (746 bytes) from udp/10.20.40.17:5060/sip next=(nil)
nta.c:3304 agent_recv_response() nta: received 200 OK for INVITE (28960824)
nta.c:3371 agent_recv_response() nta: 200 OK is going to a transaction
tport.c:4240 tport_release() tport_release(0x7f53cc004e80): 0x7f53cc041210 by 0x7f53cc05e3b0 with 0x7f53cc12de20
soa.c:1171 soa_set_remote_sdp() soa_set_remote_sdp(static::0x7f53cc00cbf0, (nil), 0x7f53cc0f6a78, 210) called
soa.c:1595 soa_process_answer() soa_process_answer(static::0x7f53cc00cbf0) called
soa_static.c:1148 offer_answer_step() soa_static_offer_answer_action(0x7f53cc00cbf0, soa_process_answer): called
soa_static.c:1029 soa_sdp_mode_set() soa_sdp_mode_set(0x7f53cc12da90, 0x7f53dc05e690, ""): called
soa_static.c:1304 offer_answer_step() soa_static(0x7f53cc00cbf0, soa_process_answer): upgrade codecs with remote description
soa_static.c:1446 offer_answer_step() soa_static(0x7f53cc00cbf0, soa_process_answer): storing local description
soa.c:1730 soa_activate() soa_activate(static::0x7f53cc00cbf0, (nil)) called
nua_session.c:986 nua_session_client_response() nua(0x7f53f006ee70): INVITE: processed SDP answer in 200 OK (200)
nua_stack.c:271 nua_stack_event() nua(0x7f53f006ee70): event r_invite 200 OK
nua_session.c:4140 signal_call_state_change() nua(0x7f53f006ee70): call state changed: calling -> completing, received answer
soa.c:1098 soa_get_remote_sdp() soa_get_remote_sdp(static::0x7f53cc00cbf0, [0x7f541440c3e8], [0x7f541440c3f0], [(nil)]) called
soa.c:616 soa_get_params() soa_get_params(static::0x7f53cc00cbf0, ...) called
nua_stack.c:271 nua_stack_event() nua(0x7f53f006ee70): event i_state 200 OK
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2020-12-03 17:00:34.831425 [DEBUG] sofia.c:7325 Channel sofia/internal/5661@10.20.40.17:5060 entering state [completing][200]
2020-12-03 17:00:34.831425 [DEBUG] sofia.c:7335 Remote SDP:
v=0
o=5661 8000 8000 IN IP4 10.20.40.17
s=SIP Call
c=IN IP4 10.20.40.17
t=0 0
m=audio 5004 RTP/AVP 9 101
a=rtpmap:9 G722/16000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-11
a=ptime:20
nua.c:639 nua_ack() nua: nua_ack: entering
nua_stack.c:529 nua_signal() nua(0x7f53f006ee70): sent signal r_ack
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua_stack.c:569 nua_stack_signal() nua(0x7f53f006ee70): recv signal r_ack
nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:403 soa_set_params() soa_set_params(static::0x7f53cc00cbf0, ...) called
soa.c:1730 soa_activate() soa_activate(static::0x7f53cc00cbf0, (nil)) called
nta.c:2670 nta_tpn_by_url() nta: selecting scheme sip
tport.c:3275 tport_tsend() tport_tsend(0x7f53cc004e80) tpn = udp/10.20.40.17:5060
tport.c:4064 tport_resolve() tport_resolve addrinfo = 10.20.40.17:5060
tport.c:4698 tport_by_addrinfo() tport_by_addrinfo(0x7f53cc004e80): not found by name udp/10.20.40.17:5060
tport.c:3612 tport_vsend() tport_vsend(0x7f53cc004e80): 395 bytes of 395 to udp/10.20.40.17:5060
tport.c:3510 tport_send_msg() tport_vsend returned 395
nta.c:8315 outgoing_send() nta: sent ACK (28960824) to udp/10.20.40.17:5060
nua_session.c:4140 signal_call_state_change() nua(0x7f53f006ee70): call state changed: completing -> ready
nua_stack.c:271 nua_stack_event() nua(0x7f53f006ee70): event i_state 200 ACK sent
nua_stack.c:271 nua_stack_event() nua(0x7f53f006ee70): event i_active 200 Call active
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2020-12-03 17:00:34.831425 [DEBUG] sofia.c:7325 Channel sofia/internal/5661@10.20.40.17:5060 entering state [ready][200]
2020-12-03 17:00:34.831425 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [G722:9:16000:20:64000:1]/[G722:9:8000:20:64000:1]
2020-12-03 17:00:34.831425 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [G722:9:16000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2020-12-03 17:00:34.831425 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [G722:9:16000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2020-12-03 17:00:34.831425 [DEBUG] switch_core_media.c:5508 Set telephone-event payload to 101@8000
2020-12-03 17:00:34.831425 [DEBUG] switch_core_media.c:5909 sofia/internal/5661@10.20.40.17:5060 Set 2833 dtmf send payload to 101 recv payload to 101
2020-12-03 17:00:34.831425 [NOTICE] sofia.c:8525 Hangup sofia/internal/5661@10.20.40.17:5060 [CS_CONSUME_MEDIA] [INCOMPATIBLE_DESTINATION]
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2020-12-03 17:00:34.851389 [DEBUG] sofia.c:1548 Channel is already hungup.
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2020-12-03 17:00:34.851389 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/5661@10.20.40.17:5060) Running State Change CS_HANGUP (Cur 2 Tot 90)
2020-12-03 17:00:34.851389 [DEBUG] switch_core_state_machine.c:848 (sofia/internal/5661@10.20.40.17:5060) Callstate Change DOWN -> HANGUP
2020-12-03 17:00:34.851389 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/5661@10.20.40.17:5060) State HANGUP
2020-12-03 17:00:34.851389 [DEBUG] mod_sofia.c:453 Channel sofia/internal/5661@10.20.40.17:5060 hanging up, cause: INCOMPATIBLE_DESTINATION
2020-12-03 17:00:34.851389 [DEBUG] mod_sofia.c:507 Sending BYE to sofia/internal/5661@10.20.40.17:5060
nua.c:645 nua_bye() nua: nua_bye: entering
nua_stack.c:569 nua_stack_signal() nua(0x7f53f006ee70): recv signal r_bye
nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:403 soa_set_params() soa_set_params(static::0x7f53cc00cbf0, ...) called
soa.c:1784 soa_terminate() soa_terminate(static::0x7f53cc00cbf0) called
nua_stack.c:529 nua_signal() nua(0x7f53f006ee70): sent signal r_bye
soa.c:1302 soa_init_offer_answer() soa_init_offer_answer(static::0x7f53cc00cbf0) called
2020-12-03 17:00:34.851389 [DEBUG] switch_core_state_machine.c:60 sofia/internal/5661@10.20.40.17:5060 Standard HANGUP, cause: INCOMPATIBLE_DESTINATION
nta.c:2670 nta_tpn_by_url() nta: selecting scheme sip
tport.c:3275 tport_tsend() tport_tsend(0x7f53cc004e80) tpn = udp/10.20.40.17:5060
2020-12-03 17:00:34.851389 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/5661@10.20.40.17:5060) State HANGUP going to sleep
tport.c:4064 tport_resolve() tport_resolve addrinfo = 10.20.40.17:5060
tport.c:4698 tport_by_addrinfo() tport_by_addrinfo(0x7f53cc004e80): not found by name udp/10.20.40.17:5060
2020-12-03 17:00:34.851389 [DEBUG] switch_core_state_machine.c:620 (sofia/internal/5661@10.20.40.17:5060) State Change CS_HANGUP -> CS_REPORTING
tport.c:3612 tport_vsend() tport_vsend(0x7f53cc004e80): 578 bytes of 578 to udp/10.20.40.17:5060
tport.c:3510 tport_send_msg() tport_vsend returned 578
nta.c:8315 outgoing_send() nta: sent BYE (28960825) to udp/10.20.40.17:5060
tport.c:4178 tport_pend() tport_pend(0x7f53cc004e80): pending 0x7f53cc05ecd0 for udp/10.20.0.1:5060 (already 0)
nta.c:1348 set_timeout() nta: timer shortened to 1000 ms
2020-12-03 17:00:34.851389 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/5661@10.20.40.17:5060) Running State Change CS_REPORTING (Cur 2 Tot 90)
2020-12-03 17:00:34.851389 [DEBUG] switch_core_state_machine.c:936 (sofia/internal/5661@10.20.40.17:5060) State REPORTING
2020-12-03 17:00:34.851389 [DEBUG] switch_core_state_machine.c:174 sofia/internal/5661@10.20.40.17:5060 Standard REPORTING, cause: INCOMPATIBLE_DESTINATION
2020-12-03 17:00:34.851389 [DEBUG] switch_core_state_machine.c:936 (sofia/internal/5661@10.20.40.17:5060) State REPORTING going to sleep
2020-12-03 17:00:34.851389 [DEBUG] switch_core_state_machine.c:611 (sofia/internal/5661@10.20.40.17:5060) State Change CS_REPORTING -> CS_DESTROY
2020-12-03 17:00:34.851389 [DEBUG] switch_core_session.c:1726 Session 90 (sofia/internal/5661@10.20.40.17:5060) Locked, Waiting on external entities
2020-12-03 17:00:34.851389 [DEBUG] switch_ivr_originate.c:3995 Originate Resulted in Error Cause: 88 [INCOMPATIBLE_DESTINATION]
2020-12-03 17:00:34.851389 [NOTICE] switch_core_session.c:1744 Session 90 (sofia/internal/5661@10.20.40.17:5060) Ended
2020-12-03 17:00:34.851389 [NOTICE] switch_core_session.c:1748 Close Channel sofia/internal/5661@10.20.40.17:5060 [CS_DESTROY]
2020-12-03 17:00:34.851389 [DEBUG] switch_core_state_machine.c:739 (sofia/internal/5661@10.20.40.17:5060) Running State Change CS_DESTROY (Cur 1 Tot 90)
2020-12-03 17:00:34.851389 [DEBUG] switch_core_state_machine.c:749 (sofia/internal/5661@10.20.40.17:5060) State DESTROY
2020-12-03 17:00:34.851389 [DEBUG] mod_sofia.c:364 sofia/internal/5661@10.20.40.17:5060 SOFIA DESTROY
2020-12-03 17:00:34.851389 [NOTICE] switch_ivr_originate.c:2999 Cannot create outgoing channel of type [user] cause: [INCOMPATIBLE_DESTINATION]
2020-12-03 17:00:34.851389 [DEBUG] switch_core_state_machine.c:181 sofia/internal/5661@10.20.40.17:5060 Standard DESTROY
2020-12-03 17:00:34.851389 [DEBUG] switch_core_state_machine.c:749 (sofia/internal/5661@10.20.40.17:5060) State DESTROY going to sleep
2020-12-03 17:00:34.851389 [DEBUG] switch_ivr_originate.c:3995 Originate Resulted in Error Cause: 88 [INCOMPATIBLE_DESTINATION]
2020-12-03 17:00:34.851389 [INFO] mod_dptools.c:3631 Originate Failed. Cause: INCOMPATIBLE_DESTINATION
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 lua(app.lua failure_handler)
2020-12-03 17:00:34.871359 [DEBUG] switch_cpp.cpp:1191 sofia/internal/4123343347@10.20.0.10 destroy/unlink session from object
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 lua(app.lua voicemail)
2020-12-03 17:00:34.891350 [DEBUG] switch_core_media.c:8661 AUDIO RTP [sofia/internal/4123343347@10.20.0.10] 10.20.0.1 port 27762 -> 10.20.0.10 port 11590 codec: 9 ms: 20
2020-12-03 17:00:34.891350 [DEBUG] switch_rtp.c:4413 Starting timer [soft] 160 bytes per 20ms
2020-12-03 17:00:34.911349 [DEBUG] switch_core_media.c:8975 sofia/internal/4123343347@10.20.0.10 Set 2833 dtmf send payload to 101
2020-12-03 17:00:34.911349 [DEBUG] switch_core_media.c:8982 sofia/internal/4123343347@10.20.0.10 Set 2833 dtmf receive payload to 101
2020-12-03 17:00:34.911349 [DEBUG] switch_core_media.c:9005 sofia/internal/4123343347@10.20.0.10 Set rtp dtmf delay to 40
2020-12-03 17:00:34.911349 [DEBUG] mod_sofia.c:898 Local SDP sofia/internal/4123343347@10.20.0.10:
v=0
o=FreeSWITCH 1607001472 1607001473 IN IP4 10.20.0.1
s=FreeSWITCH
c=IN IP4 10.20.0.1
t=0 0
m=audio 27762 RTP/AVP 9 101
a=rtpmap:9 G722/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv
nua.c:879 nua_respond() nua: nua_respond: entering
nua_stack.c:529 nua_signal() nua(0x7f53cc038ba0): sent signal r_respond
nua_stack.c:573 nua_stack_signal() nua(0x7f53cc038ba0): recv signal r_respond 200 OK
nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:403 soa_set_params() soa_set_params(static::0x7f53cc02db50, ...) called
soa.c:1052 soa_set_user_sdp() soa_set_user_sdp(static::0x7f53cc02db50, (nil), 0x7f54040bc08a, -1) called
soa.c:890 soa_set_capability_sdp() soa_set_capability_sdp(static::0x7f53cc02db50, (nil), 0x7f54040bc08a, -1) called
2020-12-03 17:00:34.911349 [NOTICE] switch_cpp.cpp:685 Channel [sofia/internal/4123343347@10.20.0.10] has been answered
nua_session.c:2318 nua_invite_server_respond() nua: nua_invite_server_respond: entering
soa.c:1515 soa_generate_answer() soa_generate_answer(static::0x7f53cc02db50) called
soa_static.c:1148 offer_answer_step() soa_static_offer_answer_action(0x7f53cc02db50, soa_generate_answer): called
soa_static.c:1189 offer_answer_step() soa_static(0x7f53cc02db50, soa_generate_answer): generating local description
soa_static.c:1230 offer_answer_step() soa_static(0x7f53cc02db50, soa_generate_answer): upgrade with remote description
soa_static.c:1029 soa_sdp_mode_set() soa_sdp_mode_set(0x7f541440a890, 0x7f53cc0f0020, ""): called
soa_static.c:1446 offer_answer_step() soa_static(0x7f53cc02db50, soa_generate_answer): storing local description
soa.c:1730 soa_activate() soa_activate(static::0x7f53cc02db50, (nil)) called
soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x7f53cc02db50, [(nil)], [0x7f541440ca18], [0x7f541440ca14]) called
tport.c:3275 tport_tsend() tport_tsend(0x7f53cc004e80) tpn = UDP/10.20.0.10:5060
tport.c:4064 tport_resolve() tport_resolve addrinfo = 10.20.0.10:5060
tport.c:4698 tport_by_addrinfo() tport_by_addrinfo(0x7f53cc004e80): not found by name UDP/10.20.0.10:5060
tport.c:3612 tport_vsend() tport_vsend(0x7f53cc004e80): 1067 bytes of 1067 to udp/10.20.0.10:5060
tport.c:3510 tport_send_msg() tport_vsend returned 1067
nta.c:6802 incoming_reply() nta: sent 200 OK for INVITE (102)
nta.c:1348 set_timeout() nta: timer shortened to 500 ms
nua_session.c:4140 signal_call_state_change() nua(0x7f53cc038ba0): call state changed: received -> completed, sent answer
soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x7f53cc02db50, [0x7f541440cac8], [0x7f541440cad0], [(nil)]) called
soa.c:616 soa_get_params() soa_get_params(static::0x7f53cc02db50, ...) called
nua_stack.c:271 nua_stack_event() nua(0x7f53cc038ba0): event i_state 200 OK
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
2020-12-03 17:00:34.911349 [DEBUG] switch_channel.c:3865 (sofia/internal/4123343347@10.20.0.10) Callstate Change RINGING -> ACTIVE
tport.c:2759 tport_wakeup_pri() tport_wakeup_pri(0x7f53cc004e80): events IN
tport.c:2882 tport_recv_event() tport_recv_event(0x7f53cc004e80)
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
tport.c:3223 tport_recv_iovec() tport_recv_iovec(0x7f53cc004e80) msg 0x7f53cc0e18a0 from (udp/10.20.0.1:5060) has 416 bytes, veclen = 1
2020-12-03 17:00:34.911349 [DEBUG] sofia.c:7325 Channel sofia/internal/4123343347@10.20.0.10 entering state [completed][200]
tport.c:3041 tport_deliver() tport_deliver(0x7f53cc004e80): msg 0x7f53cc0e18a0 (416 bytes) from udp/10.20.0.10:5060/sip next=(nil)
nta.c:2885 agent_recv_request() nta: received ACK sip:5661@10.20.0.1:5060;transport=udp SIP/2.0 (CSeq 102)
nta.c:3024 agent_recv_request() nta: ACK (102) is going to INVITE (102)
nua_session.c:2567 process_ack_or_cancel() nua: process_ack_or_cancel: entering
soa.c:1214 soa_clear_remote_sdp() soa_clear_remote_sdp(static::0x7f53cc02db50) called
nua_stack.c:271 nua_stack_event() nua(0x7f53cc038ba0): event i_ack 200 OK
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua_session.c:4140 signal_call_state_change() nua(0x7f53cc038ba0): call state changed: completed -> ready
nua_stack.c:271 nua_stack_event() nua(0x7f53cc038ba0): event i_state 200 OK
nua_stack.c:271 nua_stack_event() nua(0x7f53cc038ba0): event i_active 200 Call active
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 sleep(1000)
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2020-12-03 17:00:34.911349 [DEBUG] sofia.c:7325 Channel sofia/internal/4123343347@10.20.0.10 entering state [ready][200]
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2020-12-03 17:00:34.951356 [DEBUG] switch_rtp.c:7722 Correct audio ip/port confirmed.
tport.c:2759 tport_wakeup_pri() tport_wakeup_pri(0x7f53cc004e80): events IN
tport.c:2882 tport_recv_event() tport_recv_event(0x7f53cc004e80)
tport.c:3223 tport_recv_iovec() tport_recv_iovec(0x7f53cc004e80) msg 0x7f53cc0e18a0 from (udp/10.20.0.1:5060) has 500 bytes, veclen = 1
tport.c:3041 tport_deliver() tport_deliver(0x7f53cc004e80): msg 0x7f53cc0e18a0 (500 bytes) from udp/10.20.40.17:5060/sip next=(nil)
nta.c:3304 agent_recv_response() nta: received 200 OK for BYE (28960825)
nta.c:3371 agent_recv_response() nta: 200 OK is going to a transaction
nta.c:9584 outgoing_estimate_delay() nta_outgoing: RTT is 354.085 ms
tport.c:4240 tport_release() tport_release(0x7f53cc004e80): 0x7f53cc05ecd0 by 0x7f53cc01ccc0 with 0x7f53cc0e18a0
nua_stack.c:271 nua_stack_event() nua(0x7f53f006ee70): event r_bye 200 OK
nua_session.c:4140 signal_call_state_change() nua(0x7f53f006ee70): call state changed: terminating -> terminated
nua_stack.c:271 nua_stack_event() nua(0x7f53f006ee70): event i_state 200 to BYE
nua_stack.c:271 nua_stack_event() nua(0x7f53f006ee70): event i_terminated 200 to BYE
nua_dialog.c:397 nua_dialog_usage_remove_at() nua(0x7f53f006ee70): removing session usage
soa.c:356 soa_destroy() soa_destroy(static::0x7f53cc00cbf0) called
nta.c:4475 nta_leg_destroy() nta_leg_destroy(0x7f53cc015ae0)
nua_session.c:351 nua_session_usage_destroy() nua: terminated session 0x7f53f006ee70
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
nua_stack.c:529 nua_signal() nua(0x7f53f006ee70): sent signal r_destroy
nua_stack.c:569 nua_stack_signal() nua(0x7f53f006ee70): recv signal r_destroy
nta.c:4475 nta_leg_destroy() nta_leg_destroy((nil))
nta.c:1296 agent_timer() nta: timer set next to 4502 ms
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 unbind_meta_app()
2020-12-03 17:00:35.911412 [INFO] switch_ivr_async.c:4356 UnBound A-Leg: ALL
2020-12-03 17:00:35.911412 [DEBUG] switch_cpp.cpp:755 CoreSession::setVariable('playback_terminators', '#')
2020-12-03 17:00:35.951499 [DEBUG] switch_cpp.cpp:755 CoreSession::setVariable('missed_call', 'true')
2020-12-03 17:00:35.951499 [DEBUG] switch_cpp.cpp:755 CoreSession::setVariable('voicemail_answer_stamp', '2020-12-03 17:00:35')
2020-12-03 17:00:35.951499 [DEBUG] switch_cpp.cpp:755 CoreSession::setVariable('voicemail_answer_epoch', '1607029235')
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 playback(silence_stream://200)
2020-12-03 17:00:35.951499 [DEBUG] switch_ivr_play_say.c:1488 Codec Activated L16@16000hz 1 channels 20ms
2020-12-03 17:00:36.111406 [DEBUG] switch_ivr_play_say.c:1933 done playing file silence_stream://200
2020-12-03 17:00:36.111406 [DEBUG] switch_ivr_play_say.c:1488 Codec Activated L16@16000hz 1 channels 20ms
2020-12-03 17:00:38.291414 [DEBUG] switch_ivr_play_say.c:1933 done playing file /usr/share/freeswitch/sounds/es/ar/mario/voicemail/vm-person.wav
2020-12-03 17:00:38.291414 [DEBUG] switch_ivr.c:3655 No language specified - Using [es]
2020-12-03 17:00:38.351398 [DEBUG] switch_ivr_play_say.c:1488 Codec Activated L16@16000hz 1 channels 20ms
tport.c:2759 tport_wakeup_pri() tport_wakeup_pri(0x7f53cc004e80): events IN
tport.c:2882 tport_recv_event() tport_recv_event(0x7f53cc004e80)
tport.c:3223 tport_recv_iovec() tport_recv_iovec(0x7f53cc004e80) msg 0x7f53cc06bcf0 from (udp/10.20.0.1:5060) has 446 bytes, veclen = 1
tport.c:3041 tport_deliver() tport_deliver(0x7f53cc004e80): msg 0x7f53cc06bcf0 (446 bytes) from udp/10.20.0.10:5060/sip next=(nil)
nta.c:2885 agent_recv_request() nta: received BYE sip:5661@10.20.0.1:5060;transport=udp SIP/2.0 (CSeq 103)
nta.c:3253 agent_aliases() nta: canonizing sip:5661@10.20.0.1:5060 with contact
nta.c:3065 agent_recv_request() nta: BYE (103) going to existing leg
nua_server.c:102 nua_stack_process_request() nua: nua_stack_process_request: entering
nua_stack.c:271 nua_stack_event() nua(0x7f53cc038ba0): event i_bye 100 Trying
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2020-12-03 17:00:39.011398 [NOTICE] sofia.c:1089 Hangup sofia/internal/4123343347@10.20.0.10 [CS_EXECUTE] [NORMAL_CLEARING]
2020-12-03 17:00:39.011398 [DEBUG] mod_hash.c:296 Usage for 10.20.0.1_5661 is now 0
nua.c:879 nua_respond() nua: nua_respond: entering
nua_stack.c:573 nua_stack_signal() nua(0x7f53cc038ba0): recv signal r_respond 200 OK
nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:403 soa_set_params() soa_set_params(static::0x7f53cc02db50, ...) called
tport.c:3275 tport_tsend() tport_tsend(0x7f53cc004e80) tpn = UDP/10.20.0.10:5060
nua_stack.c:529 nua_signal() nua(0x7f53cc038ba0): sent signal r_respond
tport.c:4064 tport_resolve() tport_resolve addrinfo = 10.20.0.10:5060
tport.c:4698 tport_by_addrinfo() tport_by_addrinfo(0x7f53cc004e80): not found by name UDP/10.20.0.10:5060
nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering
nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
nua_stack.c:529 nua_signal() nua(0x7f53cc038ba0): sent signal r_destroy
2020-12-03 17:00:39.011398 [DEBUG] switch_ivr_play_say.c:1933 done playing file /usr/share/freeswitch/sounds/es/ar/mario/digits/5.wav
tport.c:3612 tport_vsend() tport_vsend(0x7f53cc004e80): 459 bytes of 459 to udp/10.20.0.10:5060
tport.c:3510 tport_send_msg() tport_vsend returned 459
nta.c:6802 incoming_reply() nta: sent 200 OK for BYE (103)
nua_dialog.c:397 nua_dialog_usage_remove_at() nua(0x7f53cc038ba0): removing session usage
nua_session.c:4140 signal_call_state_change() nua(0x7f53cc038ba0): call state changed: ready -> terminated
nua_stack.c:271 nua_stack_event() nua(0x7f53cc038ba0): event i_state 200 Session Terminated
nua_stack.c:271 nua_stack_event() nua(0x7f53cc038ba0): event i_terminated 200 Session Terminated
soa.c:356 soa_destroy() soa_destroy(static::0x7f53cc02db50) called
nta.c:4475 nta_leg_destroy() nta_leg_destroy(0x7f53cc025cd0)
nua_stack.c:569 nua_stack_signal() nua(0x7f53cc038ba0): recv signal r_destroy
nta.c:4475 nta_leg_destroy() nta_leg_destroy((nil))
2020-12-03 17:00:39.051402 [NOTICE] switch_cpp.cpp:1447 [voicemail]
2020-12-03 17:00:39.071550 [DEBUG] switch_cpp.cpp:1191 sofia/internal/4123343347@10.20.0.10 destroy/unlink session from object
2020-12-03 17:00:39.071550 [DEBUG] switch_core_session.c:2905 sofia/internal/4123343347@10.20.0.10 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
2020-12-03 17:00:39.071550 [DEBUG] switch_core_state_machine.c:651 (sofia/internal/4123343347@10.20.0.10) State EXECUTE going to sleep
2020-12-03 17:00:39.071550 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/4123343347@10.20.0.10) Running State Change CS_HANGUP (Cur 1 Tot 90)
2020-12-03 17:00:39.071550 [DEBUG] switch_core_state_machine.c:848 (sofia/internal/4123343347@10.20.0.10) Callstate Change ACTIVE -> HANGUP
2020-12-03 17:00:39.071550 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/4123343347@10.20.0.10) State HANGUP
2020-12-03 17:00:39.071550 [DEBUG] mod_sofia.c:453 Channel sofia/internal/4123343347@10.20.0.10 hanging up, cause: NORMAL_CLEARING
2020-12-03 17:00:39.071550 [DEBUG] switch_core_state_machine.c:60 sofia/internal/4123343347@10.20.0.10 Standard HANGUP, cause: NORMAL_CLEARING
2020-12-03 17:00:39.071550 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/4123343347@10.20.0.10) State HANGUP going to sleep
2020-12-03 17:00:39.091397 [DEBUG] switch_core_state_machine.c:781 Hangup Command with no Session lua(app.lua hangup):
2020-12-03 17:00:39.091397 [DEBUG] switch_core_state_machine.c:620 (sofia/internal/4123343347@10.20.0.10) State Change CS_HANGUP -> CS_REPORTING
2020-12-03 17:00:39.091397 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/4123343347@10.20.0.10) Running State Change CS_REPORTING (Cur 1 Tot 90)
2020-12-03 17:00:39.091397 [DEBUG] switch_core_state_machine.c:936 (sofia/internal/4123343347@10.20.0.10) State REPORTING
2020-12-03 17:00:39.211409 [DEBUG] switch_core_state_machine.c:174 sofia/internal/4123343347@10.20.0.10 Standard REPORTING, cause: NORMAL_CLEARING
2020-12-03 17:00:39.211409 [DEBUG] switch_core_state_machine.c:936 (sofia/internal/4123343347@10.20.0.10) State REPORTING going to sleep
2020-12-03 17:00:39.211409 [DEBUG] switch_core_state_machine.c:611 (sofia/internal/4123343347@10.20.0.10) State Change CS_REPORTING -> CS_DESTROY
2020-12-03 17:00:39.211409 [DEBUG] switch_core_session.c:1726 Session 89 (sofia/internal/4123343347@10.20.0.10) Locked, Waiting on external entities
2020-12-03 17:00:39.211409 [NOTICE] switch_core_session.c:1744 Session 89 (sofia/internal/4123343347@10.20.0.10) Ended
2020-12-03 17:00:39.211409 [NOTICE] switch_core_session.c:1748 Close Channel sofia/internal/4123343347@10.20.0.10 [CS_DESTROY]
2020-12-03 17:00:39.211409 [DEBUG] switch_core_state_machine.c:739 (sofia/internal/4123343347@10.20.0.10) Running State Change CS_DESTROY (Cur 0 Tot 90)
2020-12-03 17:00:39.211409 [DEBUG] switch_core_state_machine.c:749 (sofia/internal/4123343347@10.20.0.10) State DESTROY
2020-12-03 17:00:39.211409 [DEBUG] mod_sofia.c:364 sofia/internal/4123343347@10.20.0.10 SOFIA DESTROY
2020-12-03 17:00:39.211409 [DEBUG] switch_core_state_machine.c:181 sofia/internal/4123343347@10.20.0.10 Standard DESTROY
2020-12-03 17:00:39.211409 [DEBUG] switch_core_state_machine.c:749 (sofia/internal/4123343347@10.20.0.10) State DESTROY going to sleep
nta.c:7145 _nta_incoming_timer() nta: timer I fired, terminate 200 response
nta.c:5830 incoming_reclaim_queued() incoming_reclaim_all((nil), (nil), 0x7f541440ca50)
nta.c:7199 _nta_incoming_timer() nta_incoming_timer: 0/0 resent, 0/0 tout, 1/12 term, 1/12 free
nta.c:1296 agent_timer() nta: timer set next to 294 ms
nta.c:9121 outgoing_timer_dk() nta: timer K fired, terminate BYE (28960825)
nta.c:8810 outgoing_reclaim_queued() outgoing_reclaim_all((nil), (nil), 0x7f541440cb20)
nta.c:8940 _nta_outgoing_timer() nta_outgoing_timer: 0/0 resent, 0/1 tout, 1/2 term, 1/3 free
nta.c:1296 agent_timer() nta: timer set next to 19471 ms
2020-12-03 17:00:32.011432 [NOTICE] switch_channel.c:1118 New Channel sofia/internal/4123343347@10.20.0.10 [96139f7c-c058-4cdf-be92-165038b078e1]
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
2020-12-03 17:00:32.011432 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/4123343347@10.20.0.10) Running State Change CS_NEW (Cur 1 Tot 89)
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2020-12-03 17:00:32.011432 [DEBUG] sofia.c:10279 sofia/internal/4123343347@10.20.0.10 receiving invite from 10.20.0.10:5060 version: 1.10.3 -release-15-129de34d84 64bit
2020-12-03 17:00:32.011432 [DEBUG] sofia.c:10373 verifying acl "domains" for ip/port 10.20.0.10:0.
2020-12-03 17:00:32.011432 [DEBUG] sofia.c:10402 IP 10.20.0.10 Approved by acl "domains[]". Access Granted.
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2020-12-03 17:00:32.011432 [DEBUG] sofia.c:7325 Channel sofia/internal/4123343347@10.20.0.10 entering state [received][100]
2020-12-03 17:00:32.011432 [DEBUG] sofia.c:7335 Remote SDP:
v=0
o=root 1762744854 1762744854 IN IP4 10.20.0.10
s=Asterisk PBX 11.25.3
c=IN IP4 10.20.0.10
t=0 0
m=audio 11590 RTP/AVP 8 0 3 4 112 5 7 18 110 97 111 9 102 115 116 117 96 108 109 113 10 118 119 107 101
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:3 GSM/8000
a=rtpmap:4 G723/8000
a=fmtp:4 annexa=no
a=rtpmap:112 AAL2-G726-32/8000
a=rtpmap:5 DVI4/8000
a=rtpmap:7 LPC/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:110 speex/8000
a=rtpmap:97 iLBC/8000
a=rtpmap:111 G726-32/8000
a=rtpmap:9 G722/8000
a=rtpmap:102 G7221/16000
a=fmtp:102 bitrate=32000
a=rtpmap:115 G7221/32000
a=fmtp:115 bitrate=48000
a=rtpmap:116 G719/48000
a=fmtp:116 bitrate=64000
a=rtpmap:117 speex/16000
a=rtpmap:96 SILK/8000
a=fmtp:96 useinbandfec=1
a=rtpmap:108 SILK/12000
a=fmtp:108 useinbandfec=1
a=rtpmap:109 SILK/16000
a=fmtp:109 useinbandfec=1
a=rtpmap:113 SILK/24000
a=fmtp:113 useinbandfec=1
a=rtpmap:10 L16/8000
a=rtpmap:118 L16/16000
a=rtpmap:119 speex/32000
a=rtpmap:107 opus/48000/2
a=fmtp:107 maxplaybackrate=16000; stereo=0; sprop-stereo=0; useinbandfec=0
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=maxptime:60
a=ptime:20
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5647 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5647 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [GSM:3:8000:20:13200:1]/[G722:9:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [GSM:3:8000:20:13200:1]/[PCMU:0:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [GSM:3:8000:20:13200:1]/[PCMA:8:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [G723:4:8000:20:6300:1]/[G722:9:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [G723:4:8000:20:6300:1]/[PCMU:0:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [G723:4:8000:20:6300:1]/[PCMA:8:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [AAL2-G726-32:112:8000:20:0:1]/[G722:9:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [AAL2-G726-32:112:8000:20:0:1]/[PCMU:0:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [AAL2-G726-32:112:8000:20:0:1]/[PCMA:8:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [DVI4:5:8000:20:0:1]/[G722:9:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [DVI4:5:8000:20:0:1]/[PCMU:0:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [DVI4:5:8000:20:0:1]/[PCMA:8:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [LPC:7:8000:20:2400:1]/[G722:9:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [LPC:7:8000:20:2400:1]/[PCMU:0:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [LPC:7:8000:20:2400:1]/[PCMA:8:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [G729:18:8000:20:8000:1]/[G722:9:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMU:0:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMA:8:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [speex:110:8000:20:0:1]/[G722:9:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [speex:110:8000:20:0:1]/[PCMU:0:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [speex:110:8000:20:0:1]/[PCMA:8:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [iLBC:97:8000:30:13330:1]/[G722:9:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [iLBC:97:8000:30:13330:1]/[PCMU:0:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [iLBC:97:8000:30:13330:1]/[PCMA:8:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [G726-32:111:8000:20:0:1]/[G722:9:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [G726-32:111:8000:20:0:1]/[PCMU:0:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [G726-32:111:8000:20:0:1]/[PCMA:8:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [G722:9:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5647 Audio Codec Compare [G722:9:8000:20:64000:1] ++++ is saved as a match
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [G7221:102:16000:20:0:1]/[G722:9:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [G7221:102:16000:20:0:1]/[PCMU:0:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [G7221:102:16000:20:0:1]/[PCMA:8:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [G7221:115:32000:20:0:1]/[G722:9:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [G7221:115:32000:20:0:1]/[PCMU:0:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [G7221:115:32000:20:0:1]/[PCMA:8:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [G719:116:48000:20:0:1]/[G722:9:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [G719:116:48000:20:0:1]/[PCMU:0:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [G719:116:48000:20:0:1]/[PCMA:8:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [speex:117:16000:20:0:1]/[G722:9:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [speex:117:16000:20:0:1]/[PCMU:0:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [speex:117:16000:20:0:1]/[PCMA:8:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [SILK:96:8000:20:0:1]/[G722:9:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [SILK:96:8000:20:0:1]/[PCMU:0:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [SILK:96:8000:20:0:1]/[PCMA:8:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [SILK:108:12000:20:0:1]/[G722:9:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [SILK:108:12000:20:0:1]/[PCMU:0:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [SILK:108:12000:20:0:1]/[PCMA:8:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [SILK:109:16000:20:0:1]/[G722:9:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [SILK:109:16000:20:0:1]/[PCMU:0:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [SILK:109:16000:20:0:1]/[PCMA:8:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [SILK:113:24000:20:0:1]/[G722:9:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [SILK:113:24000:20:0:1]/[PCMU:0:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [SILK:113:24000:20:0:1]/[PCMA:8:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [L16:10:8000:20:0:1]/[G722:9:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [L16:10:8000:20:0:1]/[PCMU:0:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [L16:10:8000:20:0:1]/[PCMA:8:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [L16:118:16000:20:0:1]/[G722:9:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [L16:118:16000:20:0:1]/[PCMU:0:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [L16:118:16000:20:0:1]/[PCMA:8:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [speex:119:32000:20:0:1]/[G722:9:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [speex:119:32000:20:0:1]/[PCMU:0:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [speex:119:32000:20:0:1]/[PCMA:8:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [opus:107:48000:20:0:2]/[G722:9:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [opus:107:48000:20:0:2]/[PCMU:0:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [opus:107:48000:20:0:2]/[PCMA:8:8000:20:64000:1]
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5508 Set telephone-event payload to 101@8000
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:3837 Set Codec sofia/internal/4123343347@10.20.0.10 G722/8000 20 ms 160 samples 64000 bits 1 channels
2020-12-03 17:00:32.011432 [DEBUG] switch_core_codec.c:111 sofia/internal/4123343347@10.20.0.10 Original read codec set to G722:9
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5851 Set telephone-event payload to 101@8000
2020-12-03 17:00:32.011432 [DEBUG] switch_core_media.c:5909 sofia/internal/4123343347@10.20.0.10 Set 2833 dtmf send payload to 101 recv payload to 101
2020-12-03 17:00:32.011432 [DEBUG] sofia.c:7759 (sofia/internal/4123343347@10.20.0.10) State Change CS_NEW -> CS_INIT
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2020-12-03 17:00:32.011432 [DEBUG] switch_core_state_machine.c:604 (sofia/internal/4123343347@10.20.0.10) State NEW
2020-12-03 17:00:32.011432 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/4123343347@10.20.0.10) Running State Change CS_INIT (Cur 1 Tot 89)
2020-12-03 17:00:32.011432 [DEBUG] switch_core_state_machine.c:628 (sofia/internal/4123343347@10.20.0.10) State INIT
2020-12-03 17:00:32.011432 [DEBUG] mod_sofia.c:93 sofia/internal/4123343347@10.20.0.10 SOFIA INIT
2020-12-03 17:00:32.011432 [DEBUG] switch_core_state_machine.c:40 sofia/internal/4123343347@10.20.0.10 Standard INIT
2020-12-03 17:00:32.011432 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/4123343347@10.20.0.10) State Change CS_INIT -> CS_ROUTING
2020-12-03 17:00:32.011432 [DEBUG] switch_core_state_machine.c:628 (sofia/internal/4123343347@10.20.0.10) State INIT going to sleep
2020-12-03 17:00:32.011432 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/4123343347@10.20.0.10) Running State Change CS_ROUTING (Cur 1 Tot 89)
2020-12-03 17:00:32.011432 [DEBUG] switch_channel.c:2332 (sofia/internal/4123343347@10.20.0.10) Callstate Change DOWN -> RINGING
2020-12-03 17:00:32.011432 [DEBUG] switch_core_state_machine.c:644 (sofia/internal/4123343347@10.20.0.10) State ROUTING
nua.c:879 nua_respond() nua: nua_respond: entering
nua_stack.c:573 nua_stack_signal() nua(0x7f53cc038ba0): recv signal r_respond 100 Trying
nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:403 soa_set_params() soa_set_params(static::0x7f53cc02db50, ...) called
tport.c:3275 tport_tsend() tport_tsend(0x7f53cc004e80) tpn = UDP/10.20.0.10:5060
tport.c:4064 tport_resolve() tport_resolve addrinfo = 10.20.0.10:5060
tport.c:4698 tport_by_addrinfo() tport_by_addrinfo(0x7f53cc004e80): not found by name UDP/10.20.0.10:5060
nua_stack.c:529 nua_signal() nua(0x7f53cc038ba0): sent signal r_respond
2020-12-03 17:00:32.011432 [DEBUG] mod_sofia.c:154 sofia/internal/4123343347@10.20.0.10 SOFIA ROUTING
2020-12-03 17:00:32.011432 [DEBUG] switch_core_state_machine.c:236 sofia/internal/4123343347@10.20.0.10 Standard ROUTING
2020-12-03 17:00:32.011432 [INFO] mod_dialplan_xml.c:637 Processing 4123343347 <4123343347>->5661 in context public
tport.c:3612 tport_vsend() tport_vsend(0x7f53cc004e80): 304 bytes of 304 to udp/10.20.0.10:5060
tport.c:3510 tport_send_msg() tport_vsend returned 304
nta.c:6802 incoming_reply() nta: sent 100 Trying for INVITE (102)
Dialplan: sofia/internal/4123343347@10.20.0.10 parsing [public->caller-details] continue=true
Dialplan: sofia/internal/4123343347@10.20.0.10 Regex (PASS) [caller-details] () =~ // break=never
Dialplan: sofia/internal/4123343347@10.20.0.10 Action export(call_direction=inbound) INLINE
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 export(call_direction=inbound)
2020-12-03 17:00:32.031369 [DEBUG] switch_channel.c:1310 EXPORT (export_vars) [call_direction]=[inbound]
Dialplan: sofia/internal/4123343347@10.20.0.10 Action set(caller_destination=${sip_to_user}) INLINE
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 set(caller_destination=5661)
2020-12-03 17:00:32.031369 [DEBUG] mod_dptools.c:1672 SET sofia/internal/4123343347@10.20.0.10 [caller_destination]=[5661]
Dialplan: sofia/internal/4123343347@10.20.0.10 Action set(caller_id_name=${caller_id_name}) INLINE
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 set(caller_id_name=4123343347)
2020-12-03 17:00:32.031369 [DEBUG] mod_dptools.c:1672 SET sofia/internal/4123343347@10.20.0.10 [caller_id_name]=[4123343347]
Dialplan: sofia/internal/4123343347@10.20.0.10 Action set(caller_id_number=${caller_id_number})
Dialplan: sofia/internal/4123343347@10.20.0.10 parsing [public->5xxx] continue=true
Dialplan: sofia/internal/4123343347@10.20.0.10 Regex (PASS) [5xxx] destination_number(5661) =~ /^(5[4-7][0-9][0-9])$/ break=on-false
Dialplan: sofia/internal/4123343347@10.20.0.10 Action export(call_direction=inbound) INLINE
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 export(call_direction=inbound)
2020-12-03 17:00:32.031369 [DEBUG] switch_channel.c:1310 EXPORT (export_vars) [call_direction]=[inbound]
Dialplan: sofia/internal/4123343347@10.20.0.10 Action set(domain_uuid=c64bd80d-c20f-4bc8-b43c-41c7e9c405c5) INLINE
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 set(domain_uuid=c64bd80d-c20f-4bc8-b43c-41c7e9c405c5)
2020-12-03 17:00:32.031369 [DEBUG] mod_dptools.c:1672 SET sofia/internal/4123343347@10.20.0.10 [domain_uuid]=[c64bd80d-c20f-4bc8-b43c-41c7e9c405c5]
Dialplan: sofia/internal/4123343347@10.20.0.10 Action set(domain_name=10.20.0.1) INLINE
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 set(domain_name=10.20.0.1)
2020-12-03 17:00:32.031369 [DEBUG] mod_dptools.c:1672 SET sofia/internal/4123343347@10.20.0.10 [domain_name]=[10.20.0.1]
Dialplan: sofia/internal/4123343347@10.20.0.10 Action transfer(5661 XML default)
Dialplan: sofia/internal/4123343347@10.20.0.10 parsing [public->not-found] continue=false
Dialplan: sofia/internal/4123343347@10.20.0.10 Regex (PASS) [not-found] () =~ // break=on-false
Dialplan: sofia/internal/4123343347@10.20.0.10 Action export(call_direction=inbound) INLINE
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 export(call_direction=inbound)
2020-12-03 17:00:32.031369 [DEBUG] switch_channel.c:1310 EXPORT (export_vars) [call_direction]=[inbound]
Dialplan: sofia/internal/4123343347@10.20.0.10 Action set(call_direction=inbound) INLINE
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 set(call_direction=inbound)
2020-12-03 17:00:32.031369 [DEBUG] mod_dptools.c:1672 SET sofia/internal/4123343347@10.20.0.10 [call_direction]=[inbound]
Dialplan: sofia/internal/4123343347@10.20.0.10 Action log(WARNING [inbound routes] 404 not found ${sip_network_ip})
2020-12-03 17:00:32.031369 [DEBUG] switch_core_state_machine.c:287 (sofia/internal/4123343347@10.20.0.10) State Change CS_ROUTING -> CS_EXECUTE
2020-12-03 17:00:32.031369 [DEBUG] switch_core_state_machine.c:644 (sofia/internal/4123343347@10.20.0.10) State ROUTING going to sleep
2020-12-03 17:00:32.031369 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/4123343347@10.20.0.10) Running State Change CS_EXECUTE (Cur 1 Tot 89)
2020-12-03 17:00:32.031369 [DEBUG] switch_core_state_machine.c:651 (sofia/internal/4123343347@10.20.0.10) State EXECUTE
2020-12-03 17:00:32.031369 [DEBUG] mod_sofia.c:209 sofia/internal/4123343347@10.20.0.10 SOFIA EXECUTE
2020-12-03 17:00:32.031369 [DEBUG] switch_core_state_machine.c:329 sofia/internal/4123343347@10.20.0.10 Standard EXECUTE
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 set(caller_id_number=4123343347)
2020-12-03 17:00:32.031369 [DEBUG] mod_dptools.c:1672 SET sofia/internal/4123343347@10.20.0.10 [caller_id_number]=[4123343347]
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 transfer(5661 XML default)
2020-12-03 17:00:32.031369 [DEBUG] switch_ivr.c:2243 (sofia/internal/4123343347@10.20.0.10) State Change CS_EXECUTE -> CS_ROUTING
2020-12-03 17:00:32.031369 [NOTICE] switch_ivr.c:2250 Transfer sofia/internal/4123343347@10.20.0.10 to XML[5661@default]
2020-12-03 17:00:32.031369 [DEBUG] switch_core_state_machine.c:651 (sofia/internal/4123343347@10.20.0.10) State EXECUTE going to sleep
2020-12-03 17:00:32.031369 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/4123343347@10.20.0.10) Running State Change CS_ROUTING (Cur 1 Tot 89)
2020-12-03 17:00:32.031369 [DEBUG] switch_core_state_machine.c:644 (sofia/internal/4123343347@10.20.0.10) State ROUTING
2020-12-03 17:00:32.031369 [DEBUG] mod_sofia.c:145 Call appears to be already acknowledged
2020-12-03 17:00:32.031369 [DEBUG] mod_sofia.c:154 sofia/internal/4123343347@10.20.0.10 SOFIA ROUTING
2020-12-03 17:00:32.031369 [DEBUG] switch_core_state_machine.c:236 sofia/internal/4123343347@10.20.0.10 Standard ROUTING
2020-12-03 17:00:32.031369 [INFO] mod_dialplan_xml.c:637 Processing 4123343347 <4123343347>->5661 in context default
Dialplan: sofia/internal/4123343347@10.20.0.10 parsing [default->user_exists] continue=true
Dialplan: sofia/internal/4123343347@10.20.0.10 Regex (FAIL) [user_exists] ${loopback_leg}() =~ /^B$/ break=never
Dialplan: sofia/internal/4123343347@10.20.0.10 Regex (PASS) [user_exists] () =~ // break=on-false
Dialplan: sofia/internal/4123343347@10.20.0.10 Action set(user_exists=${user_exists id ${destination_number} ${domain_name}}) INLINE
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 set(user_exists=true)
2020-12-03 17:00:32.051345 [DEBUG] mod_dptools.c:1672 SET sofia/internal/4123343347@10.20.0.10 [user_exists]=[true]
Dialplan: sofia/internal/4123343347@10.20.0.10 Action set(from_user_exists=${user_exists id ${sip_from_user} ${sip_from_host}}) INLINE
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 set(from_user_exists=false)
2020-12-03 17:00:32.071352 [DEBUG] mod_dptools.c:1672 SET sofia/internal/4123343347@10.20.0.10 [from_user_exists]=[false]
Dialplan: sofia/internal/4123343347@10.20.0.10 Regex (PASS) [user_exists] ${user_exists}(true) =~ /^true$/ break=on-false
Dialplan: sofia/internal/4123343347@10.20.0.10 Action set(extension_uuid=${user_data ${destination_number}@${domain_name} var extension_uuid}) INLINE
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 set(extension_uuid=b2c8add0-8d18-4f50-ac20-67a36d1e7bd4)
2020-12-03 17:00:32.071352 [DEBUG] mod_dptools.c:1672 SET sofia/internal/4123343347@10.20.0.10 [extension_uuid]=[b2c8add0-8d18-4f50-ac20-67a36d1e7bd4]
Dialplan: sofia/internal/4123343347@10.20.0.10 Action set(hold_music=${user_data ${destination_number}@${domain_name} var hold_music}) INLINE
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 set(hold_music=)
2020-12-03 17:00:32.091346 [DEBUG] mod_dptools.c:1672 SET sofia/internal/4123343347@10.20.0.10 [hold_music]=[UNDEF]
Dialplan: sofia/internal/4123343347@10.20.0.10 Action set(forward_all_enabled=${user_data ${destination_number}@${domain_name} var forward_all_enabled}) INLINE
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 set(forward_all_enabled=)
2020-12-03 17:00:32.091346 [DEBUG] mod_dptools.c:1672 SET sofia/internal/4123343347@10.20.0.10 [forward_all_enabled]=[UNDEF]
Dialplan: sofia/internal/4123343347@10.20.0.10 Action set(forward_all_destination=${user_data ${destination_number}@${domain_name} var forward_all_destination}) INLINE
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 set(forward_all_destination=)
2020-12-03 17:00:32.111394 [DEBUG] mod_dptools.c:1672 SET sofia/internal/4123343347@10.20.0.10 [forward_all_destination]=[UNDEF]
Dialplan: sofia/internal/4123343347@10.20.0.10 Action set(forward_busy_enabled=${user_data ${destination_number}@${domain_name} var forward_busy_enabled}) INLINE
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 set(forward_busy_enabled=)
2020-12-03 17:00:32.111394 [DEBUG] mod_dptools.c:1672 SET sofia/internal/4123343347@10.20.0.10 [forward_busy_enabled]=[UNDEF]
Dialplan: sofia/internal/4123343347@10.20.0.10 Action set(forward_busy_destination=${user_data ${destination_number}@${domain_name} var forward_busy_destination}) INLINE
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 set(forward_busy_destination=)
2020-12-03 17:00:32.111394 [DEBUG] mod_dptools.c:1672 SET sofia/internal/4123343347@10.20.0.10 [forward_busy_destination]=[UNDEF]
Dialplan: sofia/internal/4123343347@10.20.0.10 Action set(forward_no_answer_enabled=${user_data ${destination_number}@${domain_name} var forward_no_answer_enabled}) INLINE
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 set(forward_no_answer_enabled=)
2020-12-03 17:00:32.131351 [DEBUG] mod_dptools.c:1672 SET sofia/internal/4123343347@10.20.0.10 [forward_no_answer_enabled]=[UNDEF]
Dialplan: sofia/internal/4123343347@10.20.0.10 Action set(forward_no_answer_destination=${user_data ${destination_number}@${domain_name} var forward_no_answer_destination}) INLINE
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 set(forward_no_answer_destination=)
2020-12-03 17:00:32.131351 [DEBUG] mod_dptools.c:1672 SET sofia/internal/4123343347@10.20.0.10 [forward_no_answer_destination]=[UNDEF]
Dialplan: sofia/internal/4123343347@10.20.0.10 Action set(forward_user_not_registered_enabled=${user_data ${destination_number}@${domain_name} var forward_user_not_registered_enabled}) INLINE
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 set(forward_user_not_registered_enabled=)
2020-12-03 17:00:32.131351 [DEBUG] mod_dptools.c:1672 SET sofia/internal/4123343347@10.20.0.10 [forward_user_not_registered_enabled]=[UNDEF]
Dialplan: sofia/internal/4123343347@10.20.0.10 Action set(forward_user_not_registered_destination=${user_data ${destination_number}@${domain_name} var forward_user_not_registered_destination}) INLINE
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 set(forward_user_not_registered_destination=)
2020-12-03 17:00:32.151351 [DEBUG] mod_dptools.c:1672 SET sofia/internal/4123343347@10.20.0.10 [forward_user_not_registered_destination]=[UNDEF]
Dialplan: sofia/internal/4123343347@10.20.0.10 Action set(forward_all_enabled=${user_data ${destination_number}@${domain_name} var forward_all_enabled}) INLINE
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 set(forward_all_enabled=)
2020-12-03 17:00:32.151351 [DEBUG] mod_dptools.c:1672 SET sofia/internal/4123343347@10.20.0.10 [forward_all_enabled]=[UNDEF]
Dialplan: sofia/internal/4123343347@10.20.0.10 Action set(follow_me_enabled=${user_data ${destination_number}@${domain_name} var follow_me_enabled}) INLINE
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 set(follow_me_enabled=)
2020-12-03 17:00:32.151351 [DEBUG] mod_dptools.c:1672 SET sofia/internal/4123343347@10.20.0.10 [follow_me_enabled]=[UNDEF]
Dialplan: sofia/internal/4123343347@10.20.0.10 Action set(do_not_disturb=${user_data ${destination_number}@${domain_name} var do_not_disturb}) INLINE
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 set(do_not_disturb=)
2020-12-03 17:00:32.171394 [DEBUG] mod_dptools.c:1672 SET sofia/internal/4123343347@10.20.0.10 [do_not_disturb]=[UNDEF]
Dialplan: sofia/internal/4123343347@10.20.0.10 Action set(call_timeout=${user_data ${destination_number}@${domain_name} var call_timeout}) INLINE
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 set(call_timeout=30)
2020-12-03 17:00:32.171394 [DEBUG] mod_dptools.c:1672 SET sofia/internal/4123343347@10.20.0.10 [call_timeout]=[30]
Dialplan: sofia/internal/4123343347@10.20.0.10 Action set(missed_call_app=${user_data ${destination_number}@${domain_name} var missed_call_app}) INLINE
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 set(missed_call_app=)
2020-12-03 17:00:32.171394 [DEBUG] mod_dptools.c:1672 SET sofia/internal/4123343347@10.20.0.10 [missed_call_app]=[UNDEF]
Dialplan: sofia/internal/4123343347@10.20.0.10 Action set(missed_call_data=${user_data ${destination_number}@${domain_name} var missed_call_data}) INLINE
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 set(missed_call_data=)
2020-12-03 17:00:32.191396 [DEBUG] mod_dptools.c:1672 SET sofia/internal/4123343347@10.20.0.10 [missed_call_data]=[UNDEF]
Dialplan: sofia/internal/4123343347@10.20.0.10 Action set(toll_allow=${user_data ${destination_number}@${domain_name} var toll_allow}) INLINE
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 set(toll_allow=)
2020-12-03 17:00:32.191396 [DEBUG] mod_dptools.c:1672 SET sofia/internal/4123343347@10.20.0.10 [toll_allow]=[UNDEF]
Dialplan: sofia/internal/4123343347@10.20.0.10 Action set(call_screen_enabled=${user_data ${destination_number}@${domain_name} var call_screen_enabled}) INLINE
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 set(call_screen_enabled=false)
2020-12-03 17:00:32.191396 [DEBUG] mod_dptools.c:1672 SET sofia/internal/4123343347@10.20.0.10 [call_screen_enabled]=[false]
Dialplan: sofia/internal/4123343347@10.20.0.10 Action set(user_record=${user_data ${destination_number}@${domain_name} var user_record}) INLINE
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 set(user_record=)
2020-12-03 17:00:32.211318 [DEBUG] mod_dptools.c:1672 SET sofia/internal/4123343347@10.20.0.10 [user_record]=[UNDEF]
Dialplan: sofia/internal/4123343347@10.20.0.10 parsing [default->global-variables] continue=true
Dialplan: sofia/internal/4123343347@10.20.0.10 Regex (PASS) [global-variables] () =~ // break=on-false
Dialplan: sofia/internal/4123343347@10.20.0.10 Action set(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
Dialplan: sofia/internal/4123343347@10.20.0.10 parsing [default->is_loopback] continue=true
Dialplan: sofia/internal/4123343347@10.20.0.10 Regex (FAIL) [is_loopback] ${is_follow_me_loopback}() =~ /true/ break=on-false
Dialplan: sofia/internal/4123343347@10.20.0.10 parsing [default->intercept-ext-polycom] continue=false
Dialplan: sofia/internal/4123343347@10.20.0.10 Regex (FAIL) [intercept-ext-polycom] destination_number(5661) =~ /^\*97(\d+)$/ break=on-false
Dialplan: sofia/internal/4123343347@10.20.0.10 parsing [default->extension-to-voicemail] continue=false
Dialplan: sofia/internal/4123343347@10.20.0.10 Regex (PASS) [extension-to-voicemail] ${user_exists}(true) =~ /^true$/ break=on-false
Dialplan: sofia/internal/4123343347@10.20.0.10 Regex (PASS) [extension-to-voicemail] username(4123343347) =~ /^4123343347$/ break=on-false
Dialplan: sofia/internal/4123343347@10.20.0.10 Regex (FAIL) [extension-to-voicemail] destination_number(5661) =~ /^4123343347$/ break=on-false
Dialplan: sofia/internal/4123343347@10.20.0.10 parsing [default->follow-me-destinations] continue=false
Dialplan: sofia/internal/4123343347@10.20.0.10 Regex (PASS) [follow-me-destinations] ${user_exists}(true) =~ /^true$/ break=on-false
Dialplan: sofia/internal/4123343347@10.20.0.10 Regex (FAIL) [follow-me-destinations] ${follow_me_enabled}() =~ /^true$/ break=on-false
Dialplan: sofia/internal/4123343347@10.20.0.10 parsing [default->call-forward-all] continue=
Dialplan: sofia/internal/4123343347@10.20.0.10 Regex (PASS) [call-forward-all] ${user_exists}(true) =~ /true/ break=on-false
Dialplan: sofia/internal/4123343347@10.20.0.10 Regex (FAIL) [call-forward-all] ${forward_all_enabled}() =~ /true/ break=on-false
Dialplan: sofia/internal/4123343347@10.20.0.10 parsing [default->call-forward-not-registered] continue=
Dialplan: sofia/internal/4123343347@10.20.0.10 Regex (PASS) [call-forward-not-registered] ${user_exists}(true) =~ /true/ break=on-false
Dialplan: sofia/internal/4123343347@10.20.0.10 Regex (FAIL) [call-forward-not-registered] ${forward_user_not_registered_enabled}() =~ /true/ break=on-false
Dialplan: sofia/internal/4123343347@10.20.0.10 parsing [default->talking clock date and time] continue=
Dialplan: sofia/internal/4123343347@10.20.0.10 Regex (FAIL) [talking clock date and time] destination_number(5661) =~ /^\*9172$/ break=on-false
Dialplan: sofia/internal/4123343347@10.20.0.10 parsing [default->talking clock time] continue=
Dialplan: sofia/internal/4123343347@10.20.0.10 Regex (FAIL) [talking clock time] destination_number(5661) =~ /^\*9170$/ break=on-false
Dialplan: sofia/internal/4123343347@10.20.0.10 parsing [default->talking clock date] continue=
Dialplan: sofia/internal/4123343347@10.20.0.10 Regex (FAIL) [talking clock date] destination_number(5661) =~ /^\*9171$/ break=on-false
Dialplan: sofia/internal/4123343347@10.20.0.10 parsing [default->local_extension] continue=true
Dialplan: sofia/internal/4123343347@10.20.0.10 Regex (PASS) [local_extension] ${user_exists}(true) =~ /true/ break=on-false
Dialplan: sofia/internal/4123343347@10.20.0.10 Action export(dialed_extension=${destination_number}) INLINE
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 export(dialed_extension=5661)
2020-12-03 17:00:32.211318 [DEBUG] switch_channel.c:1310 EXPORT (export_vars) [dialed_extension]=[5661]
Dialplan: sofia/internal/4123343347@10.20.0.10 Action limit(hash ${domain_name} ${destination_number} ${limit_max} ${limit_destination})
Dialplan: sofia/internal/4123343347@10.20.0.10 Regex (PASS) [local_extension] () =~ // break=on-false
Dialplan: sofia/internal/4123343347@10.20.0.10 Action set(hangup_after_bridge=true)
Dialplan: sofia/internal/4123343347@10.20.0.10 Action set(continue_on_fail=true)
Dialplan: sofia/internal/4123343347@10.20.0.10 Action hash(insert/${domain_name}-call_return/${dialed_extension}/${caller_id_number})
Dialplan: sofia/internal/4123343347@10.20.0.10 Action hash(insert/${domain_name}-last_dial_ext/${dialed_extension}/${uuid})
Dialplan: sofia/internal/4123343347@10.20.0.10 Action set(called_party_call_group=${user_data(${dialed_extension}@${domain_name} var call_group)})
Dialplan: sofia/internal/4123343347@10.20.0.10 Action hash(insert/${domain_name}-last_dial/${called_party_call_group}/${uuid})
Dialplan: sofia/internal/4123343347@10.20.0.10 Action set(api_hangup_hook=lua app.lua hangup)
Dialplan: sofia/internal/4123343347@10.20.0.10 Action export(domain_name=${domain_name})
Dialplan: sofia/internal/4123343347@10.20.0.10 Action bridge(user/${destination_number}@${domain_name})
Dialplan: sofia/internal/4123343347@10.20.0.10 Action lua(app.lua failure_handler)
Dialplan: sofia/internal/4123343347@10.20.0.10 parsing [default->voicemail] continue=false
Dialplan: sofia/internal/4123343347@10.20.0.10 Regex (PASS) [voicemail] ${user_exists}(true) =~ /true/ break=on-false
Dialplan: sofia/internal/4123343347@10.20.0.10 Action set(record_append=false) INLINE
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 set(record_append=false)
2020-12-03 17:00:32.211318 [DEBUG] mod_dptools.c:1672 SET sofia/internal/4123343347@10.20.0.10 [record_append]=[false]
Dialplan: sofia/internal/4123343347@10.20.0.10 Action set(voicemail_action=save) INLINE
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 set(voicemail_action=save)
2020-12-03 17:00:32.211318 [DEBUG] mod_dptools.c:1672 SET sofia/internal/4123343347@10.20.0.10 [voicemail_action]=[save]
Dialplan: sofia/internal/4123343347@10.20.0.10 Action set(voicemail_id=${destination_number}) INLINE
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 set(voicemail_id=5661)
2020-12-03 17:00:32.211318 [DEBUG] mod_dptools.c:1672 SET sofia/internal/4123343347@10.20.0.10 [voicemail_id]=[5661]
Dialplan: sofia/internal/4123343347@10.20.0.10 Action set(voicemail_profile=default) INLINE
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 set(voicemail_profile=default)
2020-12-03 17:00:32.211318 [DEBUG] mod_dptools.c:1672 SET sofia/internal/4123343347@10.20.0.10 [voicemail_profile]=[default]
Dialplan: sofia/internal/4123343347@10.20.0.10 Action lua(app.lua voicemail)
2020-12-03 17:00:32.211318 [DEBUG] switch_core_state_machine.c:287 (sofia/internal/4123343347@10.20.0.10) State Change CS_ROUTING -> CS_EXECUTE
2020-12-03 17:00:32.211318 [DEBUG] switch_core_state_machine.c:644 (sofia/internal/4123343347@10.20.0.10) State ROUTING going to sleep
2020-12-03 17:00:32.211318 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/4123343347@10.20.0.10) Running State Change CS_EXECUTE (Cur 1 Tot 89)
2020-12-03 17:00:32.211318 [DEBUG] switch_core_state_machine.c:651 (sofia/internal/4123343347@10.20.0.10) State EXECUTE
2020-12-03 17:00:32.211318 [DEBUG] mod_sofia.c:209 sofia/internal/4123343347@10.20.0.10 SOFIA EXECUTE
2020-12-03 17:00:32.211318 [DEBUG] switch_core_state_machine.c:329 sofia/internal/4123343347@10.20.0.10 Standard EXECUTE
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 set(RFC2822_DATE=Thu, 03 Dec 2020 17:00:32 -0400)
2020-12-03 17:00:32.211318 [DEBUG] mod_dptools.c:1672 SET sofia/internal/4123343347@10.20.0.10 [RFC2822_DATE]=[Thu, 03 Dec 2020 17:00:32 -0400]
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 limit(hash 10.20.0.1 5661 )
2020-12-03 17:00:32.211318 [DEBUG] switch_limit.c:124 incr called: 10.20.0.1_5661 max:-1, interval:0
2020-12-03 17:00:32.211318 [DEBUG] mod_hash.c:194 Usage for 10.20.0.1_5661 is now 1
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 set(hangup_after_bridge=true)
2020-12-03 17:00:32.211318 [DEBUG] mod_dptools.c:1672 SET sofia/internal/4123343347@10.20.0.10 [hangup_after_bridge]=[true]
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 set(continue_on_fail=true)
2020-12-03 17:00:32.211318 [DEBUG] mod_dptools.c:1672 SET sofia/internal/4123343347@10.20.0.10 [continue_on_fail]=[true]
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 hash(insert/10.20.0.1-call_return/5661/4123343347)
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 hash(insert/10.20.0.1-last_dial_ext/5661/96139f7c-c058-4cdf-be92-165038b078e1)
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 set(called_party_call_group=)
2020-12-03 17:00:32.211318 [DEBUG] mod_dptools.c:1672 SET sofia/internal/4123343347@10.20.0.10 [called_party_call_group]=[UNDEF]
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 hash(insert/10.20.0.1-last_dial//96139f7c-c058-4cdf-be92-165038b078e1)
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 set(api_hangup_hook=lua app.lua hangup)
2020-12-03 17:00:32.211318 [DEBUG] mod_dptools.c:1672 SET sofia/internal/4123343347@10.20.0.10 [api_hangup_hook]=[lua app.lua hangup]
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 export(domain_name=10.20.0.1)
2020-12-03 17:00:32.211318 [DEBUG] switch_channel.c:1310 EXPORT (export_vars) [domain_name]=[10.20.0.1]
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 bridge(user/5661@10.20.0.1)
nta.c:1296 agent_timer() nta: timer set next to 27461 ms
2020-12-03 17:00:32.211318 [DEBUG] switch_channel.c:1264 sofia/internal/4123343347@10.20.0.10 EXPORTING[export_vars] [call_direction]=[inbound] to event
2020-12-03 17:00:32.211318 [DEBUG] switch_channel.c:1264 sofia/internal/4123343347@10.20.0.10 EXPORTING[export_vars] [call_direction]=[inbound] to event
2020-12-03 17:00:32.211318 [DEBUG] switch_channel.c:1264 sofia/internal/4123343347@10.20.0.10 EXPORTING[export_vars] [call_direction]=[inbound] to event
2020-12-03 17:00:32.211318 [DEBUG] switch_channel.c:1264 sofia/internal/4123343347@10.20.0.10 EXPORTING[export_vars] [dialed_extension]=[5661] to event
2020-12-03 17:00:32.211318 [DEBUG] switch_channel.c:1264 sofia/internal/4123343347@10.20.0.10 EXPORTING[export_vars] [domain_name]=[10.20.0.1] to event
2020-12-03 17:00:32.211318 [DEBUG] switch_ivr_originate.c:2242 Parsing global variables
2020-12-03 17:00:32.211318 [DEBUG] switch_channel.c:1264 sofia/internal/4123343347@10.20.0.10 EXPORTING[export_vars] [call_direction]=[inbound] to event
2020-12-03 17:00:32.211318 [DEBUG] switch_channel.c:1264 sofia/internal/4123343347@10.20.0.10 EXPORTING[export_vars] [call_direction]=[inbound] to event
2020-12-03 17:00:32.211318 [DEBUG] switch_channel.c:1264 sofia/internal/4123343347@10.20.0.10 EXPORTING[export_vars] [call_direction]=[inbound] to event
2020-12-03 17:00:32.211318 [DEBUG] switch_channel.c:1264 sofia/internal/4123343347@10.20.0.10 EXPORTING[export_vars] [dialed_extension]=[5661] to event
2020-12-03 17:00:32.211318 [DEBUG] switch_channel.c:1264 sofia/internal/4123343347@10.20.0.10 EXPORTING[export_vars] [domain_name]=[10.20.0.1] to event
2020-12-03 17:00:32.211318 [DEBUG] switch_ivr_originate.c:2242 Parsing global variables
2020-12-03 17:00:32.211318 [NOTICE] switch_channel.c:1118 New Channel sofia/internal/5661@10.20.40.17:5060 [863a78f6-2e05-4e71-a5bd-c56feed57abc]
2020-12-03 17:00:32.211318 [DEBUG] mod_sofia.c:5089 (sofia/internal/5661@10.20.40.17:5060) State Change CS_NEW -> CS_INIT
2020-12-03 17:00:32.211318 [DEBUG] switch_ivr_originate.c:3111 sofia/internal/5661@10.20.40.17:5060 Setting leg timeout to 30
2020-12-03 17:00:32.231339 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/5661@10.20.40.17:5060) Running State Change CS_INIT (Cur 2 Tot 90)
2020-12-03 17:00:32.231339 [DEBUG] switch_core_state_machine.c:628 (sofia/internal/5661@10.20.40.17:5060) State INIT
2020-12-03 17:00:32.231339 [DEBUG] mod_sofia.c:93 sofia/internal/5661@10.20.40.17:5060 SOFIA INIT
nua_common.c:108 nh_create_handle() nua: nh_create_handle: entering
nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering
2020-12-03 17:00:32.231339 [DEBUG] sofia_glue.c:1618 sofia/internal/5661@10.20.40.17:5060 sending invite version: 1.10.3 -release-15-129de34d84 64bit
Local SDP:
v=0
o=FreeSWITCH 1606999076 1606999077 IN IP4 10.20.0.1
s=FreeSWITCH
c=IN IP4 10.20.0.1
t=0 0
m=audio 30156 RTP/AVP 9 0 8 101 13
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=rtpmap:13 CN/8000
a=ptime:20
a=sendrecv
nua.c:633 nua_invite() nua: nua_invite: entering
nua_stack.c:529 nua_signal() nua(0x7f53f006ee70): sent signal r_invite
2020-12-03 17:00:32.231339 [DEBUG] switch_core_state_machine.c:40 sofia/internal/5661@10.20.40.17:5060 Standard INIT
2020-12-03 17:00:32.231339 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/5661@10.20.40.17:5060) State Change CS_INIT -> CS_ROUTING
2020-12-03 17:00:32.231339 [DEBUG] switch_core_state_machine.c:628 (sofia/internal/5661@10.20.40.17:5060) State INIT going to sleep
nua_stack.c:569 nua_stack_signal() nua(0x7f53f006ee70): recv signal r_invite
nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:280 soa_clone() soa_clone(static::0x7f53cc001b90, 0x7f53cc001390, 0x7f53f006ee70) called
soa.c:403 soa_set_params() soa_set_params(static::0x7f53cc00cbf0, ...) called
soa.c:403 soa_set_params() soa_set_params(static::0x7f53cc00cbf0, ...) called
soa.c:1052 soa_set_user_sdp() soa_set_user_sdp(static::0x7f53cc00cbf0, (nil), 0x7f53f0047e22, -1) called
soa.c:890 soa_set_capability_sdp() soa_set_capability_sdp(static::0x7f53cc00cbf0, (nil), 0x7f53f0047e22, -1) called
nua_dialog.c:338 nua_dialog_usage_add() nua(0x7f53f006ee70): adding session usage
nta.c:4422 nta_leg_tcreate() nta_leg_tcreate(0x7f53cc015ae0)
2020-12-03 17:00:32.231339 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/5661@10.20.40.17:5060) Running State Change CS_ROUTING (Cur 2 Tot 90)
soa.c:1302 soa_init_offer_answer() soa_init_offer_answer(static::0x7f53cc00cbf0) called
soa.c:1426 soa_generate_offer() soa_generate_offer(static::0x7f53cc00cbf0, 0) called
soa_static.c:1148 offer_answer_step() soa_static_offer_answer_action(0x7f53cc00cbf0, soa_generate_offer): called
soa_static.c:1189 offer_answer_step() soa_static(0x7f53cc00cbf0, soa_generate_offer): generating local description
soa_static.c:1217 offer_answer_step() soa_static(0x7f53cc00cbf0, soa_generate_offer): upgrade with local description
soa_static.c:1029 soa_sdp_mode_set() soa_sdp_mode_set(0x7f541440a860, (nil), ""): called
soa_static.c:1446 offer_answer_step() soa_static(0x7f53cc00cbf0, soa_generate_offer): storing local description
soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x7f53cc00cbf0, [(nil)], [0x7f541440c9e8], [0x7f541440c9e4]) called
nta.c:2670 nta_tpn_by_url() nta: selecting scheme sip
2020-12-03 17:00:32.231339 [DEBUG] switch_core_state_machine.c:644 (sofia/internal/5661@10.20.40.17:5060) State ROUTING
2020-12-03 17:00:32.231339 [DEBUG] mod_sofia.c:154 sofia/internal/5661@10.20.40.17:5060 SOFIA ROUTING
2020-12-03 17:00:32.231339 [DEBUG] switch_ivr_originate.c:67 (sofia/internal/5661@10.20.40.17:5060) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2020-12-03 17:00:32.231339 [DEBUG] switch_core_state_machine.c:644 (sofia/internal/5661@10.20.40.17:5060) State ROUTING going to sleep
tport.c:3275 tport_tsend() tport_tsend(0x7f53cc004e80) tpn = udp/10.20.40.17:5060
tport.c:4064 tport_resolve() tport_resolve addrinfo = 10.20.40.17:5060
tport.c:4698 tport_by_addrinfo() tport_by_addrinfo(0x7f53cc004e80): not found by name udp/10.20.40.17:5060
tport.c:3612 tport_vsend() tport_vsend(0x7f53cc004e80): 1252 bytes of 1252 to udp/10.20.40.17:5060
2020-12-03 17:00:32.231339 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/5661@10.20.40.17:5060) Running State Change CS_CONSUME_MEDIA (Cur 2 Tot 90)
tport.c:3510 tport_send_msg() tport_vsend returned 1252
nta.c:8315 outgoing_send() nta: sent INVITE (28960824) to udp/10.20.40.17:5060
tport.c:4178 tport_pend() tport_pend(0x7f53cc004e80): pending 0x7f53cc041210 for udp/10.20.0.1:5060 (already 0)
nta.c:1348 set_timeout() nta: timer shortened to 1000 ms
nua_session.c:4140 signal_call_state_change() nua(0x7f53f006ee70): call state changed: init -> calling, sent offer
soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x7f53cc00cbf0, [0x7f541440c9c8], [0x7f541440c9d0], [(nil)]) called
nua_stack.c:269 nua_stack_event() nua(0x7f53f006ee70): event i_state INVITE sent
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2020-12-03 17:00:32.231339 [DEBUG] sofia.c:7325 Channel sofia/internal/5661@10.20.40.17:5060 entering state [calling][0]
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2020-12-03 17:00:32.231339 [DEBUG] switch_core_state_machine.c:663 (sofia/internal/5661@10.20.40.17:5060) State CONSUME_MEDIA
2020-12-03 17:00:32.231339 [DEBUG] switch_core_state_machine.c:663 (sofia/internal/5661@10.20.40.17:5060) State CONSUME_MEDIA going to sleep
tport.c:2759 tport_wakeup_pri() tport_wakeup_pri(0x7f53cc004e80): events IN
tport.c:2882 tport_recv_event() tport_recv_event(0x7f53cc004e80)
tport.c:3223 tport_recv_iovec() tport_recv_iovec(0x7f53cc004e80) msg 0x7f53cc125a90 from (udp/10.20.0.1:5060) has 319 bytes, veclen = 1
tport.c:3041 tport_deliver() tport_deliver(0x7f53cc004e80): msg 0x7f53cc125a90 (319 bytes) from udp/10.20.40.17:5060/sip next=(nil)
nta.c:3304 agent_recv_response() nta: received 100 Trying for INVITE (28960824)
nta.c:3371 agent_recv_response() nta: 100 Trying is going to a transaction
nta.c:9584 outgoing_estimate_delay() nta_outgoing: RTT is 104.797 ms
tport.c:4240 tport_release() tport_release(0x7f53cc004e80): 0x7f53cc041210 by 0x7f53cc05e3b0 with 0x7f53cc125a90 (preliminary)
nta.c:1296 agent_timer() nta: timer set next to 26448 ms
tport.c:2759 tport_wakeup_pri() tport_wakeup_pri(0x7f53cc004e80): events IN
tport.c:2882 tport_recv_event() tport_recv_event(0x7f53cc004e80)
tport.c:3223 tport_recv_iovec() tport_recv_iovec(0x7f53cc004e80) msg 0x7f53cc125a90 from (udp/10.20.0.1:5060) has 414 bytes, veclen = 1
tport.c:3041 tport_deliver() tport_deliver(0x7f53cc004e80): msg 0x7f53cc125a90 (414 bytes) from udp/10.20.60.11:5060/sip next=(nil)
nta.c:2885 agent_recv_request() nta: received REGISTER sip:10.20.0.1 SIP/2.0 (CSeq 78275)
nta.c:3253 agent_aliases() nta: canonizing sip:10.20.0.1 with contact
nta.c:3090 agent_recv_request() nta: REGISTER (78275) going to a default leg
nua_server.c:102 nua_stack_process_request() nua: nua_stack_process_request: entering
nua_stack.c:901 nh_create() nua: nh_create: entering
nua_common.c:108 nh_create_handle() nua: nh_create_handle: entering
nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:280 soa_clone() soa_clone(static::0x7f53cc001b90, 0x7f53cc001390, 0x7f53cc0e4350) called
soa.c:403 soa_set_params() soa_set_params(static::0x7f53cc055cb0, ...) called
nua_stack.c:271 nua_stack_event() nua(0x7f53cc0e4350): event i_register 100 Trying
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:879 nua_respond() nua: nua_respond: entering
nua_stack.c:529 nua_signal() nua(0x7f53cc0e4350): sent signal r_respond
2020-12-03 17:00:33.331423 [WARNING] sofia_reg.c:1794 SIP auth challenge (REGISTER) on sofia profile 'internal' for [5476@10.20.0.1] from ip 10.20.60.11
nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
nua_stack.c:529 nua_signal() nua(0x7f53cc0e4350): sent signal r_destroy
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
nua_stack.c:573 nua_stack_signal() nua(0x7f53cc0e4350): recv signal r_respond 401 Unauthorized
nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:403 soa_set_params() soa_set_params(static::0x7f53cc055cb0, ...) called
tport.c:3275 tport_tsend() tport_tsend(0x7f53cc004e80) tpn = UDP/10.20.60.11:5060
tport.c:4064 tport_resolve() tport_resolve addrinfo = 10.20.60.11:5060
tport.c:4698 tport_by_addrinfo() tport_by_addrinfo(0x7f53cc004e80): not found by name UDP/10.20.60.11:5060
tport.c:3612 tport_vsend() tport_vsend(0x7f53cc004e80): 578 bytes of 578 to udp/10.20.60.11:5060
tport.c:3510 tport_send_msg() tport_vsend returned 578
nta.c:6802 incoming_reply() nta: sent 401 Unauthorized for REGISTER (78275)
nua_stack.c:569 nua_stack_signal() nua(0x7f53cc0e4350): recv signal r_destroy
nta.c:4475 nta_leg_destroy() nta_leg_destroy((nil))
soa.c:356 soa_destroy() soa_destroy(static::0x7f53cc055cb0) called
tport.c:2759 tport_wakeup_pri() tport_wakeup_pri(0x7f53cc004e80): events IN
tport.c:2882 tport_recv_event() tport_recv_event(0x7f53cc004e80)
tport.c:3223 tport_recv_iovec() tport_recv_iovec(0x7f53cc004e80) msg 0x7f53cc02b4d0 from (udp/10.20.0.1:5060) has 641 bytes, veclen = 1
tport.c:3041 tport_deliver() tport_deliver(0x7f53cc004e80): msg 0x7f53cc02b4d0 (641 bytes) from udp/10.20.60.11:5060/sip next=(nil)
nta.c:2885 agent_recv_request() nta: received REGISTER sip:10.20.0.1 SIP/2.0 (CSeq 78276)
nta.c:3253 agent_aliases() nta: canonizing sip:10.20.0.1 with contact
nta.c:3090 agent_recv_request() nta: REGISTER (78276) going to a default leg
nua_server.c:102 nua_stack_process_request() nua: nua_stack_process_request: entering
nua_stack.c:901 nh_create() nua: nh_create: entering
nua_common.c:108 nh_create_handle() nua: nh_create_handle: entering
nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:280 soa_clone() soa_clone(static::0x7f53cc001b90, 0x7f53cc001390, 0x7f53cc00d520) called
soa.c:403 soa_set_params() soa_set_params(static::0x7f53cc055cb0, ...) called
nua_stack.c:271 nua_stack_event() nua(0x7f53cc00d520): event i_register 100 Trying
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:879 nua_respond() nua: nua_respond: entering
nua_stack.c:529 nua_signal() nua(0x7f53cc00d520): sent signal r_respond
nua_stack.c:573 nua_stack_signal() nua(0x7f53cc00d520): recv signal r_respond 200 OK
nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:403 soa_set_params() soa_set_params(static::0x7f53cc055cb0, ...) called
nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
nua_stack.c:529 nua_signal() nua(0x7f53cc00d520): sent signal r_destroy
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
tport.c:3275 tport_tsend() tport_tsend(0x7f53cc004e80) tpn = UDP/10.20.60.11:5060
tport.c:4064 tport_resolve() tport_resolve addrinfo = 10.20.60.11:5060
tport.c:4698 tport_by_addrinfo() tport_by_addrinfo(0x7f53cc004e80): not found by name UDP/10.20.60.11:5060
tport.c:3612 tport_vsend() tport_vsend(0x7f53cc004e80): 538 bytes of 538 to udp/10.20.60.11:5060
tport.c:3510 tport_send_msg() tport_vsend returned 538
nta.c:6802 incoming_reply() nta: sent 200 OK for REGISTER (78276)
nua_stack.c:569 nua_stack_signal() nua(0x7f53cc00d520): recv signal r_destroy
nta.c:4475 nta_leg_destroy() nta_leg_destroy((nil))
soa.c:356 soa_destroy() soa_destroy(static::0x7f53cc055cb0) called
tport.c:2759 tport_wakeup_pri() tport_wakeup_pri(0x7f53cc004e80): events IN
tport.c:2882 tport_recv_event() tport_recv_event(0x7f53cc004e80)
tport.c:3223 tport_recv_iovec() tport_recv_iovec(0x7f53cc004e80) msg 0x7f53cc047480 from (udp/10.20.0.1:5060) has 408 bytes, veclen = 1
tport.c:3041 tport_deliver() tport_deliver(0x7f53cc004e80): msg 0x7f53cc047480 (408 bytes) from udp/10.20.50.1:5060/sip next=(nil)
nta.c:2885 agent_recv_request() nta: received REGISTER sip:10.20.0.1 SIP/2.0 (CSeq 31)
nta.c:3253 agent_aliases() nta: canonizing sip:10.20.0.1 with contact
nta.c:3090 agent_recv_request() nta: REGISTER (31) going to a default leg
nua_server.c:102 nua_stack_process_request() nua: nua_stack_process_request: entering
nua_stack.c:901 nh_create() nua: nh_create: entering
nua_common.c:108 nh_create_handle() nua: nh_create_handle: entering
nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:280 soa_clone() soa_clone(static::0x7f53cc001b90, 0x7f53cc001390, 0x7f53cc129340) called
soa.c:403 soa_set_params() soa_set_params(static::0x7f53cc1364f0, ...) called
nua_stack.c:271 nua_stack_event() nua(0x7f53cc129340): event i_register 100 Trying
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:879 nua_respond() nua: nua_respond: entering
nua_stack.c:573 nua_stack_signal() nua(0x7f53cc129340): recv signal r_respond 401 Unauthorized
nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:403 soa_set_params() soa_set_params(static::0x7f53cc1364f0, ...) called
tport.c:3275 tport_tsend() tport_tsend(0x7f53cc004e80) tpn = UDP/10.20.50.1:5060
nua_stack.c:529 nua_signal() nua(0x7f53cc129340): sent signal r_respond
tport.c:4064 tport_resolve() tport_resolve addrinfo = 10.20.50.1:5060
tport.c:4698 tport_by_addrinfo() tport_by_addrinfo(0x7f53cc004e80): not found by name UDP/10.20.50.1:5060
2020-12-03 17:00:34.431401 [WARNING] sofia_reg.c:1794 SIP auth challenge (REGISTER) on sofia profile 'internal' for [5602@10.20.0.1] from ip 10.20.50.1
nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
nua_stack.c:529 nua_signal() nua(0x7f53cc129340): sent signal r_destroy
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
tport.c:3612 tport_vsend() tport_vsend(0x7f53cc004e80): 572 bytes of 572 to udp/10.20.50.1:5060
tport.c:3510 tport_send_msg() tport_vsend returned 572
nta.c:6802 incoming_reply() nta: sent 401 Unauthorized for REGISTER (31)
nua_stack.c:569 nua_stack_signal() nua(0x7f53cc129340): recv signal r_destroy
nta.c:4475 nta_leg_destroy() nta_leg_destroy((nil))
soa.c:356 soa_destroy() soa_destroy(static::0x7f53cc1364f0) called
tport.c:2759 tport_wakeup_pri() tport_wakeup_pri(0x7f53cc004e80): events IN
tport.c:2882 tport_recv_event() tport_recv_event(0x7f53cc004e80)
tport.c:3223 tport_recv_iovec() tport_recv_iovec(0x7f53cc004e80) msg 0x7f53cc102050 from (udp/10.20.0.1:5060) has 634 bytes, veclen = 1
tport.c:3041 tport_deliver() tport_deliver(0x7f53cc004e80): msg 0x7f53cc102050 (634 bytes) from udp/10.20.50.1:5060/sip next=(nil)
nta.c:2885 agent_recv_request() nta: received REGISTER sip:10.20.0.1 SIP/2.0 (CSeq 32)
nta.c:3253 agent_aliases() nta: canonizing sip:10.20.0.1 with contact
nta.c:3090 agent_recv_request() nta: REGISTER (32) going to a default leg
nua_server.c:102 nua_stack_process_request() nua: nua_stack_process_request: entering
nua_stack.c:901 nh_create() nua: nh_create: entering
nua_common.c:108 nh_create_handle() nua: nh_create_handle: entering
nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:280 soa_clone() soa_clone(static::0x7f53cc001b90, 0x7f53cc001390, 0x7f53cc0f6c80) called
soa.c:403 soa_set_params() soa_set_params(static::0x7f53cc129260, ...) called
nua_stack.c:271 nua_stack_event() nua(0x7f53cc0f6c80): event i_register 100 Trying
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:879 nua_respond() nua: nua_respond: entering
nua_stack.c:573 nua_stack_signal() nua(0x7f53cc0f6c80): recv signal r_respond 200 OK
nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering
nua_stack.c:529 nua_signal() nua(0x7f53cc0f6c80): sent signal r_respond
soa.c:403 soa_set_params() soa_set_params(static::0x7f53cc129260, ...) called
tport.c:3275 tport_tsend() tport_tsend(0x7f53cc004e80) tpn = UDP/10.20.50.1:5060
tport.c:4064 tport_resolve() tport_resolve addrinfo = 10.20.50.1:5060
tport.c:4698 tport_by_addrinfo() tport_by_addrinfo(0x7f53cc004e80): not found by name UDP/10.20.50.1:5060
nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
tport.c:3612 tport_vsend() tport_vsend(0x7f53cc004e80): 532 bytes of 532 to udp/10.20.50.1:5060
tport.c:3510 tport_send_msg() tport_vsend returned 532
nua_stack.c:529 nua_signal() nua(0x7f53cc0f6c80): sent signal r_destroy
nta.c:6802 incoming_reply() nta: sent 200 OK for REGISTER (32)
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
nua_stack.c:569 nua_stack_signal() nua(0x7f53cc0f6c80): recv signal r_destroy
nta.c:4475 nta_leg_destroy() nta_leg_destroy((nil))
soa.c:356 soa_destroy() soa_destroy(static::0x7f53cc129260) called
tport.c:2759 tport_wakeup_pri() tport_wakeup_pri(0x7f53cc004e80): events IN
tport.c:2882 tport_recv_event() tport_recv_event(0x7f53cc004e80)
tport.c:3223 tport_recv_iovec() tport_recv_iovec(0x7f53cc004e80) msg 0x7f53cc12de20 from (udp/10.20.0.1:5060) has 746 bytes, veclen = 1
tport.c:3041 tport_deliver() tport_deliver(0x7f53cc004e80): msg 0x7f53cc12de20 (746 bytes) from udp/10.20.40.17:5060/sip next=(nil)
nta.c:3304 agent_recv_response() nta: received 200 OK for INVITE (28960824)
nta.c:3371 agent_recv_response() nta: 200 OK is going to a transaction
tport.c:4240 tport_release() tport_release(0x7f53cc004e80): 0x7f53cc041210 by 0x7f53cc05e3b0 with 0x7f53cc12de20
soa.c:1171 soa_set_remote_sdp() soa_set_remote_sdp(static::0x7f53cc00cbf0, (nil), 0x7f53cc0f6a78, 210) called
soa.c:1595 soa_process_answer() soa_process_answer(static::0x7f53cc00cbf0) called
soa_static.c:1148 offer_answer_step() soa_static_offer_answer_action(0x7f53cc00cbf0, soa_process_answer): called
soa_static.c:1029 soa_sdp_mode_set() soa_sdp_mode_set(0x7f53cc12da90, 0x7f53dc05e690, ""): called
soa_static.c:1304 offer_answer_step() soa_static(0x7f53cc00cbf0, soa_process_answer): upgrade codecs with remote description
soa_static.c:1446 offer_answer_step() soa_static(0x7f53cc00cbf0, soa_process_answer): storing local description
soa.c:1730 soa_activate() soa_activate(static::0x7f53cc00cbf0, (nil)) called
nua_session.c:986 nua_session_client_response() nua(0x7f53f006ee70): INVITE: processed SDP answer in 200 OK (200)
nua_stack.c:271 nua_stack_event() nua(0x7f53f006ee70): event r_invite 200 OK
nua_session.c:4140 signal_call_state_change() nua(0x7f53f006ee70): call state changed: calling -> completing, received answer
soa.c:1098 soa_get_remote_sdp() soa_get_remote_sdp(static::0x7f53cc00cbf0, [0x7f541440c3e8], [0x7f541440c3f0], [(nil)]) called
soa.c:616 soa_get_params() soa_get_params(static::0x7f53cc00cbf0, ...) called
nua_stack.c:271 nua_stack_event() nua(0x7f53f006ee70): event i_state 200 OK
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2020-12-03 17:00:34.831425 [DEBUG] sofia.c:7325 Channel sofia/internal/5661@10.20.40.17:5060 entering state [completing][200]
2020-12-03 17:00:34.831425 [DEBUG] sofia.c:7335 Remote SDP:
v=0
o=5661 8000 8000 IN IP4 10.20.40.17
s=SIP Call
c=IN IP4 10.20.40.17
t=0 0
m=audio 5004 RTP/AVP 9 101
a=rtpmap:9 G722/16000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-11
a=ptime:20
nua.c:639 nua_ack() nua: nua_ack: entering
nua_stack.c:529 nua_signal() nua(0x7f53f006ee70): sent signal r_ack
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua_stack.c:569 nua_stack_signal() nua(0x7f53f006ee70): recv signal r_ack
nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:403 soa_set_params() soa_set_params(static::0x7f53cc00cbf0, ...) called
soa.c:1730 soa_activate() soa_activate(static::0x7f53cc00cbf0, (nil)) called
nta.c:2670 nta_tpn_by_url() nta: selecting scheme sip
tport.c:3275 tport_tsend() tport_tsend(0x7f53cc004e80) tpn = udp/10.20.40.17:5060
tport.c:4064 tport_resolve() tport_resolve addrinfo = 10.20.40.17:5060
tport.c:4698 tport_by_addrinfo() tport_by_addrinfo(0x7f53cc004e80): not found by name udp/10.20.40.17:5060
tport.c:3612 tport_vsend() tport_vsend(0x7f53cc004e80): 395 bytes of 395 to udp/10.20.40.17:5060
tport.c:3510 tport_send_msg() tport_vsend returned 395
nta.c:8315 outgoing_send() nta: sent ACK (28960824) to udp/10.20.40.17:5060
nua_session.c:4140 signal_call_state_change() nua(0x7f53f006ee70): call state changed: completing -> ready
nua_stack.c:271 nua_stack_event() nua(0x7f53f006ee70): event i_state 200 ACK sent
nua_stack.c:271 nua_stack_event() nua(0x7f53f006ee70): event i_active 200 Call active
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2020-12-03 17:00:34.831425 [DEBUG] sofia.c:7325 Channel sofia/internal/5661@10.20.40.17:5060 entering state [ready][200]
2020-12-03 17:00:34.831425 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [G722:9:16000:20:64000:1]/[G722:9:8000:20:64000:1]
2020-12-03 17:00:34.831425 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [G722:9:16000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2020-12-03 17:00:34.831425 [DEBUG] switch_core_media.c:5592 Audio Codec Compare [G722:9:16000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2020-12-03 17:00:34.831425 [DEBUG] switch_core_media.c:5508 Set telephone-event payload to 101@8000
2020-12-03 17:00:34.831425 [DEBUG] switch_core_media.c:5909 sofia/internal/5661@10.20.40.17:5060 Set 2833 dtmf send payload to 101 recv payload to 101
2020-12-03 17:00:34.831425 [NOTICE] sofia.c:8525 Hangup sofia/internal/5661@10.20.40.17:5060 [CS_CONSUME_MEDIA] [INCOMPATIBLE_DESTINATION]
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2020-12-03 17:00:34.851389 [DEBUG] sofia.c:1548 Channel is already hungup.
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2020-12-03 17:00:34.851389 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/5661@10.20.40.17:5060) Running State Change CS_HANGUP (Cur 2 Tot 90)
2020-12-03 17:00:34.851389 [DEBUG] switch_core_state_machine.c:848 (sofia/internal/5661@10.20.40.17:5060) Callstate Change DOWN -> HANGUP
2020-12-03 17:00:34.851389 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/5661@10.20.40.17:5060) State HANGUP
2020-12-03 17:00:34.851389 [DEBUG] mod_sofia.c:453 Channel sofia/internal/5661@10.20.40.17:5060 hanging up, cause: INCOMPATIBLE_DESTINATION
2020-12-03 17:00:34.851389 [DEBUG] mod_sofia.c:507 Sending BYE to sofia/internal/5661@10.20.40.17:5060
nua.c:645 nua_bye() nua: nua_bye: entering
nua_stack.c:569 nua_stack_signal() nua(0x7f53f006ee70): recv signal r_bye
nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:403 soa_set_params() soa_set_params(static::0x7f53cc00cbf0, ...) called
soa.c:1784 soa_terminate() soa_terminate(static::0x7f53cc00cbf0) called
nua_stack.c:529 nua_signal() nua(0x7f53f006ee70): sent signal r_bye
soa.c:1302 soa_init_offer_answer() soa_init_offer_answer(static::0x7f53cc00cbf0) called
2020-12-03 17:00:34.851389 [DEBUG] switch_core_state_machine.c:60 sofia/internal/5661@10.20.40.17:5060 Standard HANGUP, cause: INCOMPATIBLE_DESTINATION
nta.c:2670 nta_tpn_by_url() nta: selecting scheme sip
tport.c:3275 tport_tsend() tport_tsend(0x7f53cc004e80) tpn = udp/10.20.40.17:5060
2020-12-03 17:00:34.851389 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/5661@10.20.40.17:5060) State HANGUP going to sleep
tport.c:4064 tport_resolve() tport_resolve addrinfo = 10.20.40.17:5060
tport.c:4698 tport_by_addrinfo() tport_by_addrinfo(0x7f53cc004e80): not found by name udp/10.20.40.17:5060
2020-12-03 17:00:34.851389 [DEBUG] switch_core_state_machine.c:620 (sofia/internal/5661@10.20.40.17:5060) State Change CS_HANGUP -> CS_REPORTING
tport.c:3612 tport_vsend() tport_vsend(0x7f53cc004e80): 578 bytes of 578 to udp/10.20.40.17:5060
tport.c:3510 tport_send_msg() tport_vsend returned 578
nta.c:8315 outgoing_send() nta: sent BYE (28960825) to udp/10.20.40.17:5060
tport.c:4178 tport_pend() tport_pend(0x7f53cc004e80): pending 0x7f53cc05ecd0 for udp/10.20.0.1:5060 (already 0)
nta.c:1348 set_timeout() nta: timer shortened to 1000 ms
2020-12-03 17:00:34.851389 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/5661@10.20.40.17:5060) Running State Change CS_REPORTING (Cur 2 Tot 90)
2020-12-03 17:00:34.851389 [DEBUG] switch_core_state_machine.c:936 (sofia/internal/5661@10.20.40.17:5060) State REPORTING
2020-12-03 17:00:34.851389 [DEBUG] switch_core_state_machine.c:174 sofia/internal/5661@10.20.40.17:5060 Standard REPORTING, cause: INCOMPATIBLE_DESTINATION
2020-12-03 17:00:34.851389 [DEBUG] switch_core_state_machine.c:936 (sofia/internal/5661@10.20.40.17:5060) State REPORTING going to sleep
2020-12-03 17:00:34.851389 [DEBUG] switch_core_state_machine.c:611 (sofia/internal/5661@10.20.40.17:5060) State Change CS_REPORTING -> CS_DESTROY
2020-12-03 17:00:34.851389 [DEBUG] switch_core_session.c:1726 Session 90 (sofia/internal/5661@10.20.40.17:5060) Locked, Waiting on external entities
2020-12-03 17:00:34.851389 [DEBUG] switch_ivr_originate.c:3995 Originate Resulted in Error Cause: 88 [INCOMPATIBLE_DESTINATION]
2020-12-03 17:00:34.851389 [NOTICE] switch_core_session.c:1744 Session 90 (sofia/internal/5661@10.20.40.17:5060) Ended
2020-12-03 17:00:34.851389 [NOTICE] switch_core_session.c:1748 Close Channel sofia/internal/5661@10.20.40.17:5060 [CS_DESTROY]
2020-12-03 17:00:34.851389 [DEBUG] switch_core_state_machine.c:739 (sofia/internal/5661@10.20.40.17:5060) Running State Change CS_DESTROY (Cur 1 Tot 90)
2020-12-03 17:00:34.851389 [DEBUG] switch_core_state_machine.c:749 (sofia/internal/5661@10.20.40.17:5060) State DESTROY
2020-12-03 17:00:34.851389 [DEBUG] mod_sofia.c:364 sofia/internal/5661@10.20.40.17:5060 SOFIA DESTROY
2020-12-03 17:00:34.851389 [NOTICE] switch_ivr_originate.c:2999 Cannot create outgoing channel of type [user] cause: [INCOMPATIBLE_DESTINATION]
2020-12-03 17:00:34.851389 [DEBUG] switch_core_state_machine.c:181 sofia/internal/5661@10.20.40.17:5060 Standard DESTROY
2020-12-03 17:00:34.851389 [DEBUG] switch_core_state_machine.c:749 (sofia/internal/5661@10.20.40.17:5060) State DESTROY going to sleep
2020-12-03 17:00:34.851389 [DEBUG] switch_ivr_originate.c:3995 Originate Resulted in Error Cause: 88 [INCOMPATIBLE_DESTINATION]
2020-12-03 17:00:34.851389 [INFO] mod_dptools.c:3631 Originate Failed. Cause: INCOMPATIBLE_DESTINATION
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 lua(app.lua failure_handler)
2020-12-03 17:00:34.871359 [DEBUG] switch_cpp.cpp:1191 sofia/internal/4123343347@10.20.0.10 destroy/unlink session from object
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 lua(app.lua voicemail)
2020-12-03 17:00:34.891350 [DEBUG] switch_core_media.c:8661 AUDIO RTP [sofia/internal/4123343347@10.20.0.10] 10.20.0.1 port 27762 -> 10.20.0.10 port 11590 codec: 9 ms: 20
2020-12-03 17:00:34.891350 [DEBUG] switch_rtp.c:4413 Starting timer [soft] 160 bytes per 20ms
2020-12-03 17:00:34.911349 [DEBUG] switch_core_media.c:8975 sofia/internal/4123343347@10.20.0.10 Set 2833 dtmf send payload to 101
2020-12-03 17:00:34.911349 [DEBUG] switch_core_media.c:8982 sofia/internal/4123343347@10.20.0.10 Set 2833 dtmf receive payload to 101
2020-12-03 17:00:34.911349 [DEBUG] switch_core_media.c:9005 sofia/internal/4123343347@10.20.0.10 Set rtp dtmf delay to 40
2020-12-03 17:00:34.911349 [DEBUG] mod_sofia.c:898 Local SDP sofia/internal/4123343347@10.20.0.10:
v=0
o=FreeSWITCH 1607001472 1607001473 IN IP4 10.20.0.1
s=FreeSWITCH
c=IN IP4 10.20.0.1
t=0 0
m=audio 27762 RTP/AVP 9 101
a=rtpmap:9 G722/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv
nua.c:879 nua_respond() nua: nua_respond: entering
nua_stack.c:529 nua_signal() nua(0x7f53cc038ba0): sent signal r_respond
nua_stack.c:573 nua_stack_signal() nua(0x7f53cc038ba0): recv signal r_respond 200 OK
nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:403 soa_set_params() soa_set_params(static::0x7f53cc02db50, ...) called
soa.c:1052 soa_set_user_sdp() soa_set_user_sdp(static::0x7f53cc02db50, (nil), 0x7f54040bc08a, -1) called
soa.c:890 soa_set_capability_sdp() soa_set_capability_sdp(static::0x7f53cc02db50, (nil), 0x7f54040bc08a, -1) called
2020-12-03 17:00:34.911349 [NOTICE] switch_cpp.cpp:685 Channel [sofia/internal/4123343347@10.20.0.10] has been answered
nua_session.c:2318 nua_invite_server_respond() nua: nua_invite_server_respond: entering
soa.c:1515 soa_generate_answer() soa_generate_answer(static::0x7f53cc02db50) called
soa_static.c:1148 offer_answer_step() soa_static_offer_answer_action(0x7f53cc02db50, soa_generate_answer): called
soa_static.c:1189 offer_answer_step() soa_static(0x7f53cc02db50, soa_generate_answer): generating local description
soa_static.c:1230 offer_answer_step() soa_static(0x7f53cc02db50, soa_generate_answer): upgrade with remote description
soa_static.c:1029 soa_sdp_mode_set() soa_sdp_mode_set(0x7f541440a890, 0x7f53cc0f0020, ""): called
soa_static.c:1446 offer_answer_step() soa_static(0x7f53cc02db50, soa_generate_answer): storing local description
soa.c:1730 soa_activate() soa_activate(static::0x7f53cc02db50, (nil)) called
soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x7f53cc02db50, [(nil)], [0x7f541440ca18], [0x7f541440ca14]) called
tport.c:3275 tport_tsend() tport_tsend(0x7f53cc004e80) tpn = UDP/10.20.0.10:5060
tport.c:4064 tport_resolve() tport_resolve addrinfo = 10.20.0.10:5060
tport.c:4698 tport_by_addrinfo() tport_by_addrinfo(0x7f53cc004e80): not found by name UDP/10.20.0.10:5060
tport.c:3612 tport_vsend() tport_vsend(0x7f53cc004e80): 1067 bytes of 1067 to udp/10.20.0.10:5060
tport.c:3510 tport_send_msg() tport_vsend returned 1067
nta.c:6802 incoming_reply() nta: sent 200 OK for INVITE (102)
nta.c:1348 set_timeout() nta: timer shortened to 500 ms
nua_session.c:4140 signal_call_state_change() nua(0x7f53cc038ba0): call state changed: received -> completed, sent answer
soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x7f53cc02db50, [0x7f541440cac8], [0x7f541440cad0], [(nil)]) called
soa.c:616 soa_get_params() soa_get_params(static::0x7f53cc02db50, ...) called
nua_stack.c:271 nua_stack_event() nua(0x7f53cc038ba0): event i_state 200 OK
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
2020-12-03 17:00:34.911349 [DEBUG] switch_channel.c:3865 (sofia/internal/4123343347@10.20.0.10) Callstate Change RINGING -> ACTIVE
tport.c:2759 tport_wakeup_pri() tport_wakeup_pri(0x7f53cc004e80): events IN
tport.c:2882 tport_recv_event() tport_recv_event(0x7f53cc004e80)
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
tport.c:3223 tport_recv_iovec() tport_recv_iovec(0x7f53cc004e80) msg 0x7f53cc0e18a0 from (udp/10.20.0.1:5060) has 416 bytes, veclen = 1
2020-12-03 17:00:34.911349 [DEBUG] sofia.c:7325 Channel sofia/internal/4123343347@10.20.0.10 entering state [completed][200]
tport.c:3041 tport_deliver() tport_deliver(0x7f53cc004e80): msg 0x7f53cc0e18a0 (416 bytes) from udp/10.20.0.10:5060/sip next=(nil)
nta.c:2885 agent_recv_request() nta: received ACK sip:5661@10.20.0.1:5060;transport=udp SIP/2.0 (CSeq 102)
nta.c:3024 agent_recv_request() nta: ACK (102) is going to INVITE (102)
nua_session.c:2567 process_ack_or_cancel() nua: process_ack_or_cancel: entering
soa.c:1214 soa_clear_remote_sdp() soa_clear_remote_sdp(static::0x7f53cc02db50) called
nua_stack.c:271 nua_stack_event() nua(0x7f53cc038ba0): event i_ack 200 OK
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua_session.c:4140 signal_call_state_change() nua(0x7f53cc038ba0): call state changed: completed -> ready
nua_stack.c:271 nua_stack_event() nua(0x7f53cc038ba0): event i_state 200 OK
nua_stack.c:271 nua_stack_event() nua(0x7f53cc038ba0): event i_active 200 Call active
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 sleep(1000)
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2020-12-03 17:00:34.911349 [DEBUG] sofia.c:7325 Channel sofia/internal/4123343347@10.20.0.10 entering state [ready][200]
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2020-12-03 17:00:34.951356 [DEBUG] switch_rtp.c:7722 Correct audio ip/port confirmed.
tport.c:2759 tport_wakeup_pri() tport_wakeup_pri(0x7f53cc004e80): events IN
tport.c:2882 tport_recv_event() tport_recv_event(0x7f53cc004e80)
tport.c:3223 tport_recv_iovec() tport_recv_iovec(0x7f53cc004e80) msg 0x7f53cc0e18a0 from (udp/10.20.0.1:5060) has 500 bytes, veclen = 1
tport.c:3041 tport_deliver() tport_deliver(0x7f53cc004e80): msg 0x7f53cc0e18a0 (500 bytes) from udp/10.20.40.17:5060/sip next=(nil)
nta.c:3304 agent_recv_response() nta: received 200 OK for BYE (28960825)
nta.c:3371 agent_recv_response() nta: 200 OK is going to a transaction
nta.c:9584 outgoing_estimate_delay() nta_outgoing: RTT is 354.085 ms
tport.c:4240 tport_release() tport_release(0x7f53cc004e80): 0x7f53cc05ecd0 by 0x7f53cc01ccc0 with 0x7f53cc0e18a0
nua_stack.c:271 nua_stack_event() nua(0x7f53f006ee70): event r_bye 200 OK
nua_session.c:4140 signal_call_state_change() nua(0x7f53f006ee70): call state changed: terminating -> terminated
nua_stack.c:271 nua_stack_event() nua(0x7f53f006ee70): event i_state 200 to BYE
nua_stack.c:271 nua_stack_event() nua(0x7f53f006ee70): event i_terminated 200 to BYE
nua_dialog.c:397 nua_dialog_usage_remove_at() nua(0x7f53f006ee70): removing session usage
soa.c:356 soa_destroy() soa_destroy(static::0x7f53cc00cbf0) called
nta.c:4475 nta_leg_destroy() nta_leg_destroy(0x7f53cc015ae0)
nua_session.c:351 nua_session_usage_destroy() nua: terminated session 0x7f53f006ee70
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
nua_stack.c:529 nua_signal() nua(0x7f53f006ee70): sent signal r_destroy
nua_stack.c:569 nua_stack_signal() nua(0x7f53f006ee70): recv signal r_destroy
nta.c:4475 nta_leg_destroy() nta_leg_destroy((nil))
nta.c:1296 agent_timer() nta: timer set next to 4502 ms
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 unbind_meta_app()
2020-12-03 17:00:35.911412 [INFO] switch_ivr_async.c:4356 UnBound A-Leg: ALL
2020-12-03 17:00:35.911412 [DEBUG] switch_cpp.cpp:755 CoreSession::setVariable('playback_terminators', '#')
2020-12-03 17:00:35.951499 [DEBUG] switch_cpp.cpp:755 CoreSession::setVariable('missed_call', 'true')
2020-12-03 17:00:35.951499 [DEBUG] switch_cpp.cpp:755 CoreSession::setVariable('voicemail_answer_stamp', '2020-12-03 17:00:35')
2020-12-03 17:00:35.951499 [DEBUG] switch_cpp.cpp:755 CoreSession::setVariable('voicemail_answer_epoch', '1607029235')
EXECUTE [depth=0] sofia/internal/4123343347@10.20.0.10 playback(silence_stream://200)
2020-12-03 17:00:35.951499 [DEBUG] switch_ivr_play_say.c:1488 Codec Activated L16@16000hz 1 channels 20ms
2020-12-03 17:00:36.111406 [DEBUG] switch_ivr_play_say.c:1933 done playing file silence_stream://200
2020-12-03 17:00:36.111406 [DEBUG] switch_ivr_play_say.c:1488 Codec Activated L16@16000hz 1 channels 20ms
2020-12-03 17:00:38.291414 [DEBUG] switch_ivr_play_say.c:1933 done playing file /usr/share/freeswitch/sounds/es/ar/mario/voicemail/vm-person.wav
2020-12-03 17:00:38.291414 [DEBUG] switch_ivr.c:3655 No language specified - Using [es]
2020-12-03 17:00:38.351398 [DEBUG] switch_ivr_play_say.c:1488 Codec Activated L16@16000hz 1 channels 20ms
tport.c:2759 tport_wakeup_pri() tport_wakeup_pri(0x7f53cc004e80): events IN
tport.c:2882 tport_recv_event() tport_recv_event(0x7f53cc004e80)
tport.c:3223 tport_recv_iovec() tport_recv_iovec(0x7f53cc004e80) msg 0x7f53cc06bcf0 from (udp/10.20.0.1:5060) has 446 bytes, veclen = 1
tport.c:3041 tport_deliver() tport_deliver(0x7f53cc004e80): msg 0x7f53cc06bcf0 (446 bytes) from udp/10.20.0.10:5060/sip next=(nil)
nta.c:2885 agent_recv_request() nta: received BYE sip:5661@10.20.0.1:5060;transport=udp SIP/2.0 (CSeq 103)
nta.c:3253 agent_aliases() nta: canonizing sip:5661@10.20.0.1:5060 with contact
nta.c:3065 agent_recv_request() nta: BYE (103) going to existing leg
nua_server.c:102 nua_stack_process_request() nua: nua_stack_process_request: entering
nua_stack.c:271 nua_stack_event() nua(0x7f53cc038ba0): event i_bye 100 Trying
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2020-12-03 17:00:39.011398 [NOTICE] sofia.c:1089 Hangup sofia/internal/4123343347@10.20.0.10 [CS_EXECUTE] [NORMAL_CLEARING]
2020-12-03 17:00:39.011398 [DEBUG] mod_hash.c:296 Usage for 10.20.0.1_5661 is now 0
nua.c:879 nua_respond() nua: nua_respond: entering
nua_stack.c:573 nua_stack_signal() nua(0x7f53cc038ba0): recv signal r_respond 200 OK
nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:403 soa_set_params() soa_set_params(static::0x7f53cc02db50, ...) called
tport.c:3275 tport_tsend() tport_tsend(0x7f53cc004e80) tpn = UDP/10.20.0.10:5060
nua_stack.c:529 nua_signal() nua(0x7f53cc038ba0): sent signal r_respond
tport.c:4064 tport_resolve() tport_resolve addrinfo = 10.20.0.10:5060
tport.c:4698 tport_by_addrinfo() tport_by_addrinfo(0x7f53cc004e80): not found by name UDP/10.20.0.10:5060
nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering
nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
nua_stack.c:529 nua_signal() nua(0x7f53cc038ba0): sent signal r_destroy
2020-12-03 17:00:39.011398 [DEBUG] switch_ivr_play_say.c:1933 done playing file /usr/share/freeswitch/sounds/es/ar/mario/digits/5.wav
tport.c:3612 tport_vsend() tport_vsend(0x7f53cc004e80): 459 bytes of 459 to udp/10.20.0.10:5060
tport.c:3510 tport_send_msg() tport_vsend returned 459
nta.c:6802 incoming_reply() nta: sent 200 OK for BYE (103)
nua_dialog.c:397 nua_dialog_usage_remove_at() nua(0x7f53cc038ba0): removing session usage
nua_session.c:4140 signal_call_state_change() nua(0x7f53cc038ba0): call state changed: ready -> terminated
nua_stack.c:271 nua_stack_event() nua(0x7f53cc038ba0): event i_state 200 Session Terminated
nua_stack.c:271 nua_stack_event() nua(0x7f53cc038ba0): event i_terminated 200 Session Terminated
soa.c:356 soa_destroy() soa_destroy(static::0x7f53cc02db50) called
nta.c:4475 nta_leg_destroy() nta_leg_destroy(0x7f53cc025cd0)
nua_stack.c:569 nua_stack_signal() nua(0x7f53cc038ba0): recv signal r_destroy
nta.c:4475 nta_leg_destroy() nta_leg_destroy((nil))
2020-12-03 17:00:39.051402 [NOTICE] switch_cpp.cpp:1447 [voicemail]
2020-12-03 17:00:39.071550 [DEBUG] switch_cpp.cpp:1191 sofia/internal/4123343347@10.20.0.10 destroy/unlink session from object
2020-12-03 17:00:39.071550 [DEBUG] switch_core_session.c:2905 sofia/internal/4123343347@10.20.0.10 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
2020-12-03 17:00:39.071550 [DEBUG] switch_core_state_machine.c:651 (sofia/internal/4123343347@10.20.0.10) State EXECUTE going to sleep
2020-12-03 17:00:39.071550 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/4123343347@10.20.0.10) Running State Change CS_HANGUP (Cur 1 Tot 90)
2020-12-03 17:00:39.071550 [DEBUG] switch_core_state_machine.c:848 (sofia/internal/4123343347@10.20.0.10) Callstate Change ACTIVE -> HANGUP
2020-12-03 17:00:39.071550 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/4123343347@10.20.0.10) State HANGUP
2020-12-03 17:00:39.071550 [DEBUG] mod_sofia.c:453 Channel sofia/internal/4123343347@10.20.0.10 hanging up, cause: NORMAL_CLEARING
2020-12-03 17:00:39.071550 [DEBUG] switch_core_state_machine.c:60 sofia/internal/4123343347@10.20.0.10 Standard HANGUP, cause: NORMAL_CLEARING
2020-12-03 17:00:39.071550 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/4123343347@10.20.0.10) State HANGUP going to sleep
2020-12-03 17:00:39.091397 [DEBUG] switch_core_state_machine.c:781 Hangup Command with no Session lua(app.lua hangup):
2020-12-03 17:00:39.091397 [DEBUG] switch_core_state_machine.c:620 (sofia/internal/4123343347@10.20.0.10) State Change CS_HANGUP -> CS_REPORTING
2020-12-03 17:00:39.091397 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/4123343347@10.20.0.10) Running State Change CS_REPORTING (Cur 1 Tot 90)
2020-12-03 17:00:39.091397 [DEBUG] switch_core_state_machine.c:936 (sofia/internal/4123343347@10.20.0.10) State REPORTING
2020-12-03 17:00:39.211409 [DEBUG] switch_core_state_machine.c:174 sofia/internal/4123343347@10.20.0.10 Standard REPORTING, cause: NORMAL_CLEARING
2020-12-03 17:00:39.211409 [DEBUG] switch_core_state_machine.c:936 (sofia/internal/4123343347@10.20.0.10) State REPORTING going to sleep
2020-12-03 17:00:39.211409 [DEBUG] switch_core_state_machine.c:611 (sofia/internal/4123343347@10.20.0.10) State Change CS_REPORTING -> CS_DESTROY
2020-12-03 17:00:39.211409 [DEBUG] switch_core_session.c:1726 Session 89 (sofia/internal/4123343347@10.20.0.10) Locked, Waiting on external entities
2020-12-03 17:00:39.211409 [NOTICE] switch_core_session.c:1744 Session 89 (sofia/internal/4123343347@10.20.0.10) Ended
2020-12-03 17:00:39.211409 [NOTICE] switch_core_session.c:1748 Close Channel sofia/internal/4123343347@10.20.0.10 [CS_DESTROY]
2020-12-03 17:00:39.211409 [DEBUG] switch_core_state_machine.c:739 (sofia/internal/4123343347@10.20.0.10) Running State Change CS_DESTROY (Cur 0 Tot 90)
2020-12-03 17:00:39.211409 [DEBUG] switch_core_state_machine.c:749 (sofia/internal/4123343347@10.20.0.10) State DESTROY
2020-12-03 17:00:39.211409 [DEBUG] mod_sofia.c:364 sofia/internal/4123343347@10.20.0.10 SOFIA DESTROY
2020-12-03 17:00:39.211409 [DEBUG] switch_core_state_machine.c:181 sofia/internal/4123343347@10.20.0.10 Standard DESTROY
2020-12-03 17:00:39.211409 [DEBUG] switch_core_state_machine.c:749 (sofia/internal/4123343347@10.20.0.10) State DESTROY going to sleep
nta.c:7145 _nta_incoming_timer() nta: timer I fired, terminate 200 response
nta.c:5830 incoming_reclaim_queued() incoming_reclaim_all((nil), (nil), 0x7f541440ca50)
nta.c:7199 _nta_incoming_timer() nta_incoming_timer: 0/0 resent, 0/0 tout, 1/12 term, 1/12 free
nta.c:1296 agent_timer() nta: timer set next to 294 ms
nta.c:9121 outgoing_timer_dk() nta: timer K fired, terminate BYE (28960825)
nta.c:8810 outgoing_reclaim_queued() outgoing_reclaim_all((nil), (nil), 0x7f541440cb20)
nta.c:8940 _nta_outgoing_timer() nta_outgoing_timer: 0/0 resent, 0/1 tout, 1/2 term, 1/3 free
nta.c:1296 agent_timer() nta: timer set next to 19471 ms
