[Freeswitch-users] Sudden call termination: [terminating][487]
Victor Bogatyryev
victor.bogatyryev at gmail.com
Sat Feb 22 07:37:06 UTC 2020
Hi,
Sudden call termination about 30 s after the connection has been
estableshed.
There is no record in the SIPTRACE about sending BYE to/from the UA.
tcpdump also does not see any SIP-related packets at the moment of call
termination. FS hungup the channel but the UA continues to send rtp.
tport.c:2782 tport_wakeup() tport_wakeup(0x7f30800a2f80): events IN
tport.c:2880 tport_recv_event() tport_recv_event(0x7f30800a2f80)
tport_type_tls.c:434 tport_tls_recv() tport_tls_recv(0x7f30800a2f80):
tls_read() returned 1372
tport.c:3221 tport_recv_iovec() tport_recv_iovec(0x7f30800a2f80) msg
0x7f30800e2e50 from (tls/33.2.151.64:2210) has 1372 bytes, veclen = 1
tport.c:3039 tport_deliver() tport_deliver(0x7f30800a2f80): msg
0x7f30800e2e50 (1372 bytes) from tls/33.2.151.64:2210/sips next=(nil)
nta.c:2880 agent_recv_request() nta: received INVITE
sip:009197 at 6.27.9.120:5061 SIP/2.0 (CSeq 50)
nta.c:3174 agent_check_request_via() nta: Via check: received=33.2.151.64
nta.c:3085 agent_recv_request() nta: INVITE (50) going to a default leg
nta.c:1348 set_timeout() nta: timer shortened to 2000 ms
nua_server.c:102 nua_stack_process_request() nua:
nua_stack_process_request: entering
nua_stack.c:899 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::0x7f3080044490, 0x7f3080043c90,
0x7f3080063290) called
soa.c:403 soa_set_params() soa_set_params(static::0x7f30800d65b0, ...)
called
nta.c:4417 nta_leg_tcreate() nta_leg_tcreate(0x7f30800f2c50)
soa.c:1302 soa_init_offer_answer()
soa_init_offer_answer(static::0x7f30800d65b0) called
soa.c:1171 soa_set_remote_sdp()
soa_set_remote_sdp(static::0x7f30800d65b0, (nil), 0x7f30800eb52f, 637)
called
nua_dialog.c:338 nua_dialog_usage_add() nua(0x7f3080063290): adding
session usage
nua_stack.c:271 nua_stack_event() nua(0x7f3080063290): event i_invite
100 Trying
nua_session.c:4143 signal_call_state_change() nua(0x7f3080063290): call
state changed: init -> received, received offer
soa.c:1098 soa_get_remote_sdp()
soa_get_remote_sdp(static::0x7f30800d65b0, [0x7f30a14f97b8],
[0x7f30a14f97c0], [(nil)]) called
nua_stack.c:271 nua_stack_event() nua(0x7f3080063290): event i_state 100
Trying
tport.c:2302 tport_set_secondary_timer() tport(0x7f30800a2f80): reset timer
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering
2020-02-22 08:56:56.867070 [NOTICE] switch_channel.c:1118 New Channel
sofia/external/1000 at 6.27.9.120:5061 [223734d0-5538-11ea-bbfb-e979e915e05b]
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
2020-02-22 08:56:56.867070 [DEBUG] switch_core_state_machine.c:585
(sofia/external/1000 at 6.27.9.120:5061) Running State Change CS_NEW (Cur 1
Tot 9)
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2020-02-22 08:56:56.867070 [DEBUG] sofia.c:10255
sofia/external/1000 at 6.27.9.120:5061 receiving invite from
33.2.151.64:2210 version: 1.10.2-release git f7bdd38 2019-12-31
14:01:19Z 64bit
nua.c:610 nua_set_hparams() nua: nua_set_hparams: entering
nua_stack.c:569 nua_stack_signal() nua(0x7f3080063290): recv signal
r_set_params
nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:403 soa_set_params() soa_set_params(static::0x7f30800d65b0, ...)
called
nua_stack.c:271 nua_stack_event() nua(0x7f3080063290): event
r_set_params 200 OK
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua_stack.c:529 nua_signal() nua(0x7f3080063290): sent signal r_set_params
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2020-02-22 08:56:56.867070 [DEBUG] sofia.c:7301 Channel
sofia/external/1000 at 6.27.9.120:5061 entering state [received][100]
2020-02-22 08:56:56.867070 [DEBUG] sofia.c:7311 Remote SDP:
v=0
o=1000 8002 8000 IN IP4 192.168.2.5
s=SIP Call
c=IN IP4 192.168.2.5
t=0 0
m=audio 5012 RTP/SAVP 8 0 4 18 97 102 2 103 101
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:4 G723/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:97 iLBC/8000
a=fmtp:97 mode=30
a=rtpmap:102 G729E/8000
a=rtpmap:2 G726-32/8000
a=rtpmap:103 AAL2-G726-40/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16,32-36,54
a=ptime:20
a=crypto:1 AES_CM_128_HMAC_SHA1_80
inline:djoxnaC5dQ7mre6tjhfK13Ca1sBgQKEIBjQab653|2^32
a=crypto:2 AES_CM_128_HMAC_SHA1_32
inline:SCSxesFRMzZfGeNNxnFkkUjUKx6Ui182k2VqrtUY|2^32
2020-02-22 08:56:56.867070 [DEBUG] sofia.c:7714
(sofia/external/1000 at 6.27.9.120:5061) State Change CS_NEW -> CS_INIT
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-02-22 08:56:56.867070 [DEBUG] switch_core_state_machine.c:604
(sofia/external/1000 at 6.27.9.120:5061) State NEW
2020-02-22 08:56:56.867070 [DEBUG] switch_core_state_machine.c:585
(sofia/external/1000 at 6.27.9.120:5061) Running State Change CS_INIT (Cur
1 Tot 9)
2020-02-22 08:56:56.867070 [DEBUG] switch_core_state_machine.c:628
(sofia/external/1000 at 6.27.9.120:5061) State INIT
2020-02-22 08:56:56.867070 [DEBUG] mod_sofia.c:93
sofia/external/1000 at 6.27.9.120:5061 SOFIA INIT
2020-02-22 08:56:56.867070 [DEBUG] switch_core_state_machine.c:40
sofia/external/1000 at 6.27.9.120:5061 Standard INIT
2020-02-22 08:56:56.867070 [DEBUG] switch_core_state_machine.c:48
(sofia/external/1000 at 6.27.9.120:5061) State Change CS_INIT -> CS_ROUTING
2020-02-22 08:56:56.867070 [DEBUG] switch_core_state_machine.c:628
(sofia/external/1000 at 6.27.9.120:5061) State INIT going to sleep
2020-02-22 08:56:56.867070 [DEBUG] switch_core_state_machine.c:585
(sofia/external/1000 at 6.27.9.120:5061) Running State Change CS_ROUTING
(Cur 1 Tot 9)
2020-02-22 08:56:56.867070 [DEBUG] switch_channel.c:2332
(sofia/external/1000 at 6.27.9.120:5061) Callstate Change DOWN -> RINGING
2020-02-22 08:56:56.867070 [DEBUG] switch_core_state_machine.c:644
(sofia/external/1000 at 6.27.9.120:5061) State ROUTING
nua.c:879 nua_respond() nua: nua_respond: entering
nua_stack.c:573 nua_stack_signal() nua(0x7f3080063290): 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::0x7f30800d65b0, ...)
called
tport.c:3273 tport_tsend() tport_tsend(0x7f30800a2f80) tpn =
TLS/33.2.151.64:2210
tport_type_tls.c:537 tport_tls_send() tport_tls_writevec: vec
0x7f30800a3420 0x7f30800ebe20 379 (379)
tport.c:3610 tport_vsend() tport_vsend(0x7f30800a2f80): 379 bytes of 379
to tls/33.2.151.64:2210
tport.c:3508 tport_send_msg() tport_vsend returned 379
tport.c:2302 tport_set_secondary_timer() tport(0x7f30800a2f80): reset timer
nta.c:6797 incoming_reply() nta: sent 100 Trying for INVITE (50)
nua_stack.c:529 nua_signal() nua(0x7f3080063290): sent signal r_respond
2020-02-22 08:56:56.867070 [DEBUG] mod_sofia.c:154
sofia/external/1000 at 6.27.9.120:5061 SOFIA ROUTING
2020-02-22 08:56:56.867070 [DEBUG] switch_core_state_machine.c:236
sofia/external/1000 at 6.27.9.120:5061 Standard ROUTING
2020-02-22 08:56:56.867070 [INFO] mod_dialplan_xml.c:637 Processing 1000
<1000>->009197 in context public
Dialplan: sofia/external/1000 at 6.27.9.120:5061 parsing [public->unloop]
continue=false
Dialplan: sofia/external/1000 at 6.27.9.120:5061 Regex (PASS) [unloop]
${unroll_loops}(true) =~ /^true$/ break=on-false
Dialplan: sofia/external/1000 at 6.27.9.120:5061 Regex (FAIL) [unloop]
${sip_looped_call}() =~ /^true$/ break=on-false
Dialplan: sofia/external/1000 at 6.27.9.120:5061 parsing
[public->outside_call] continue=true
Dialplan: sofia/external/1000 at 6.27.9.120:5061 Absolute Condition
[outside_call]
Dialplan: sofia/external/1000 at 6.27.9.120:5061 Action set(outside_call=true)
Dialplan: sofia/external/1000 at 6.27.9.120:5061 Action
export(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
Dialplan: sofia/external/1000 at 6.27.9.120:5061 parsing
[public->call_debug] continue=true
Dialplan: sofia/external/1000 at 6.27.9.120:5061 Regex (FAIL) [call_debug]
${call_debug}(false) =~ /^true$/ break=never
Dialplan: sofia/external/1000 at 6.27.9.120:5061 parsing
[public->public_extensions] continue=false
Dialplan: sofia/external/1000 at 6.27.9.120:5061 Regex (FAIL)
[public_extensions] destination_number(009197) =~ /^(10[01][0-9])$/
break=on-false
Dialplan: sofia/external/1000 at 6.27.9.120:5061 parsing
[public->public_conference_extensions] continue=false
Dialplan: sofia/external/1000 at 6.27.9.120:5061 Regex (FAIL)
[public_conference_extensions] destination_number(009197) =~
/^(3[5-8][01][0-9])$/ break=on-false
Dialplan: sofia/external/1000 at 6.27.9.120:5061 parsing
[public->public_did] continue=false
Dialplan: sofia/external/1000 at 6.27.9.120:5061 Regex (FAIL) [public_did]
destination_number(009197) =~ /^(5551212)$/ break=on-false
Dialplan: sofia/external/1000 at 6.27.9.120:5061 parsing [public->us1_ipv6]
continue=false
Dialplan: sofia/external/1000 at 6.27.9.120:5061 Regex (PASS) [us1_ipv6]
destination_number(009197) =~ /^00(\d{3,})$/ break=on-false
Dialplan: sofia/external/1000 at 6.27.9.120:5061 Action
export(inbound_late_negotiation=true)
Dialplan: sofia/external/1000 at 6.27.9.120:5061 Action
export(inbound_zrtp_passthru=false)
Dialplan: sofia/external/1000 at 6.27.9.120:5061 Action
set(rtp_secure_media=mandatory:AES_CM_128_HMAC_SHA1_80)
Dialplan: sofia/external/1000 at 6.27.9.120:5061 Action
export(absolute_codec_string=PCMA)
Dialplan: sofia/external/1000 at 6.27.9.120:5061 Action
set(ringback=%(2000,4000,440,480))
Dialplan: sofia/external/1000 at 6.27.9.120:5061 Action
bridge([rtp_secure_media=mandatory:AEAD_AES_256_GCM_8]sofia/gateway/us1_ipv6/9197)
2020-02-22 08:56:56.867070 [DEBUG] switch_core_state_machine.c:287
(sofia/external/1000 at 6.27.9.120:5061) State Change CS_ROUTING -> CS_EXECUTE
2020-02-22 08:56:56.867070 [DEBUG] switch_core_state_machine.c:644
(sofia/external/1000 at 6.27.9.120:5061) State ROUTING going to sleep
2020-02-22 08:56:56.867070 [DEBUG] switch_core_state_machine.c:585
(sofia/external/1000 at 6.27.9.120:5061) Running State Change CS_EXECUTE
(Cur 1 Tot 9)
2020-02-22 08:56:56.867070 [DEBUG] switch_core_state_machine.c:651
(sofia/external/1000 at 6.27.9.120:5061) State EXECUTE
2020-02-22 08:56:56.867070 [DEBUG] mod_sofia.c:209
sofia/external/1000 at 6.27.9.120:5061 SOFIA EXECUTE
2020-02-22 08:56:56.867070 [DEBUG] switch_core_state_machine.c:329
sofia/external/1000 at 6.27.9.120:5061 Standard EXECUTE
EXECUTE [depth=0] sofia/external/1000 at 6.27.9.120:5061 set(outside_call=true)
2020-02-22 08:56:56.867070 [DEBUG] mod_dptools.c:1672 SET
sofia/external/1000 at 6.27.9.120:5061 [outside_call]=[true]
EXECUTE [depth=0] sofia/external/1000 at 6.27.9.120:5061
export(RFC2822_DATE=Sat, 22 Feb 2020 08:56:56 +0300)
2020-02-22 08:56:56.867070 [DEBUG] switch_channel.c:1310 EXPORT
(export_vars) [RFC2822_DATE]=[Sat, 22 Feb 2020 08:56:56 +0300]
EXECUTE [depth=0] sofia/external/1000 at 6.27.9.120:5061
export(inbound_late_negotiation=true)
2020-02-22 08:56:56.867070 [DEBUG] switch_channel.c:1310 EXPORT
(export_vars) [inbound_late_negotiation]=[true]
EXECUTE [depth=0] sofia/external/1000 at 6.27.9.120:5061
export(inbound_zrtp_passthru=false)
2020-02-22 08:56:56.867070 [DEBUG] switch_channel.c:1310 EXPORT
(export_vars) [inbound_zrtp_passthru]=[false]
EXECUTE [depth=0] sofia/external/1000 at 6.27.9.120:5061
set(rtp_secure_media=mandatory:AES_CM_128_HMAC_SHA1_80)
2020-02-22 08:56:56.867070 [DEBUG] mod_dptools.c:1672 SET
sofia/external/1000 at 6.27.9.120:5061
[rtp_secure_media]=[mandatory:AES_CM_128_HMAC_SHA1_80]
EXECUTE [depth=0] sofia/external/1000 at 6.27.9.120:5061
export(absolute_codec_string=PCMA)
2020-02-22 08:56:56.867070 [DEBUG] switch_channel.c:1310 EXPORT
(export_vars) [absolute_codec_string]=[PCMA]
EXECUTE [depth=0] sofia/external/1000 at 6.27.9.120:5061
set(ringback=%(2000,4000,440,480))
2020-02-22 08:56:56.867070 [DEBUG] mod_dptools.c:1672 SET
sofia/external/1000 at 6.27.9.120:5061 [ringback]=[%(2000,4000,440,480)]
EXECUTE [depth=0] sofia/external/1000 at 6.27.9.120:5061
bridge([rtp_secure_media=mandatory:AEAD_AES_256_GCM_8]sofia/gateway/us1_ipv6/9197)
2020-02-22 08:56:56.867070 [DEBUG] switch_channel.c:1264
sofia/external/1000 at 6.27.9.120:5061 EXPORTING[export_vars]
[RFC2822_DATE]=[Sat, 22 Feb 2020 08:56:56 +0300] to event
2020-02-22 08:56:56.867070 [DEBUG] switch_channel.c:1264
sofia/external/1000 at 6.27.9.120:5061 EXPORTING[export_vars]
[inbound_late_negotiation]=[true] to event
2020-02-22 08:56:56.867070 [DEBUG] switch_channel.c:1264
sofia/external/1000 at 6.27.9.120:5061 EXPORTING[export_vars]
[inbound_zrtp_passthru]=[false] to event
2020-02-22 08:56:56.867070 [DEBUG] switch_channel.c:1264
sofia/external/1000 at 6.27.9.120:5061 EXPORTING[export_vars]
[absolute_codec_string]=[PCMA] to event
2020-02-22 08:56:56.867070 [DEBUG] switch_ivr_originate.c:2212 Parsing
global variables
2020-02-22 08:56:56.867070 [DEBUG] switch_ivr_originate.c:2760 Parsing
session specific variables
2020-02-22 08:56:56.887055 [NOTICE] switch_channel.c:1118 New Channel
sofia/external-ipv6/9197 [22386314-5538-11ea-bc07-e979e915e05b]
2020-02-22 08:56:56.887055 [DEBUG] mod_sofia.c:5089
(sofia/external-ipv6/9197) State Change CS_NEW -> CS_INIT
2020-02-22 08:56:56.887055 [DEBUG] switch_core_state_machine.c:585
(sofia/external-ipv6/9197) Running State Change CS_INIT (Cur 2 Tot 10)
2020-02-22 08:56:56.887055 [DEBUG] switch_core_state_machine.c:628
(sofia/external-ipv6/9197) State INIT
2020-02-22 08:56:56.887055 [DEBUG] mod_sofia.c:93
sofia/external-ipv6/9197 SOFIA INIT
2020-02-22 08:56:56.887055 [DEBUG] switch_core_media.c:1215 Set Local
audio crypto Key [1 AEAD_AES_256_GCM_8
inline:l7g+SjnmyEXkdODYNoM4vjNljooxPJvFuumXJZM8OpgX52o5hnFWJ54qvhU=]
2020-02-22 08:56:56.887055 [DEBUG] switch_core_media.c:1215 Set Local
video crypto Key [1 AEAD_AES_256_GCM_8
inline:UCkQ762LUOckln/vOdFBmuNp6gow4IM4WLQxgp1vMJ4XJMY3YLrmmt2KRlg=]
2020-02-22 08:56:56.887055 [DEBUG] switch_core_media.c:1215 Set Local
text crypto Key [1 AEAD_AES_256_GCM_8
inline:b8+841hCfTOwh3wNzMustM9VWGHaCdw2kCm4rwH4LF9TLrpTUuLF8BhgnjI=]
nua_common.c:108 nh_create_handle() nua: nh_create_handle: entering
nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering
2020-02-22 08:56:56.887055 [DEBUG] sofia_glue.c:1618
sofia/external-ipv6/9197 sending invite version: 1.10.2-release git
f7bdd38 2019-12-31 14:01:19Z 64bit
Local SDP:
v=0
o=FreeSWITCH 1582333804 1582333805 IN IP6 2a2a:810b:a2ba::65
s=FreeSWITCH
c=IN IP6 2a2a:810b:a2ba::65
t=0 0
m=audio 17212 RTP/SAVP 8 101
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=crypto:1 AEAD_AES_256_GCM_8
inline:l7g+SjnmyEXkdODYNoM4vjNljooxPJvFuumXJZM8OpgX52o5hnFWJ54qvhU=
a=ptime:20
a=sendrecv
nua.c:633 nua_invite() nua: nua_invite: entering
nua_stack.c:569 nua_stack_signal() nua(0x18ca7e0): 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::0x7f307c0448f0, 0x7f307c0440f0,
0x18ca7e0) called
soa.c:403 soa_set_params() soa_set_params(static::0x7f307c0b7770, ...)
called
soa.c:403 soa_set_params() soa_set_params(static::0x7f307c0b7770, ...)
called
soa.c:1052 soa_set_user_sdp() soa_set_user_sdp(static::0x7f307c0b7770,
(nil), 0x17cec61, -1) called
soa.c:890 soa_set_capability_sdp()
soa_set_capability_sdp(static::0x7f307c0b7770, (nil), 0x17cec61, -1) called
nua_dialog.c:338 nua_dialog_usage_add() nua(0x18ca7e0): adding session usage
nta.c:4417 nta_leg_tcreate() nta_leg_tcreate(0x7f307c0bfdd0)
soa.c:1302 soa_init_offer_answer()
soa_init_offer_answer(static::0x7f307c0b7770) called
soa.c:1426 soa_generate_offer()
soa_generate_offer(static::0x7f307c0b7770, 0) called
soa_static.c:1148 offer_answer_step()
soa_static_offer_answer_action(0x7f307c0b7770, soa_generate_offer): called
soa_static.c:1189 offer_answer_step() soa_static(0x7f307c0b7770,
soa_generate_offer): generating local description
soa_static.c:1217 offer_answer_step() soa_static(0x7f307c0b7770,
soa_generate_offer): upgrade with local description
soa_static.c:1029 soa_sdp_mode_set() soa_sdp_mode_set(0x7f308b4e49f0,
(nil), ""): called
soa_static.c:1446 offer_answer_step() soa_static(0x7f307c0b7770,
soa_generate_offer): storing local description
soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x7f307c0b7770,
[(nil)], [0x7f308b4e6b28], [0x7f308b4e6b24]) called
nta.c:2665 nta_tpn_by_url() nta: selecting scheme sip
tport.c:4604 tport_by_name() tport(0x7f307c048c20): found 0x7f307c064180
by name tls/[2a01:7b30:a00f:62ba::3]:9999
tport.c:3273 tport_tsend() tport_tsend(0x7f307c064180) tpn =
tls/[2a01:7b30:a00f:62ba::3]:9999
tport_type_tls.c:537 tport_tls_send() tport_tls_writevec: vec
0x7f307c061870 0x7f307c0f0750 911 (911)
tport_type_tls.c:537 tport_tls_send() tport_tls_writevec: vec
0x7f307c061870 0x7f307c05d000 332 (332)
tport.c:3610 tport_vsend() tport_vsend(0x7f307c064180): 1243 bytes of
1243 to tls/[2a01:7b30:a00f:62ba::3]:9999
tport.c:3508 tport_send_msg() tport_vsend returned 1243
tport.c:2302 tport_set_secondary_timer() tport(0x7f307c064180): reset timer
nta.c:8310 outgoing_send() nta: sent INVITE (16621716) to
tls/[2a01:7b30:a00f:62ba::3]:9999
tport.c:4176 tport_pend() tport_pend(0x7f307c064180): pending
0x7f307c0ec980 for tls/[2a01:7b30:a00f:62ba::3]:9999 (already 1)
nua_session.c:4143 signal_call_state_change() nua(0x18ca7e0): call state
changed: init -> calling, sent offer
soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x7f307c0b7770,
[0x7f308b4e6b08], [0x7f308b4e6b10], [(nil)]) called
nua_stack.c:269 nua_stack_event() nua(0x18ca7e0): event i_state INVITE sent
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua_stack.c:529 nua_signal() nua(0x18ca7e0): sent signal r_invite
2020-02-22 08:56:56.887055 [DEBUG] switch_core_state_machine.c:40
sofia/external-ipv6/9197 Standard INIT
2020-02-22 08:56:56.887055 [DEBUG] switch_core_state_machine.c:48
(sofia/external-ipv6/9197) State Change CS_INIT -> CS_ROUTING
2020-02-22 08:56:56.887055 [DEBUG] switch_core_state_machine.c:628
(sofia/external-ipv6/9197) State INIT going to sleep
2020-02-22 08:56:56.887055 [DEBUG] switch_core_state_machine.c:585
(sofia/external-ipv6/9197) Running State Change CS_ROUTING (Cur 2 Tot 10)
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2020-02-22 08:56:56.887055 [DEBUG] sofia.c:7301 Channel
sofia/external-ipv6/9197 entering state [calling][0]
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2020-02-22 08:56:56.887055 [DEBUG] switch_core_state_machine.c:644
(sofia/external-ipv6/9197) State ROUTING
2020-02-22 08:56:56.887055 [DEBUG] mod_sofia.c:154
sofia/external-ipv6/9197 SOFIA ROUTING
2020-02-22 08:56:56.887055 [DEBUG] switch_ivr_originate.c:67
(sofia/external-ipv6/9197) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2020-02-22 08:56:56.887055 [DEBUG] switch_core_state_machine.c:644
(sofia/external-ipv6/9197) State ROUTING going to sleep
2020-02-22 08:56:56.887055 [DEBUG] switch_core_state_machine.c:585
(sofia/external-ipv6/9197) Running State Change CS_CONSUME_MEDIA (Cur 2
Tot 10)
2020-02-22 08:56:56.887055 [DEBUG] switch_core_state_machine.c:663
(sofia/external-ipv6/9197) State CONSUME_MEDIA
2020-02-22 08:56:56.887055 [DEBUG] switch_core_state_machine.c:663
(sofia/external-ipv6/9197) State CONSUME_MEDIA going to sleep
tport.c:2782 tport_wakeup() tport_wakeup(0x7f307c064180): events IN
tport.c:2880 tport_recv_event() tport_recv_event(0x7f307c064180)
tport_type_tls.c:434 tport_tls_recv() tport_tls_recv(0x7f307c064180):
tls_read() returned 401
tport.c:3221 tport_recv_iovec() tport_recv_iovec(0x7f307c064180) msg
0x7f307c0acc80 from (tls/[2a01:7b30:a00f:62ba::3]:9999) has 401 bytes,
veclen = 1
tport.c:3039 tport_deliver() tport_deliver(0x7f307c064180): msg
0x7f307c0acc80 (401 bytes) from tls/[2a01:7b30:a00f:62ba::3]:9999/sips
next=(nil)
nta.c:3299 agent_recv_response() nta: received 100 Trying for INVITE
(16621716)
nta.c:3366 agent_recv_response() nta: 100 Trying is going to a transaction
nta.c:9570 outgoing_estimate_delay() nta_outgoing: RTT is 23.315 ms
tport.c:4238 tport_release() tport_release(0x7f307c064180):
0x7f307c0ec980 by 0x7f307c0b1410 with 0x7f307c0acc80 (preliminary)
tport.c:2302 tport_set_secondary_timer() tport(0x7f307c064180): reset timer
tport.c:2782 tport_wakeup() tport_wakeup(0x7f307c064180): events IN
tport.c:2880 tport_recv_event() tport_recv_event(0x7f307c064180)
tport_type_tls.c:434 tport_tls_recv() tport_tls_recv(0x7f307c064180):
tls_read() returned 955
tport.c:3221 tport_recv_iovec() tport_recv_iovec(0x7f307c064180) msg
0x7f307c0acc80 from (tls/[2a01:7b30:a00f:62ba::3]:9999) has 955 bytes,
veclen = 1
tport.c:2302 tport_set_secondary_timer() tport(0x7f307c064180): reset timer
tport.c:2782 tport_wakeup() tport_wakeup(0x7f307c064180): events IN
tport.c:2880 tport_recv_event() tport_recv_event(0x7f307c064180)
tport_type_tls.c:434 tport_tls_recv() tport_tls_recv(0x7f307c064180):
tls_read() returned 340
tport.c:3221 tport_recv_iovec() tport_recv_iovec(0x7f307c064180) msg
0x7f307c0acc80 from (tls/[2a01:7b30:a00f:62ba::3]:9999) has 340 bytes,
veclen = 1
tport.c:3039 tport_deliver() tport_deliver(0x7f307c064180): msg
0x7f307c0acc80 (1295 bytes) from tls/[2a01:7b30:a00f:62ba::3]:9999/sips
next=(nil)
nta.c:3299 agent_recv_response() nta: received 200 OK for INVITE (16621716)
nta.c:3366 agent_recv_response() nta: 200 OK is going to a transaction
tport.c:4238 tport_release() tport_release(0x7f307c064180):
0x7f307c0ec980 by 0x7f307c0b1410 with 0x7f307c0acc80
soa.c:1171 soa_set_remote_sdp()
soa_set_remote_sdp(static::0x7f307c0b7770, (nil), 0x7f307c0ed3b0, 340)
called
soa.c:1595 soa_process_answer()
soa_process_answer(static::0x7f307c0b7770) called
soa_static.c:1148 offer_answer_step()
soa_static_offer_answer_action(0x7f307c0b7770, soa_process_answer): called
soa_static.c:1029 soa_sdp_mode_set() soa_sdp_mode_set(0x7f309804da10,
0x7f308c016280, ""): called
soa_static.c:1304 offer_answer_step() soa_static(0x7f307c0b7770,
soa_process_answer): upgrade codecs with remote description
soa.c:1730 soa_activate() soa_activate(static::0x7f307c0b7770, (nil)) called
nua_session.c:992 nua_session_client_response() nua(0x18ca7e0): INVITE:
processed SDP answer in 200 OK (200)
nua_stack.c:271 nua_stack_event() nua(0x18ca7e0): event r_invite 200 OK
nua_session.c:4143 signal_call_state_change() nua(0x18ca7e0): call state
changed: calling -> completing, received answer
soa.c:1098 soa_get_remote_sdp()
soa_get_remote_sdp(static::0x7f307c0b7770, [0x7f308b4e6558],
[0x7f308b4e6560], [(nil)]) called
soa.c:616 soa_get_params() soa_get_params(static::0x7f307c0b7770, ...)
called
nua_stack.c:271 nua_stack_event() nua(0x18ca7e0): event i_state 200 OK
tport.c:2302 tport_set_secondary_timer() tport(0x7f307c064180): reset timer
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-02-22 08:56:57.927086 [INFO] sofia.c:1369 sofia/external-ipv6/9197
Update Callee ID to "9197" <sip:9197@[2a01:7b30:a00f:62ba::3]>
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2020-02-22 08:56:57.927086 [DEBUG] sofia.c:7301 Channel
sofia/external-ipv6/9197 entering state [completing][200]
2020-02-22 08:56:57.927086 [DEBUG] sofia.c:7311 Remote SDP:
v=0
o=FreeSWITCH 1582325031 1582325032 IN IP6 2a01:7b30:a00f:62ba::3
s=FreeSWITCH
c=IN IP6 2a01:7b30:a00f:62ba::3
t=0 0
m=audio 25986 RTP/SAVP 8 101
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=crypto:1 AEAD_AES_256_GCM_8
inline:YtCNFeeP7Nfe5QM64JWmcNBBdpwXAYEG3ZJ2e0aKTFJBhhiR4CCieyro68E=
nua.c:639 nua_ack() nua: nua_ack: entering
nua_stack.c:569 nua_stack_signal() nua(0x18ca7e0): 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::0x7f307c0b7770, ...)
called
soa.c:1730 soa_activate() soa_activate(static::0x7f307c0b7770, (nil)) called
nta.c:2665 nta_tpn_by_url() nta: selecting scheme sip
tport.c:4604 tport_by_name() tport(0x7f307c048c20): found 0x7f307c064180
by name tls/[2a01:7b30:a00f:62ba::3]:9999
tport.c:3273 tport_tsend() tport_tsend(0x7f307c064180) tpn =
tls/[2a01:7b30:a00f:62ba::3]:9999
tport_type_tls.c:537 tport_tls_send() tport_tls_writevec: vec
0x7f307c061870 0x7f307c0b4a50 461 (461)
tport.c:3610 tport_vsend() tport_vsend(0x7f307c064180): 461 bytes of 461
to tls/[2a01:7b30:a00f:62ba::3]:9999
tport.c:3508 tport_send_msg() tport_vsend returned 461
tport.c:2302 tport_set_secondary_timer() tport(0x7f307c064180): reset timer
nta.c:8310 outgoing_send() nta: sent ACK (16621716) to
tls/[2a01:7b30:a00f:62ba::3]:9999
nua_session.c:4143 signal_call_state_change() nua(0x18ca7e0): call state
changed: completing -> ready
nua_stack.c:271 nua_stack_event() nua(0x18ca7e0): event i_state 200 ACK sent
nua_stack.c:271 nua_stack_event() nua(0x18ca7e0): 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:529 nua_signal() nua(0x18ca7e0): sent signal r_ack
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2020-02-22 08:56:57.927086 [DEBUG] sofia.c:7301 Channel
sofia/external-ipv6/9197 entering state [ready][200]
2020-02-22 08:56:57.927086 [DEBUG] switch_core_media.c:1813 looking for
crypto suite [AEAD_AES_256_GCM_8]alias=[] in [1 AEAD_AES_256_GCM_8
inline:YtCNFeeP7Nfe5QM64JWmcNBBdpwXAYEG3ZJ2e0aKTFJBhhiR4CCieyro68E=]
2020-02-22 08:56:57.927086 [DEBUG] switch_core_media.c:1822 Found suite
AEAD_AES_256_GCM_8
2020-02-22 08:56:57.927086 [DEBUG] switch_core_media.c:1892 Set Remote
Key [1 AEAD_AES_256_GCM_8
inline:YtCNFeeP7Nfe5QM64JWmcNBBdpwXAYEG3ZJ2e0aKTFJBhhiR4CCieyro68E=]
2020-02-22 08:56:57.927086 [DEBUG] switch_core_media.c:5592 Audio Codec
Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2020-02-22 08:56:57.927086 [DEBUG] switch_core_media.c:5647 Audio Codec
Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
2020-02-22 08:56:57.927086 [DEBUG] switch_core_media.c:5508 Set
telephone-event payload to 101 at 8000
2020-02-22 08:56:57.927086 [DEBUG] switch_core_media.c:3837 Set Codec
sofia/external-ipv6/9197 PCMA/8000 20 ms 160 samples 64000 bits 1 channels
2020-02-22 08:56:57.927086 [DEBUG] switch_core_codec.c:111
sofia/external-ipv6/9197 Original read codec set to PCMA:8
2020-02-22 08:56:57.927086 [DEBUG] switch_core_media.c:5851 Set
telephone-event payload to 101 at 8000
2020-02-22 08:56:57.927086 [DEBUG] switch_core_media.c:5909
sofia/external-ipv6/9197 Set 2833 dtmf send payload to 101 recv payload
to 101
2020-02-22 08:56:57.927086 [DEBUG] switch_core_media.c:8659 AUDIO RTP
[sofia/external-ipv6/9197] 2a2a:810b:a2ba::65 port 17212 ->
2a01:7b30:a00f:62ba::3 port 25986 codec: 8 ms: 20
2020-02-22 08:56:57.927086 [DEBUG] switch_rtp.c:4430 Not using a timer
2020-02-22 08:56:57.947037 [DEBUG] switch_core_media.c:8973
sofia/external-ipv6/9197 Set 2833 dtmf send payload to 101
2020-02-22 08:56:57.947037 [DEBUG] switch_core_media.c:8980
sofia/external-ipv6/9197 Set 2833 dtmf receive payload to 101
2020-02-22 08:56:57.947037 [DEBUG] switch_core_media.c:9003
sofia/external-ipv6/9197 Set rtp dtmf delay to 40
2020-02-22 08:56:57.947037 [INFO] switch_rtp.c:4212 Activating audio
Secure RTP SEND
2020-02-22 08:56:57.947037 [DEBUG] switch_core_sqldb.c:2827 Secure Type:
srtp:sdes:AEAD_AES_256_GCM_8
2020-02-22 08:56:57.947037 [INFO] switch_rtp.c:4190 Activating audio
Secure RTP RECV
2020-02-22 08:56:57.947037 [DEBUG] switch_core_sqldb.c:2827 Secure Type:
srtp:sdes:AEAD_AES_256_GCM_8
2020-02-22 08:56:57.947037 [NOTICE] sofia.c:8479 Channel
[sofia/external-ipv6/9197] has been answered
2020-02-22 08:56:57.947037 [DEBUG] switch_channel.c:3865
(sofia/external-ipv6/9197) Callstate Change DOWN -> ACTIVE
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-02-22 08:56:57.967059 [DEBUG] switch_core_media.c:1813 looking for
crypto suite [AES_CM_128_HMAC_SHA1_80]alias=[] in [1
AES_CM_128_HMAC_SHA1_80
inline:djoxnaC5dQ7mre6tjhfK13Ca1sBgQKEIBjQab653|2^32]
2020-02-22 08:56:57.967059 [DEBUG] switch_core_media.c:1822 Found suite
AES_CM_128_HMAC_SHA1_80
2020-02-22 08:56:57.967059 [DEBUG] switch_core_media.c:1892 Set Remote
Key [1 AES_CM_128_HMAC_SHA1_80
inline:djoxnaC5dQ7mre6tjhfK13Ca1sBgQKEIBjQab653|2^32]
2020-02-22 08:56:57.967059 [DEBUG] switch_core_media.c:1215 Set Local
audio crypto Key [1 AES_CM_128_HMAC_SHA1_80
inline:1FV79mvFW9EJ0Kzoz54tK71JzkmM8BYeOYcUd+uP]
2020-02-22 08:56:57.967059 [DEBUG] switch_core_media.c:5592 Audio Codec
Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2020-02-22 08:56:57.967059 [DEBUG] switch_core_media.c:5647 Audio Codec
Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
2020-02-22 08:56:57.967059 [DEBUG] switch_core_media.c:5592 Audio Codec
Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2020-02-22 08:56:57.967059 [DEBUG] switch_core_media.c:5592 Audio Codec
Compare [G723:4:8000:20:6300:1]/[PCMA:8:8000:20:64000:1]
2020-02-22 08:56:57.967059 [DEBUG] switch_core_media.c:5592 Audio Codec
Compare [G729:18:8000:20:8000:1]/[PCMA:8:8000:20:64000:1]
2020-02-22 08:56:57.967059 [DEBUG] switch_core_media.c:5592 Audio Codec
Compare [iLBC:97:8000:20:0:1]/[PCMA:8:8000:20:64000:1]
2020-02-22 08:56:57.967059 [DEBUG] switch_core_media.c:5592 Audio Codec
Compare [G729E:102:8000:20:0:1]/[PCMA:8:8000:20:64000:1]
2020-02-22 08:56:57.967059 [DEBUG] switch_core_media.c:5592 Audio Codec
Compare [G726-32:2:8000:20:0:1]/[PCMA:8:8000:20:64000:1]
2020-02-22 08:56:57.967059 [DEBUG] switch_core_media.c:5592 Audio Codec
Compare [AAL2-G726-40:103:8000:20:0:1]/[PCMA:8:8000:20:64000:1]
2020-02-22 08:56:57.967059 [DEBUG] switch_core_media.c:5508 Set
telephone-event payload to 101 at 8000
2020-02-22 08:56:57.967059 [DEBUG] switch_core_media.c:3837 Set Codec
sofia/external/1000 at 6.27.9.120:5061 PCMA/8000 20 ms 160 samples 64000
bits 1 channels
2020-02-22 08:56:57.967059 [DEBUG] switch_core_codec.c:111
sofia/external/1000 at 6.27.9.120:5061 Original read codec set to PCMA:8
2020-02-22 08:56:57.967059 [DEBUG] switch_core_media.c:5851 Set
telephone-event payload to 101 at 8000
2020-02-22 08:56:57.967059 [DEBUG] switch_core_media.c:5909
sofia/external/1000 at 6.27.9.120:5061 Set 2833 dtmf send payload to 101
recv payload to 101
2020-02-22 08:56:57.967059 [DEBUG] switch_core_media.c:8659 AUDIO RTP
[sofia/external/1000 at 6.27.9.120:5061] 6.27.9.120 port 27568 ->
192.168.2.5 port 5012 codec: 8 ms: 20
2020-02-22 08:56:57.967059 [DEBUG] switch_rtp.c:4408 Starting timer
[timerfd] 160 bytes per 20ms
nta.c:1289 agent_timer() nta: timer not set
2020-02-22 08:56:59.027038 [DEBUG] switch_core_media.c:8973
sofia/external/1000 at 6.27.9.120:5061 Set 2833 dtmf send payload to 101
2020-02-22 08:56:59.027038 [DEBUG] switch_core_media.c:8980
sofia/external/1000 at 6.27.9.120:5061 Set 2833 dtmf receive payload to 101
2020-02-22 08:56:59.027038 [DEBUG] switch_core_media.c:9003
sofia/external/1000 at 6.27.9.120:5061 Set rtp dtmf delay to 40
2020-02-22 08:56:59.027038 [DEBUG] switch_core_media.c:1501 LIFETIME
found in |2^32, base 2 exp 32
2020-02-22 08:56:59.027038 [NOTICE] switch_core_media.c:1524 Skipping
MKI due to empty index
2020-02-22 08:56:59.027038 [INFO] switch_rtp.c:4212 Activating audio
Secure RTP SEND
2020-02-22 08:56:59.027038 [DEBUG] switch_core_sqldb.c:2827 Secure Type:
srtp:sdes:AES_CM_128_HMAC_SHA1_80
2020-02-22 08:56:59.027038 [INFO] switch_rtp.c:4190 Activating audio
Secure RTP RECV
2020-02-22 08:56:59.027038 [DEBUG] switch_core_sqldb.c:2827 Secure Type:
srtp:sdes:AES_CM_128_HMAC_SHA1_80
2020-02-22 08:56:59.027038 [NOTICE] sofia_media.c:92 Pre-Answer
sofia/external/1000 at 6.27.9.120:5061!
2020-02-22 08:56:59.027038 [DEBUG] switch_channel.c:3565
(sofia/external/1000 at 6.27.9.120:5061) Callstate Change RINGING -> EARLY
2020-02-22 08:56:59.027038 [DEBUG] switch_core_media.c:8641 Audio params
are unchanged for sofia/external/1000 at 6.27.9.120:5061.
2020-02-22 08:56:59.027038 [DEBUG] mod_sofia.c:898 Local SDP
sofia/external/1000 at 6.27.9.120:5061:
v=0
o=FreeSWITCH 1582323451 1582323452 IN IP4 6.27.9.120
s=FreeSWITCH
c=IN IP4 6.27.9.120
t=0 0
m=audio 27568 RTP/SAVP 8 101
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv
a=crypto:1 AES_CM_128_HMAC_SHA1_80
inline:1FV79mvFW9EJ0Kzoz54tK71JzkmM8BYeOYcUd+uP
nua.c:879 nua_respond() nua: nua_respond: entering
nua_stack.c:573 nua_stack_signal() nua(0x7f3080063290): 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::0x7f30800d65b0, ...)
called
soa.c:1052 soa_set_user_sdp() soa_set_user_sdp(static::0x7f30800d65b0,
(nil), 0x7f309c050042, -1) called
soa.c:890 soa_set_capability_sdp()
soa_set_capability_sdp(static::0x7f30800d65b0, (nil), 0x7f309c050042,
-1) called
nua_session.c:2324 nua_invite_server_respond() nua:
nua_invite_server_respond: entering
soa.c:1515 soa_generate_answer()
soa_generate_answer(static::0x7f30800d65b0) called
soa_static.c:1148 offer_answer_step()
soa_static_offer_answer_action(0x7f30800d65b0, soa_generate_answer): called
soa_static.c:1189 offer_answer_step() soa_static(0x7f30800d65b0,
soa_generate_answer): generating local description
soa_static.c:1230 offer_answer_step() soa_static(0x7f30800d65b0,
soa_generate_answer): upgrade with remote description
soa_static.c:1029 soa_sdp_mode_set() soa_sdp_mode_set(0x7f30a14f7a20,
0x7f30800e2250, ""): called
soa_static.c:1446 offer_answer_step() soa_static(0x7f30800d65b0,
soa_generate_answer): storing local description
soa.c:1730 soa_activate() soa_activate(static::0x7f30800d65b0, (nil)) called
soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x7f30800d65b0,
[(nil)], [0x7f30a14f9b58], [0x7f30a14f9b54]) called
tport.c:3273 tport_tsend() tport_tsend(0x7f30800a2f80) tpn =
TLS/33.2.151.64:2210
tport_type_tls.c:537 tport_tls_send() tport_tls_writevec: vec
0x7f30800a3420 0x7f3080068f70 758 (758)
tport_type_tls.c:537 tport_tls_send() tport_tls_writevec: vec
0x7f30800a3420 0x7f30800a0e50 305 (305)
tport.c:3610 tport_vsend() tport_vsend(0x7f30800a2f80): 1063 bytes of
1063 to tls/33.2.151.64:2210
tport.c:3508 tport_send_msg() tport_vsend returned 1063
tport.c:2302 tport_set_secondary_timer() tport(0x7f30800a2f80): reset timer
nta.c:6797 incoming_reply() nta: sent 200 OK for INVITE (50)
nta.c:1350 set_timeout() nta: timer set to 500 ms
nua_session.c:4143 signal_call_state_change() nua(0x7f3080063290): call
state changed: received -> completed, sent answer
soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x7f30800d65b0,
[0x7f30a14f9c08], [0x7f30a14f9c10], [(nil)]) called
soa.c:616 soa_get_params() soa_get_params(static::0x7f30800d65b0, ...)
called
nua_stack.c:271 nua_stack_event() nua(0x7f3080063290): event i_state 200 OK
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua_stack.c:529 nua_signal() nua(0x7f3080063290): sent signal r_respond
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2020-02-22 08:56:59.027038 [DEBUG] sofia.c:7301 Channel
sofia/external/1000 at 6.27.9.120:5061 entering state [completed][200]
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2020-02-22 08:56:59.027038 [NOTICE] switch_ivr_originate.c:3751 Channel
[sofia/external/1000 at 6.27.9.120:5061] has been answered
2020-02-22 08:56:59.027038 [DEBUG] switch_channel.c:3865
(sofia/external/1000 at 6.27.9.120:5061) Callstate Change EARLY -> ACTIVE
2020-02-22 08:56:59.027038 [DEBUG] switch_ivr_originate.c:3809 Originate
Resulted in Success: [sofia/external-ipv6/9197]
2020-02-22 08:56:59.027038 [DEBUG] switch_ivr_bridge.c:1796
(sofia/external-ipv6/9197) State Change CS_CONSUME_MEDIA ->
CS_EXCHANGE_MEDIA
2020-02-22 08:56:59.027038 [DEBUG] switch_core_state_machine.c:585
(sofia/external-ipv6/9197) Running State Change CS_EXCHANGE_MEDIA (Cur 2
Tot 10)
2020-02-22 08:56:59.027038 [DEBUG] switch_core_state_machine.c:654
(sofia/external-ipv6/9197) State EXCHANGE_MEDIA
2020-02-22 08:56:59.027038 [DEBUG] mod_sofia.c:656 SOFIA EXCHANGE_MEDIA
2020-02-22 08:56:59.027038 [DEBUG] switch_rtp.c:7720 Correct audio
ip/port confirmed.
tport.c:2782 tport_wakeup() tport_wakeup(0x7f30800a2f80): events IN
tport.c:2880 tport_recv_event() tport_recv_event(0x7f30800a2f80)
tport_type_tls.c:434 tport_tls_recv() tport_tls_recv(0x7f30800a2f80):
tls_read() returned 568
tport.c:3221 tport_recv_iovec() tport_recv_iovec(0x7f30800a2f80) msg
0x7f30800f0fc0 from (tls/33.2.151.64:2210) has 568 bytes, veclen = 1
tport.c:3039 tport_deliver() tport_deliver(0x7f30800a2f80): msg
0x7f30800f0fc0 (568 bytes) from tls/33.2.151.64:2210/sips next=(nil)
nta.c:2880 agent_recv_request() nta: received ACK
sip:009197 at 6.27.9.120:6666;transport=tls SIP/2.0 (CSeq 50)
nta.c:3174 agent_check_request_via() nta: Via check: received=33.2.151.64
nta.c:3019 agent_recv_request() nta: ACK (50) is going to INVITE (50)
nua_session.c:2573 process_ack_or_cancel() nua: process_ack_or_cancel:
entering
soa.c:1214 soa_clear_remote_sdp()
soa_clear_remote_sdp(static::0x7f30800d65b0) called
nua_stack.c:271 nua_stack_event() nua(0x7f3080063290): event i_ack 200 OK
nua_session.c:4143 signal_call_state_change() nua(0x7f3080063290): call
state changed: completed -> ready
nua_stack.c:271 nua_stack_event() nua(0x7f3080063290): event i_state 200 OK
nua_stack.c:271 nua_stack_event() nua(0x7f3080063290): event i_active
200 Call active
nta.c:5744 incoming_free() nta: incoming_free(0x7f30800cc750)
tport.c:2302 tport_set_secondary_timer() tport(0x7f30800a2f80): reset timer
tport.c:2302 tport_set_secondary_timer() tport(0x7f30800a2f80): reset timer
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
2020-02-22 08:56:59.127093 [DEBUG] sofia.c:7301 Channel
sofia/external/1000 at 6.27.9.120:5061 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
nua.c:798 nua_info() nua: nua_info: entering
nua_stack.c:569 nua_stack_signal() nua(0x18ca7e0): recv signal r_info
nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:403 soa_set_params() soa_set_params(static::0x7f307c0b7770, ...)
called
nta.c:2665 nta_tpn_by_url() nta: selecting scheme sip
tport.c:4604 tport_by_name() tport(0x7f307c048c20): found 0x7f307c064180
by name tls/[2a01:7b30:a00f:62ba::3]:9999
tport.c:3273 tport_tsend() tport_tsend(0x7f307c064180) tpn =
tls/[2a01:7b30:a00f:62ba::3]:9999
tport_type_tls.c:537 tport_tls_send() tport_tls_writevec: vec
0x7f307c061870 0x7f307c0f9130 764 (764)
tport.c:3610 tport_vsend() tport_vsend(0x7f307c064180): 764 bytes of 764
to tls/[2a01:7b30:a00f:62ba::3]:9999
tport.c:3508 tport_send_msg() tport_vsend returned 764
tport.c:2302 tport_set_secondary_timer() tport(0x7f307c064180): reset timer
nta.c:8310 outgoing_send() nta: sent INFO (16621717) to
tls/[2a01:7b30:a00f:62ba::3]:9999
tport.c:4176 tport_pend() tport_pend(0x7f307c064180): pending
0x7f307c0f0ed0 for tls/[2a01:7b30:a00f:62ba::3]:9999 (already 1)
nua_stack.c:529 nua_signal() nua(0x18ca7e0): sent signal r_info
nua.c:810 nua_update() nua: nua_update: entering
nua_stack.c:569 nua_stack_signal() nua(0x7f3080063290): recv signal r_update
nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:403 soa_set_params() soa_set_params(static::0x7f30800d65b0, ...)
called
soa.c:1302 soa_init_offer_answer()
soa_init_offer_answer(static::0x7f30800d65b0) called
soa.c:1426 soa_generate_offer()
soa_generate_offer(static::0x7f30800d65b0, 0) called
soa_static.c:1148 offer_answer_step()
soa_static_offer_answer_action(0x7f30800d65b0, soa_generate_offer): called
soa_static.c:1029 soa_sdp_mode_set() soa_sdp_mode_set(0x7f30800d99f0,
(nil), ""): called
soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x7f30800d65b0,
[(nil)], [0x7f30a14f9b78], [0x7f30a14f9b74]) called
nta.c:2665 nta_tpn_by_url() nta: selecting scheme sip
tport.c:3273 tport_tsend() tport_tsend(0x7f3080049a00) tpn =
tls/192.168.2.5:5099
tport.c:4062 tport_resolve() tport_resolve addrinfo = 192.168.2.5:5099
tport.c:4696 tport_by_addrinfo() tport_by_addrinfo(0x7f3080049a00): not
found by name tls/192.168.2.5:5099
tport.c:862 tport_alloc_secondary()
tport_alloc_secondary(0x7f3080049a00): new secondary tport 0x7f30800e5000
tport_type_tcp.c:203 tport_tcp_init_secondary()
tport_tcp_init_secondary(0x7f30800e5000): Setting TCP_KEEPIDLE to 30
tport_type_tcp.c:209 tport_tcp_init_secondary()
tport_tcp_init_secondary(0x7f30800e5000): Setting TCP_KEEPINTVL to 30
tport_type_tls.c:686 tport_tls_connect()
tport_tls_connect(0x7f30800e5000): connecting to tls/192.168.2.5:5099/sips
tport.c:2302 tport_set_secondary_timer() tport(0x7f30800e5000): reset timer
tport.c:3798 tport_queue() tport_queue(0x7f30800e5000): queueing
0x7f30800e2e50 for tls/192.168.2.5:5099
nta.c:8310 outgoing_send() nta: sent UPDATE (16621717) to
tls/192.168.2.5:5099
tport.c:4176 tport_pend() tport_pend(0x7f30800e5000): pending
0x7f30800e2e50 for tls/192.168.2.5:5099 (already 0)
nua_session.c:4149 signal_call_state_change() nua(0x7f3080063290): ready
call updated: calling sent offer
soa.c:1270 soa_get_local_sdp() soa_get_local_sdp(static::0x7f30800d65b0,
[0x7f30a14f9b58], [0x7f30a14f9b60], [(nil)]) called
nua_stack.c:269 nua_stack_event() nua(0x7f3080063290): event i_state
UPDATE sent
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
nua_stack.c:529 nua_signal() nua(0x7f3080063290): sent signal r_update
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2020-02-22 08:56:59.147097 [DEBUG] sofia.c:7301 Channel
sofia/external/1000 at 6.27.9.120:5061 entering state [calling][0]
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
tport.c:2782 tport_wakeup() tport_wakeup(0x7f307c064180): events IN
tport.c:2880 tport_recv_event() tport_recv_event(0x7f307c064180)
tport_type_tls.c:434 tport_tls_recv() tport_tls_recv(0x7f307c064180):
tls_read() returned 537
tport.c:3221 tport_recv_iovec() tport_recv_iovec(0x7f307c064180) msg
0x7f307c0f7420 from (tls/[2a01:7b30:a00f:62ba::3]:9999) has 537 bytes,
veclen = 1
tport.c:3039 tport_deliver() tport_deliver(0x7f307c064180): msg
0x7f307c0f7420 (537 bytes) from tls/[2a01:7b30:a00f:62ba::3]:9999/sips
next=(nil)
nta.c:3299 agent_recv_response() nta: received 200 OK for INFO (16621717)
nta.c:3366 agent_recv_response() nta: 200 OK is going to a transaction
nta.c:9570 outgoing_estimate_delay() nta_outgoing: RTT is 20.353 ms
tport.c:4238 tport_release() tport_release(0x7f307c064180):
0x7f307c0f0ed0 by 0x7f307c0ac960 with 0x7f307c0f7420
nua_stack.c:271 nua_stack_event() nua(0x18ca7e0): event r_info 200 OK
nta.c:8728 outgoing_free() nta: outgoing_free(0x7f307c0ac960)
tport.c:2302 tport_set_secondary_timer() tport(0x7f307c064180): reset timer
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
2020-02-22 08:56:59.327055 [INFO] switch_rtp.c:7680 Auto Changing audio
port from 192.168.2.5:5012 to 33.2.151.64:5012
nta.c:1296 agent_timer() nta: timer set next to 31631 ms
tport.c:2782 tport_wakeup() tport_wakeup(0x7f30800a2f80): events IN
tport.c:2880 tport_recv_event() tport_recv_event(0x7f30800a2f80)
tport_type_tls.c:434 tport_tls_recv() tport_tls_recv(0x7f30800a2f80):
tls_read() returned 788
tport.c:3221 tport_recv_iovec() tport_recv_iovec(0x7f30800a2f80) msg
0x7f30800688b0 from (tls/33.2.151.64:2210) has 788 bytes, veclen = 1
tport.c:3039 tport_deliver() tport_deliver(0x7f30800a2f80): msg
0x7f30800688b0 (788 bytes) from tls/33.2.151.64:2210/sips next=(nil)
nta.c:2880 agent_recv_request() nta: received REGISTER
sip:6.27.9.120:5061 SIP/2.0 (CSeq 2247)
nta.c:3174 agent_check_request_via() nta: Via check: received=33.2.151.64
nta.c:3085 agent_recv_request() nta: REGISTER (2247) going to a default leg
nua_server.c:102 nua_stack_process_request() nua:
nua_stack_process_request: entering
nua_stack.c:899 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::0x7f3080044490, 0x7f3080043c90,
0x7f30800aa610) called
soa.c:403 soa_set_params() soa_set_params(static::0x7f30800eab50, ...)
called
nua_dialog.c:338 nua_dialog_usage_add() nua(0x7f30800aa610): adding
registrar usage
tport.c:4176 tport_pend() tport_pend(0x7f30800a2f80): pending (nil) for
tls/33.2.151.64:2210 (already 0)
nua_stack.c:271 nua_stack_event() nua(0x7f30800aa610): event i_register
100 Trying
tport.c:2302 tport_set_secondary_timer() tport(0x7f30800a2f80): reset timer
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(0x7f30800aa610): 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::0x7f30800eab50, ...)
called
tport.c:3273 tport_tsend() tport_tsend(0x7f30800a2f80) tpn =
TLS/33.2.151.64:2210
tport_type_tls.c:537 tport_tls_send() tport_tls_writevec: vec
0x7f30800a3420 0x7f30800e66e0 621 (621)
tport.c:3610 tport_vsend() tport_vsend(0x7f30800a2f80): 621 bytes of 621
to tls/33.2.151.64:2210
tport.c:3508 tport_send_msg() tport_vsend returned 621
tport.c:2302 tport_set_secondary_timer() tport(0x7f30800a2f80): reset timer
nta.c:6797 incoming_reply() nta: sent 200 OK for REGISTER (2247)
nta.c:5744 incoming_free() nta: incoming_free(0x7f30800cc750)
nua_stack.c:529 nua_signal() nua(0x7f30800aa610): sent signal r_respond
nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
nua_stack.c:569 nua_stack_signal() nua(0x7f30800aa610): recv signal
r_destroy
nua_dialog.c:397 nua_dialog_usage_remove_at() nua(0x7f30800aa610):
removing registrar usage
tport.c:4238 tport_release() tport_release(0x7f30800a2f80): (nil) by
0x7f30800aa610 with (nil)
tport.c:2302 tport_set_secondary_timer() tport(0x7f30800a2f80): reset timer
nta.c:4470 nta_leg_destroy() nta_leg_destroy((nil))
soa.c:356 soa_destroy() soa_destroy(static::0x7f30800eab50) called
nua_stack.c:529 nua_signal() nua(0x7f30800aa610): 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
nta.c:1296 agent_timer() nta: timer set next to 1052 ms
nta.c:9107 outgoing_timer_dk() nta: timer D fired, terminate INVITE
(16621703)
nta.c:8805 outgoing_reclaim_queued() outgoing_reclaim_all((nil), (nil),
0x7f308b4e6c60)
nta.c:8935 _nta_outgoing_timer() nta_outgoing_timer: 0/0 resent, 0/2
tout, 1/2 term, 1/4 free
nta.c:1296 agent_timer() nta: timer set next to 3 ms
nta.c:8988 outgoing_timer_bf() nta: timer F fired, terminating ACK
(16621703)
nta.c:8805 outgoing_reclaim_queued() outgoing_reclaim_all((nil), (nil),
0x7f308b4e6c60)
nta.c:8935 _nta_outgoing_timer() nta_outgoing_timer: 0/0 resent, 1/2
tout, 0/1 term, 1/3 free
nta.c:1296 agent_timer() nta: timer set next to 26697 ms
tport.c:2782 tport_wakeup() tport_wakeup(0x7f30800a2f80): events IN
tport.c:2880 tport_recv_event() tport_recv_event(0x7f30800a2f80)
tport_type_tls.c:434 tport_tls_recv() tport_tls_recv(0x7f30800a2f80):
tls_read() returned 4
tport.c:3221 tport_recv_iovec() tport_recv_iovec(0x7f30800a2f80) msg
0x7f30800688b0 from (tls/33.2.151.64:2210) has 4 bytes, veclen = 1
tport.c:2302 tport_set_secondary_timer() tport(0x7f30800a2f80): reset timer
tport.c:2782 tport_wakeup() tport_wakeup(0x7f30800a2f80): events IN
tport.c:2880 tport_recv_event() tport_recv_event(0x7f30800a2f80)
tport_type_tls.c:434 tport_tls_recv() tport_tls_recv(0x7f30800a2f80):
tls_read() returned 788
tport.c:3221 tport_recv_iovec() tport_recv_iovec(0x7f30800a2f80) msg
0x7f30800688b0 from (tls/33.2.151.64:2210) has 788 bytes, veclen = 1
tport.c:3039 tport_deliver() tport_deliver(0x7f30800a2f80): msg
0x7f30800688b0 (792 bytes) from tls/33.2.151.64:2210/sips next=(nil)
nta.c:2880 agent_recv_request() nta: received REGISTER
sip:6.27.9.120:5061 SIP/2.0 (CSeq 2248)
nta.c:3174 agent_check_request_via() nta: Via check: received=33.2.151.64
nta.c:3085 agent_recv_request() nta: REGISTER (2248) going to a default leg
nua_server.c:102 nua_stack_process_request() nua:
nua_stack_process_request: entering
nua_stack.c:899 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::0x7f3080044490, 0x7f3080043c90,
0x7f30800ead90) called
soa.c:403 soa_set_params() soa_set_params(static::0x7f30800eb600, ...)
called
nua_dialog.c:338 nua_dialog_usage_add() nua(0x7f30800ead90): adding
registrar usage
tport.c:4176 tport_pend() tport_pend(0x7f30800a2f80): pending (nil) for
tls/33.2.151.64:2210 (already 0)
nua_stack.c:271 nua_stack_event() nua(0x7f30800ead90): event i_register
100 Trying
tport.c:2302 tport_set_secondary_timer() tport(0x7f30800a2f80): reset timer
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(0x7f30800ead90): 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::0x7f30800eb600, ...)
called
tport.c:3273 tport_tsend() tport_tsend(0x7f30800a2f80) tpn =
TLS/33.2.151.64:2210
tport_type_tls.c:537 tport_tls_send() tport_tls_writevec: vec
0x7f30800a3420 0x7f3080069a90 621 (621)
tport.c:3610 tport_vsend() tport_vsend(0x7f30800a2f80): 621 bytes of 621
to tls/33.2.151.64:2210
tport.c:3508 tport_send_msg() tport_vsend returned 621
tport.c:2302 tport_set_secondary_timer() tport(0x7f30800a2f80): reset timer
nta.c:6797 incoming_reply() nta: sent 200 OK for REGISTER (2248)
nta.c:5744 incoming_free() nta: incoming_free(0x7f30800b2d00)
nua_stack.c:529 nua_signal() nua(0x7f30800ead90): sent signal r_respond
nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
nua_stack.c:569 nua_stack_signal() nua(0x7f30800ead90): recv signal
r_destroy
nua_dialog.c:397 nua_dialog_usage_remove_at() nua(0x7f30800ead90):
removing registrar usage
tport.c:4238 tport_release() tport_release(0x7f30800a2f80): (nil) by
0x7f30800ead90 with (nil)
tport.c:2302 tport_set_secondary_timer() tport(0x7f30800a2f80): reset timer
nta.c:4470 nta_leg_destroy() nta_leg_destroy((nil))
soa.c:356 soa_destroy() soa_destroy(static::0x7f30800eb600) called
nua_stack.c:529 nua_signal() nua(0x7f30800ead90): 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:2782 tport_wakeup() tport_wakeup(0x7f30800a2f80): events IN
tport.c:2880 tport_recv_event() tport_recv_event(0x7f30800a2f80)
tport_type_tls.c:434 tport_tls_recv() tport_tls_recv(0x7f30800a2f80):
tls_read() returned 4
tport.c:3221 tport_recv_iovec() tport_recv_iovec(0x7f30800a2f80) msg
0x7f30800eb490 from (tls/33.2.151.64:2210) has 4 bytes, veclen = 1
tport.c:2302 tport_set_secondary_timer() tport(0x7f30800a2f80): reset timer
nta.c:9107 outgoing_timer_dk() nta: timer D fired, terminate INVITE
(16621716)
nta.c:8805 outgoing_reclaim_queued() outgoing_reclaim_all((nil), (nil),
0x7f308b4e6c60)
nta.c:8935 _nta_outgoing_timer() nta_outgoing_timer: 0/0 resent, 0/1
tout, 1/1 term, 1/2 free
nta.c:1296 agent_timer() nta: timer set next to 2 ms
nta.c:8988 outgoing_timer_bf() nta: timer F fired, terminating ACK
(16621716)
nta.c:8805 outgoing_reclaim_queued() outgoing_reclaim_all((nil), (nil),
0x7f308b4e6c60)
nta.c:8935 _nta_outgoing_timer() nta_outgoing_timer: 0/0 resent, 1/1
tout, 0/0 term, 1/1 free
nta.c:1289 agent_timer() nta: timer not set
nta.c:8988 outgoing_timer_bf() nta: timer F fired, timeout UPDATE (16621717)
tport.c:4238 tport_release() tport_release(0x7f30800e5000):
0x7f30800e2e50 by 0x7f30800f19f0 with (nil)
nua_stack.c:271 nua_stack_event() nua(0x7f3080063290): event r_update
408 Request Timeout
nta.c:8728 outgoing_free() nta: outgoing_free(0x7f30800f19f0)
tport.c:2302 tport_set_secondary_timer() tport(0x7f30800e5000): reset timer
nua_params.c:482 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:1784 soa_terminate() soa_terminate(static::0x7f30800d65b0) called
soa.c:1302 soa_init_offer_answer()
soa_init_offer_answer(static::0x7f30800d65b0) called
nta.c:2665 nta_tpn_by_url() nta: selecting scheme sip
tport.c:4604 tport_by_name() tport(0x7f3080049a00): found 0x7f30800e5000
by name tls/192.168.2.5:5099
tport.c:3273 tport_tsend() tport_tsend(0x7f30800e5000) tpn =
tls/192.168.2.5:5099
tport.c:3798 tport_queue() tport_queue(0x7f30800e5000): queueing
0x7f30800e2250 for tls/192.168.2.5:5099
nta.c:8310 outgoing_send() nta: sent BYE (16621718) to tls/192.168.2.5:5099
tport.c:4176 tport_pend() tport_pend(0x7f30800e5000): pending
0x7f30800e2250 for tls/192.168.2.5:5099 (already 0)
nua_session.c:4143 signal_call_state_change() nua(0x7f3080063290): call
state changed: ready -> terminating
nua_stack.c:271 nua_stack_event() nua(0x7f3080063290): event i_state 487
BYE sent
nta.c:8935 _nta_outgoing_timer() nta_outgoing_timer: 0/0 resent, 1/1
tout, 0/0 term, 0/1 free
nta.c:1296 agent_timer() nta: timer set next to 32001 ms
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-02-22 08:57:31.167054 [DEBUG] sofia.c:7301 Channel
sofia/external/1000 at 6.27.9.120:5061 entering state [terminating][487]
2020-02-22 08:57:31.167054 [NOTICE] sofia.c:8534 Hangup
sofia/external/1000 at 6.27.9.120:5061 [CS_EXECUTE] [ORIGINATOR_CANCEL]
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:569 nua_stack_signal() nua(0x7f3080063290): recv signal
r_destroy
nua_dialog.c:397 nua_dialog_usage_remove_at() nua(0x7f3080063290):
removing session usage
nua_session.c:4143 signal_call_state_change() nua(0x7f3080063290): call
state changed: terminating -> terminated
nua_stack.c:269 nua_stack_event() nua(0x7f3080063290): event i_state
Terminated
nua_stack.c:269 nua_stack_event() nua(0x7f3080063290): event
i_terminated Terminated
soa.c:356 soa_destroy() soa_destroy(static::0x7f30800d65b0) called
nta.c:4470 nta_leg_destroy() nta_leg_destroy(0x7f30800f2c50)
nua_stack.c:529 nua_signal() nua(0x7f3080063290): sent signal r_destroy
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering
nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
2020-02-22 08:57:31.167054 [DEBUG] switch_ivr_bridge.c:829
sofia/external/1000 at 6.27.9.120:5061 ending bridge by request from read
function
2020-02-22 08:57:31.167054 [DEBUG] switch_ivr_bridge.c:915 BRIDGE THREAD
DONE [sofia/external/1000 at 6.27.9.120:5061]
2020-02-22 08:57:31.187101 [DEBUG] switch_ivr_bridge.c:823
sofia/external/1000 at 6.27.9.120:5061 ending bridge by request from write
function
2020-02-22 08:57:31.187101 [DEBUG] switch_ivr_bridge.c:915 BRIDGE THREAD
DONE [sofia/external-ipv6/9197]
2020-02-22 08:57:31.187101 [NOTICE] switch_ivr_bridge.c:1032 Hangup
sofia/external-ipv6/9197 [CS_EXCHANGE_MEDIA] [NORMAL_CLEARING]
--
Regards,
V.Bogatyryev
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.freeswitch.org/pipermail/freeswitch-users/attachments/20200222/d51a1f05/attachment-0001.html>
More information about the FreeSWITCH-users
mailing list