Background mode - PID=[18763]
uac_telephone_event_check .........................................nua_stack.c:389 nua_application_event() nua: nua_application_event: entering
nua.c:1157 nua_unref_user() nua: nua_unref_user: entering
nua_stack.c:558 nua_signal() nua((nil)): sent signal r_unref
nua.c:365 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:1157 nua_unref_user() nua: nua_unref_user: entering
nua_stack.c:558 nua_signal() nua((nil)): sent signal r_unref
nua_stack.c:599 nua_stack_signal() nua((nil)): recv signal r_unref
nua_stack.c:599 nua_stack_signal() nua((nil)): recv signal r_unref
nua_stack.c:301 nua_stack_event() nua((nil)): event r_set_params 200 OK
nua_stack.c:389 nua_application_event() nua: nua_application_event: entering
nua.c:1157 nua_unref_user() nua: nua_unref_user: entering
nua_stack.c:558 nua_signal() nua((nil)): sent signal r_unref
nua_stack.c:599 nua_stack_signal() nua((nil)): recv signal r_unref
nua.c:365 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:1157 nua_unref_user() nua: nua_unref_user: entering
nua_stack.c:558 nua_signal() nua((nil)): sent signal r_unref
nua_stack.c:599 nua_stack_signal() nua((nil)): recv signal r_unref
2023-11-03 20:28:43.821461 100.00% [WARNING] switch_core.c:3492 Exit status (25344): sipp 172.19.0.2:5080 -nr -p 5062 -m 1 -s 1212121212 -recv_timeout 10000 -timeout 10s -sf sipp-scenarios/uac_telephone_event.xml -bg 
sipp 172.19.0.2:5080 -nr -p 5062 -m 1 -s 1212121212 -recv_timeout 10000 -timeout 10s -sf sipp-scenarios/uac_telephone_event.xml -bg 
tport.c:2769 tport_wakeup_pri() tport_wakeup_pri(0x6160000f1b80): events IN
tport.c:2900 tport_recv_event() tport_recv_event(0x6160000f1b80)
tport.c:3237 tport_recv_iovec() tport_recv_iovec(0x6160000f1b80) msg 0x619000351680 from (udp/172.19.0.2:5080) has 667 bytes, veclen = 1
recv 667 bytes from udp/[172.19.0.2]:5062 at 20:28:43.947097:
------------------------------------------------------------------------
INVITE sip:1212121212@172.19.0.2:5080 SIP/2.0
Via: SIP/2.0/UDP 172.19.0.2:5062;branch=z9hG4bK-18762-1-0
From: t_sipp <sip:t_sipp@172.19.0.2:5062>;tag=1
To: sut <sip:1212121212@172.19.0.2:5080>
Call-ID: 1-18762@172.19.0.2
CSeq: 1 INVITE
Contact: sip:t_sipp@172.19.0.2:5062
Max-Forwards: 70
Subject: Performance Test
Content-Type: application/sdp
Content-Length:   287

v=0
o=user1 53655765 2353687637 IN IP4 172.19.0.2
s=-
c=IN IP4 172.19.0.2
t=0 0
m=audio 6000 RTP/AVP 8 0 18 101
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:101 telephone-event/8000
  a=fmtp:101 0-11,16
a=sendrecv
a=ptime:20

tport.c:3055 tport_deliver() tport_deliver(0x6160000f1b80): msg 0x619000351680 (667 bytes) from udp/172.19.0.2:5080/sip next=(nil)
nta.c:2957 agent_recv_request() nta: received INVITE sip:1212121212@172.19.0.2:5080 SIP/2.0 (CSeq 1) (load: 1 rps)
nta.c:3326 agent_aliases() nta: canonizing sip:1212121212@172.19.0.2:5080 with contact
nta.c:3164 agent_recv_request() nta: INVITE (1) going to a default leg
nua_server.c:102 nua_stack_process_request() nua: nua_stack_process_request: entering
nua_stack.c:938 nh_create() nua: nh_create: entering
nua_common.c:108 nh_create_handle() nua: nh_create_handle: entering
nua_params.c:484 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:278 soa_clone() soa_clone(static::0x6150000b0480, 0x606000050000, 0x6120000f28c0) called
soa.c:402 soa_set_params() soa_set_params(static::0x6150000b0e80, ...) called
nta.c:4497 nta_leg_tcreate() nta_leg_tcreate(0x60c000086740)
soa.c:1301 soa_init_offer_answer() soa_init_offer_answer(static::0x6150000b0e80) called
soa.c:1170 soa_set_remote_sdp() soa_set_remote_sdp(static::0x6150000b0e80, (nil), 0x6170000b1bfc, 287) called
nua_dialog.c:336 nua_dialog_usage_add() nua(0x6120000f28c0): adding session usage
nua_stack.c:301 nua_stack_event() nua(0x6120000f28c0): event i_invite 100 Trying
nua_session.c:4131 signal_call_state_change() nua(0x6120000f28c0): call state changed: init -> received, received offer
soa.c:1096 soa_get_remote_sdp() soa_get_remote_sdp(static::0x6150000b0e80, [0x7fd316caf398], [0x7fd316caf390], [(nil)]) called
nua_stack.c:301 nua_stack_event() nua(0x6120000f28c0): event i_state 100 Trying
nua_stack.c:389 nua_application_event() nua: nua_application_event: entering
nua.c:341 nua_handle_bind() nua: nua_handle_bind: entering
04af4a7b-e0b7-449e-89ea-fb59839ffdec 2023-11-03 20:28:43.943762 96.67% [NOTICE] switch_channel.c:1143 New Channel sofia/external/t_sipp@172.19.0.2:5062 [04af4a7b-e0b7-449e-89ea-fb59839ffdec]
nua.c:1170 nua_handle_unref_user() nua nua_handle_unref_user(0x6120000f28c0): entering
nua_stack.c:558 nua_signal() nua(0x6120000f28c0): sent signal r_handle_unref
nua.c:1157 nua_unref_user() nua: nua_unref_user: entering
nua_stack.c:558 nua_signal() nua((nil)): sent signal r_unref
nua_stack.c:389 nua_application_event() nua: nua_application_event: entering
nua.c:1170 nua_handle_unref_user() nua nua_handle_unref_user(0x6120000f28c0): entering
nua_stack.c:558 nua_signal() nua(0x6120000f28c0): sent signal r_handle_unref
nua.c:1157 nua_unref_user() nua: nua_unref_user: entering
nua_stack.c:558 nua_signal() nua((nil)): sent signal r_unref
nua_stack.c:599 nua_stack_signal() nua(0x6120000f28c0): recv signal r_handle_unref
nua_stack.c:599 nua_stack_signal() nua((nil)): recv signal r_unref
nua_stack.c:599 nua_stack_signal() nua(0x6120000f28c0): recv signal r_handle_unref
nua_stack.c:599 nua_stack_signal() nua((nil)): recv signal r_unref
04af4a7b-e0b7-449e-89ea-fb59839ffdec 2023-11-03 20:28:43.943762 96.67% [DEBUG] switch_core_state_machine.c:581 (sofia/external/t_sipp@172.19.0.2:5062) Running State Change CS_NEW (Cur 1 Tot 1)
nua.c:365 nua_handle_magic() nua: nua_handle_magic: entering
04af4a7b-e0b7-449e-89ea-fb59839ffdec 2023-11-03 20:28:43.943762 96.67% [INFO] sofia.c:10459 sofia/external/t_sipp@172.19.0.2:5062 receiving invite from 172.19.0.2:5062 version: 1.10.11-dev git 583788b 2023-11-03 20:19:48Z 64bit call-id: 1-18762@172.19.0.2
nua.c:365 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:1170 nua_handle_unref_user() nua nua_handle_unref_user(0x6120000f28c0): entering
nua_stack.c:558 nua_signal() nua(0x6120000f28c0): sent signal r_handle_unref
nua.c:1157 nua_unref_user() nua: nua_unref_user: entering
nua_stack.c:558 nua_signal() nua((nil)): sent signal r_unref
nua.c:365 nua_handle_magic() nua: nua_handle_magic: entering
nua_stack.c:599 nua_stack_signal() nua(0x6120000f28c0): recv signal r_handle_unref
nua_stack.c:599 nua_stack_signal() nua((nil)): recv signal r_unref
04af4a7b-e0b7-449e-89ea-fb59839ffdec 2023-11-03 20:28:43.963537 96.67% [DEBUG] sofia.c:7493 Channel sofia/external/t_sipp@172.19.0.2:5062 entering state [received][100]
04af4a7b-e0b7-449e-89ea-fb59839ffdec 2023-11-03 20:28:43.963537 96.67% [DEBUG] sofia.c:7503 Remote SDP:
v=0
o=user1 53655765 2353687637 IN IP4 172.19.0.2
s=-
c=IN IP4 172.19.0.2
t=0 0
m=audio 6000 RTP/AVP 8 0 18 101
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-11,16
a=ptime:20

04af4a7b-e0b7-449e-89ea-fb59839ffdec 2023-11-03 20:28:43.963537 96.67% [DEBUG] sofia.c:7906 (sofia/external/t_sipp@172.19.0.2:5062) State Change CS_NEW -> CS_INIT
nua.c:365 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:1170 nua_handle_unref_user() nua nua_handle_unref_user(0x6120000f28c0): entering
nua_stack.c:558 nua_signal() nua(0x6120000f28c0): sent signal r_handle_unref
nua.c:1157 nua_unref_user() nua: nua_unref_user: entering
nua_stack.c:558 nua_signal() nua((nil)): sent signal r_unref
04af4a7b-e0b7-449e-89ea-fb59839ffdec 2023-11-03 20:28:43.963537 96.67% [DEBUG] switch_core_state_machine.c:600 (sofia/external/t_sipp@172.19.0.2:5062) State NEW
04af4a7b-e0b7-449e-89ea-fb59839ffdec 2023-11-03 20:28:43.963537 96.67% [DEBUG] switch_core_state_machine.c:581 (sofia/external/t_sipp@172.19.0.2:5062) Running State Change CS_INIT (Cur 1 Tot 1)
nua_stack.c:599 nua_stack_signal() nua(0x6120000f28c0): recv signal r_handle_unref
nua_stack.c:599 nua_stack_signal() nua((nil)): recv signal r_unref
04af4a7b-e0b7-449e-89ea-fb59839ffdec 2023-11-03 20:28:43.963537 96.67% [DEBUG] switch_core_state_machine.c:624 (sofia/external/t_sipp@172.19.0.2:5062) State INIT
04af4a7b-e0b7-449e-89ea-fb59839ffdec 2023-11-03 20:28:43.963537 96.67% [DEBUG] mod_sofia.c:97 sofia/external/t_sipp@172.19.0.2:5062 SOFIA INIT
04af4a7b-e0b7-449e-89ea-fb59839ffdec 2023-11-03 20:28:43.963537 96.67% [DEBUG] switch_core_state_machine.c:40 sofia/external/t_sipp@172.19.0.2:5062 Standard INIT
04af4a7b-e0b7-449e-89ea-fb59839ffdec 2023-11-03 20:28:43.963537 96.67% [DEBUG] switch_core_state_machine.c:48 (sofia/external/t_sipp@172.19.0.2:5062) State Change CS_INIT -> CS_ROUTING
04af4a7b-e0b7-449e-89ea-fb59839ffdec 2023-11-03 20:28:43.963537 96.67% [DEBUG] switch_core_state_machine.c:624 (sofia/external/t_sipp@172.19.0.2:5062) State INIT going to sleep
04af4a7b-e0b7-449e-89ea-fb59839ffdec 2023-11-03 20:28:43.984576 96.67% [DEBUG] switch_core_state_machine.c:581 (sofia/external/t_sipp@172.19.0.2:5062) Running State Change CS_ROUTING (Cur 1 Tot 1)
04af4a7b-e0b7-449e-89ea-fb59839ffdec 2023-11-03 20:28:43.984576 96.67% [DEBUG] switch_channel.c:2400 (sofia/external/t_sipp@172.19.0.2:5062) Callstate Change DOWN -> RINGING
04af4a7b-e0b7-449e-89ea-fb59839ffdec 2023-11-03 20:28:43.984576 96.67% [DEBUG] switch_core_state_machine.c:640 (sofia/external/t_sipp@172.19.0.2:5062) State ROUTING
nua.c:878 nua_respond() nua: nua_respond: entering
nua_stack.c:558 nua_signal() nua(0x6120000f28c0): sent signal r_respond
04af4a7b-e0b7-449e-89ea-fb59839ffdec 2023-11-03 20:28:43.984576 96.67% [DEBUG] mod_sofia.c:158 sofia/external/t_sipp@172.19.0.2:5062 SOFIA ROUTING
04af4a7b-e0b7-449e-89ea-fb59839ffdec 2023-11-03 20:28:43.984576 96.67% [DEBUG] switch_core_state_machine.c:230 sofia/external/t_sipp@172.19.0.2:5062 Standard ROUTING
04af4a7b-e0b7-449e-89ea-fb59839ffdec 2023-11-03 20:28:43.984576 96.67% [INFO] mod_dialplan_xml.c:642 Processing t_sipp <t_sipp>->1212121212 in context default
nua_stack.c:601 nua_stack_signal() nua(0x6120000f28c0): recv signal r_respond 100 Trying
nua_params.c:484 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:402 soa_set_params() soa_set_params(static::0x6150000b0e80, ...) called
tport.c:3290 tport_tsend() tport_tsend(0x6160000f1b80) tpn = UDP/172.19.0.2:5062
tport.c:4076 tport_resolve() tport_resolve addrinfo = 172.19.0.2:5062
tport.c:4713 tport_by_addrinfo() tport_by_addrinfo(0x6160000f1b80): not found by name UDP/172.19.0.2:5062
tport.c:3625 tport_vsend() tport_vsend(0x6160000f1b80): 259 bytes of 259 to udp/172.19.0.2:5062
tport.c:3526 tport_send_msg() tport_vsend returned 259
send 259 bytes to udp/[172.19.0.2]:5062 at 20:28:44.005215:
------------------------------------------------------------------------
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 172.19.0.2:5062;branch=z9hG4bK-18762-1-0
From: t_sipp <sip:t_sipp@172.19.0.2:5062>;tag=1
To: sut <sip:1212121212@172.19.0.2:5080>
Call-ID: 1-18762@172.19.0.2
CSeq: 1 INVITE
User-Agent: Unit Test
Content-Length: 0


nta.c:6879 incoming_reply() nta: sent 100 Trying for INVITE (1)
04af4a7b-e0b7-449e-89ea-fb59839ffdec Dialplan: sofia/external/t_sipp@172.19.0.2:5062 parsing [default->unit_test_sipp-uac-digest-leak] continue=false
04af4a7b-e0b7-449e-89ea-fb59839ffdec Dialplan: sofia/external/t_sipp@172.19.0.2:5062 Regex (FAIL) [unit_test_sipp-uac-digest-leak] destination_number(1212121212) =~ /^\+15553334444$/ break=on-false
04af4a7b-e0b7-449e-89ea-fb59839ffdec Dialplan: sofia/external/t_sipp@172.19.0.2:5062 parsing [default->sipp_telephone_check] continue=false
04af4a7b-e0b7-449e-89ea-fb59839ffdec Dialplan: sofia/external/t_sipp@172.19.0.2:5062 Regex (PASS) [sipp_telephone_check] destination_number(1212121212) =~ /^1212121212$/ break=on-false
04af4a7b-e0b7-449e-89ea-fb59839ffdec Dialplan: sofia/external/t_sipp@172.19.0.2:5062 Action answer() 
04af4a7b-e0b7-449e-89ea-fb59839ffdec Dialplan: sofia/external/t_sipp@172.19.0.2:5062 Action set(park_after_bridge=true) 
04af4a7b-e0b7-449e-89ea-fb59839ffdec Dialplan: sofia/external/t_sipp@172.19.0.2:5062 Action park() 
04af4a7b-e0b7-449e-89ea-fb59839ffdec 2023-11-03 20:28:44.004610 96.67% [DEBUG] switch_core_state_machine.c:281 (sofia/external/t_sipp@172.19.0.2:5062) State Change CS_ROUTING -> CS_EXECUTE
04af4a7b-e0b7-449e-89ea-fb59839ffdec 2023-11-03 20:28:44.004610 96.67% [DEBUG] switch_core_state_machine.c:640 (sofia/external/t_sipp@172.19.0.2:5062) State ROUTING going to sleep
04af4a7b-e0b7-449e-89ea-fb59839ffdec 2023-11-03 20:28:44.004610 96.67% [DEBUG] switch_core_state_machine.c:581 (sofia/external/t_sipp@172.19.0.2:5062) Running State Change CS_EXECUTE (Cur 1 Tot 1)
04af4a7b-e0b7-449e-89ea-fb59839ffdec 2023-11-03 20:28:44.004610 96.67% [DEBUG] switch_core_state_machine.c:647 (sofia/external/t_sipp@172.19.0.2:5062) State EXECUTE
04af4a7b-e0b7-449e-89ea-fb59839ffdec 2023-11-03 20:28:44.004610 96.67% [DEBUG] mod_sofia.c:213 sofia/external/t_sipp@172.19.0.2:5062 SOFIA EXECUTE
04af4a7b-e0b7-449e-89ea-fb59839ffdec 2023-11-03 20:28:44.004610 96.67% [DEBUG] switch_core_state_machine.c:323 sofia/external/t_sipp@172.19.0.2:5062 Standard EXECUTE
04af4a7b-e0b7-449e-89ea-fb59839ffdec EXECUTE [depth=0] sofia/external/t_sipp@172.19.0.2:5062 answer()
04af4a7b-e0b7-449e-89ea-fb59839ffdec 2023-11-03 20:28:44.024582 96.67% [DEBUG] switch_core_media.c:5526 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
04af4a7b-e0b7-449e-89ea-fb59839ffdec 2023-11-03 20:28:44.024582 96.67% [DEBUG] switch_core_media.c:5526 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
04af4a7b-e0b7-449e-89ea-fb59839ffdec 2023-11-03 20:28:44.024582 96.67% [DEBUG] switch_core_media.c:5588 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
04af4a7b-e0b7-449e-89ea-fb59839ffdec 2023-11-03 20:28:44.024582 96.67% [DEBUG] switch_core_media.c:5526 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMU:0:8000:20:64000:1]
04af4a7b-e0b7-449e-89ea-fb59839ffdec 2023-11-03 20:28:44.024582 96.67% [DEBUG] switch_core_media.c:5438 Set telephone-event payload to 101@8000
04af4a7b-e0b7-449e-89ea-fb59839ffdec 2023-11-03 20:28:44.024582 96.67% [DEBUG] switch_core_media.c:3731 Set Codec sofia/external/t_sipp@172.19.0.2:5062 PCMU/8000 20 ms 160 samples 64000 bits 1 channels
04af4a7b-e0b7-449e-89ea-fb59839ffdec 2023-11-03 20:28:44.024582 96.67% [DEBUG] switch_core_codec.c:111 sofia/external/t_sipp@172.19.0.2:5062 Original read codec set to PCMU:0
04af4a7b-e0b7-449e-89ea-fb59839ffdec 2023-11-03 20:28:44.048297 96.67% [DEBUG] switch_core_media.c:5798 Set telephone-event payload to 101@8000
04af4a7b-e0b7-449e-89ea-fb59839ffdec 2023-11-03 20:28:44.048297 96.67% [DEBUG] switch_core_media.c:5856 sofia/external/t_sipp@172.19.0.2:5062 Set 2833 dtmf send payload to 101 recv payload to 101
04af4a7b-e0b7-449e-89ea-fb59839ffdec 2023-11-03 20:28:44.048297 96.67% [DEBUG] switch_core_media.c:8660 AUDIO RTP [sofia/external/t_sipp@172.19.0.2:5062] 172.19.0.2 port 22984 -> 172.19.0.2 port 6000 codec: 0 ms: 20
04af4a7b-e0b7-449e-89ea-fb59839ffdec 2023-11-03 20:28:44.048297 96.67% [DEBUG] switch_rtp.c:4535 Starting timer [soft] 160 bytes per 20ms
nta.c:1317 agent_timer() nta: timer set next to 4000 ms
04af4a7b-e0b7-449e-89ea-fb59839ffdec 2023-11-03 20:28:44.048297 96.67% [DEBUG] switch_core_media.c:8973 sofia/external/t_sipp@172.19.0.2:5062 Set 2833 dtmf send payload to 101
04af4a7b-e0b7-449e-89ea-fb59839ffdec 2023-11-03 20:28:44.048297 96.67% [DEBUG] switch_core_media.c:8980 sofia/external/t_sipp@172.19.0.2:5062 Set 2833 dtmf receive payload to 101
04af4a7b-e0b7-449e-89ea-fb59839ffdec 2023-11-03 20:28:44.048297 96.67% [DEBUG] switch_core_media.c:9003 sofia/external/t_sipp@172.19.0.2:5062 Set rtp dtmf delay to 40
04af4a7b-e0b7-449e-89ea-fb59839ffdec 2023-11-03 20:28:44.048297 96.67% [NOTICE] sofia_media.c:90 Pre-Answer sofia/external/t_sipp@172.19.0.2:5062!
04af4a7b-e0b7-449e-89ea-fb59839ffdec 2023-11-03 20:28:44.144578 96.67% [DEBUG] switch_channel.c:3586 (sofia/external/t_sipp@172.19.0.2:5062) Callstate Change RINGING -> EARLY
04af4a7b-e0b7-449e-89ea-fb59839ffdec 2023-11-03 20:28:44.164587 96.67% [DEBUG] switch_core_media.c:8642 Audio params are unchanged for sofia/external/t_sipp@172.19.0.2:5062.
04af4a7b-e0b7-449e-89ea-fb59839ffdec 2023-11-03 20:28:44.164587 96.67% [DEBUG] mod_sofia.c:914 Local SDP sofia/external/t_sipp@172.19.0.2:5062:
v=0
o=FS 1699020340 1699020341 IN IP4 172.19.0.2
s=FS
c=IN IP4 172.19.0.2
t=0 0
m=audio 22984 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20
a=sendrecv

nua.c:878 nua_respond() nua: nua_respond: entering
nua_stack.c:601 nua_stack_signal() nua(0x6120000f28c0): recv signal r_respond 200 OK
nua_params.c:484 nua_stack_set_params() nua: nua_stack_set_params: entering
nua_stack.c:558 nua_signal() nua(0x6120000f28c0): sent signal r_respond
soa.c:402 soa_set_params() soa_set_params(static::0x6150000b0e80, ...) called
soa.c:1051 soa_set_user_sdp() soa_set_user_sdp(static::0x6150000b0e80, (nil), 0x61700010084e, -1) called
soa.c:889 soa_set_capability_sdp() soa_set_capability_sdp(static::0x6150000b0e80, (nil), 0x61700010084e, -1) called
nua_session.c:2317 nua_invite_server_respond() nua: nua_invite_server_respond: entering
soa.c:1514 soa_generate_answer() soa_generate_answer(static::0x6150000b0e80) called
soa_static.c:1147 offer_answer_step() soa_static_offer_answer_action(0x6150000b0e80, soa_generate_answer): called
soa_static.c:1188 offer_answer_step() soa_static(0x6150000b0e80, soa_generate_answer): generating local description
soa_static.c:1229 offer_answer_step() soa_static(0x6150000b0e80, soa_generate_answer): upgrade with remote description
soa_static.c:1028 soa_sdp_mode_set() soa_sdp_mode_set(0x7fd316caf730, 0x6180000d0880, ""): called
soa_static.c:1445 offer_answer_step() soa_static(0x6150000b0e80, soa_generate_answer): storing local description
soa.c:1729 soa_activate() soa_activate(static::0x6150000b0e80, (nil)) called
soa.c:1268 soa_get_local_sdp() soa_get_local_sdp(static::0x6150000b0e80, [(nil)], [0x7fd316caf820], [0x7fd316caf81c]) called
tport.c:3290 tport_tsend() tport_tsend(0x6160000f1b80) tpn = UDP/172.19.0.2:5062
tport.c:4076 tport_resolve() tport_resolve addrinfo = 172.19.0.2:5062
tport.c:4713 tport_by_addrinfo() tport_by_addrinfo(0x6160000f1b80): not found by name UDP/172.19.0.2:5062
tport.c:3625 tport_vsend() tport_vsend(0x6160000f1b80): 918 bytes of 918 to udp/172.19.0.2:5062
tport.c:3526 tport_send_msg() tport_vsend returned 918
send 918 bytes to udp/[172.19.0.2]:5062 at 20:28:44.178805:
------------------------------------------------------------------------
SIP/2.0 200 OK
Via: SIP/2.0/UDP 172.19.0.2:5062;branch=z9hG4bK-18762-1-0
From: t_sipp <sip:t_sipp@172.19.0.2:5062>;tag=1
To: sut <sip:1212121212@172.19.0.2:5080>;tag=BF0Z356DDK23p
Call-ID: 1-18762@172.19.0.2
CSeq: 1 INVITE
Contact: <sip:1212121212@172.19.0.2:5080;transport=udp>
User-Agent: Unit Test
Accept: application/sdp
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
Supported: timer, path, replaces
Allow-Events: talk, hold, conference, refer
Session-Expires: 600;refresher=uas
Content-Type: application/sdp
Content-Disposition: session
Content-Length: 200
Remote-Party-ID: "1212121212" <sip:1212121212@172.19.0.2>;party=calling;privacy=off;screen=no

v=0
o=FS 1699020340 1699020341 IN IP4 172.19.0.2
s=FS
c=IN IP4 172.19.0.2
t=0 0
m=audio 22984 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20

nta.c:6879 incoming_reply() nta: sent 200 OK for INVITE (1)
nta.c:1369 set_timeout() nta: timer shortened to 500 ms
nua_session.c:4131 signal_call_state_change() nua(0x6120000f28c0): call state changed: received -> completed, sent answer
soa.c:1268 soa_get_local_sdp() soa_get_local_sdp(static::0x6150000b0e80, [0x7fd316caf8e8], [0x7fd316caf8e0], [(nil)]) called
soa.c:615 soa_get_params() soa_get_params(static::0x6150000b0e80, ...) called
nua_stack.c:301 nua_stack_event() nua(0x6120000f28c0): event i_state 200 OK
tport.c:2769 tport_wakeup_pri() tport_wakeup_pri(0x6160000f1b80): events IN
tport.c:2900 tport_recv_event() tport_recv_event(0x6160000f1b80)
tport.c:3237 tport_recv_iovec() tport_recv_iovec(0x6160000f1b80) msg 0x619000353e80 from (udp/172.19.0.2:5080) has 357 bytes, veclen = 1
recv 357 bytes from udp/[172.19.0.2]:5062 at 20:28:44.180906:
------------------------------------------------------------------------
ACK sip:1212121212@172.19.0.2:5080 SIP/2.0
Via: SIP/2.0/UDP 172.19.0.2:5062;branch=z9hG4bK-18762-1-4
From: t_sipp <sip:t_sipp@172.19.0.2:5062>;tag=1
To: sut <sip:1212121212@172.19.0.2:5080>;tag=BF0Z356DDK23p
Call-ID: 1-18762@172.19.0.2
CSeq: 1 ACK
Contact: sip:t_sipp@172.19.0.2:5062
Max-Forwards: 70
Subject: Performance Test
Content-Length: 0


tport.c:3055 tport_deliver() tport_deliver(0x6160000f1b80): msg 0x619000353e80 (357 bytes) from udp/172.19.0.2:5080/sip next=(nil)
nta.c:2957 agent_recv_request() nta: received ACK sip:1212121212@172.19.0.2:5080 SIP/2.0 (CSeq 1) (load: 1 rps)
nta.c:3097 agent_recv_request() nta: ACK (1) is going to INVITE (1)
nua_session.c:2566 process_ack_or_cancel() nua: process_ack_or_cancel: entering
soa.c:1213 soa_clear_remote_sdp() soa_clear_remote_sdp(static::0x6150000b0e80) called
nua_stack.c:301 nua_stack_event() nua(0x6120000f28c0): event i_ack 200 OK
nua_session.c:4131 signal_call_state_change() nua(0x6120000f28c0): call state changed: completed -> ready
nua_stack.c:301 nua_stack_event() nua(0x6120000f28c0): event i_state 200 OK
nua_stack.c:301 nua_stack_event() nua(0x6120000f28c0): event i_active 200 Call active
nua_dialog.c:563 nua_dialog_usage_set_refresh_range() nua(): refresh session after 302 seconds (in [295..305])
nua_stack.c:389 nua_application_event() nua: nua_application_event: entering
nua.c:1170 nua_handle_unref_user() nua nua_handle_unref_user(0x6120000f28c0): entering
nua_stack.c:599 nua_stack_signal() nua(0x6120000f28c0): recv signal r_handle_unref
nua_stack.c:558 nua_signal() nua(0x6120000f28c0): sent signal r_handle_unref
nua.c:1157 nua_unref_user() nua: nua_unref_user: entering
nua_stack.c:558 nua_signal() nua((nil)): sent signal r_unref
nua_stack.c:389 nua_application_event() nua: nua_application_event: entering
nua.c:1170 nua_handle_unref_user() nua nua_handle_unref_user(0x6120000f28c0): entering
nua_stack.c:558 nua_signal() nua(0x6120000f28c0): sent signal r_handle_unref
nua.c:1157 nua_unref_user() nua: nua_unref_user: entering
nua_stack.c:558 nua_signal() nua((nil)): sent signal r_unref
nua_stack.c:389 nua_application_event() nua: nua_application_event: entering
nua.c:1170 nua_handle_unref_user() nua nua_handle_unref_user(0x6120000f28c0): entering
nua_stack.c:558 nua_signal() nua(0x6120000f28c0): sent signal r_handle_unref
nua.c:1157 nua_unref_user() nua: nua_unref_user: entering
nua_stack.c:558 nua_signal() nua((nil)): sent signal r_unref
nua_stack.c:389 nua_application_event() nua: nua_application_event: entering
nua.c:1170 nua_handle_unref_user() nua nua_handle_unref_user(0x6120000f28c0): entering
nua_stack.c:558 nua_signal() nua(0x6120000f28c0): sent signal r_handle_unref
nua.c:1157 nua_unref_user() nua: nua_unref_user: entering
nua_stack.c:558 nua_signal() nua((nil)): sent signal r_unref
nua_stack.c:599 nua_stack_signal() nua((nil)): recv signal r_unref
nua_stack.c:599 nua_stack_signal() nua(0x6120000f28c0): recv signal r_handle_unref
nua_stack.c:599 nua_stack_signal() nua((nil)): recv signal r_unref
nua_stack.c:599 nua_stack_signal() nua(0x6120000f28c0): recv signal r_handle_unref
nua_stack.c:599 nua_stack_signal() nua((nil)): recv signal r_unref
nua_stack.c:599 nua_stack_signal() nua(0x6120000f28c0): recv signal r_handle_unref
nua_stack.c:599 nua_stack_signal() nua((nil)): recv signal r_unref
04af4a7b-e0b7-449e-89ea-fb59839ffdec 2023-11-03 20:28:44.184586 96.67% [NOTICE] mod_dptools.c:1406 Channel [sofia/external/t_sipp@172.19.0.2:5062] has been answered
04af4a7b-e0b7-449e-89ea-fb59839ffdec 2023-11-03 20:28:44.244589 96.67% [DEBUG] switch_channel.c:3913 (sofia/external/t_sipp@172.19.0.2:5062) Callstate Change EARLY -> ACTIVE
nua.c:365 nua_handle_magic() nua: nua_handle_magic: entering
04af4a7b-e0b7-449e-89ea-fb59839ffdec 2023-11-03 20:28:44.264583 96.67% [DEBUG] sofia.c:7493 Channel sofia/external/t_sipp@172.19.0.2:5062 entering state [completed][200]
nua.c:365 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:1170 nua_handle_unref_user() nua nua_handle_unref_user(0x6120000f28c0): entering
nua_stack.c:599 nua_stack_signal() nua(0x6120000f28c0): recv signal r_handle_unref
nua_stack.c:558 nua_signal() nua(0x6120000f28c0): sent signal r_handle_unref
nua.c:1157 nua_unref_user() nua: nua_unref_user: entering
nua_stack.c:599 nua_stack_signal() nua((nil)): recv signal r_unref
nua_stack.c:558 nua_signal() nua((nil)): sent signal r_unref
nua.c:365 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:365 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:1170 nua_handle_unref_user() nua nua_handle_unref_user(0x6120000f28c0): entering
nua_stack.c:599 nua_stack_signal() nua(0x6120000f28c0): recv signal r_handle_unref
nua_stack.c:558 nua_signal() nua(0x6120000f28c0): sent signal r_handle_unref
nua.c:1157 nua_unref_user() nua: nua_unref_user: entering
nua_stack.c:599 nua_stack_signal() nua((nil)): recv signal r_unref
nua_stack.c:558 nua_signal() nua((nil)): sent signal r_unref
nua.c:365 nua_handle_magic() nua: nua_handle_magic: entering
04af4a7b-e0b7-449e-89ea-fb59839ffdec 2023-11-03 20:28:44.264583 96.67% [DEBUG] sofia.c:7493 Channel sofia/external/t_sipp@172.19.0.2:5062 entering state [ready][200]
nua.c:365 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:1170 nua_handle_unref_user() nua nua_handle_unref_user(0x6120000f28c0): entering
nua_stack.c:599 nua_stack_signal() nua(0x6120000f28c0): recv signal r_handle_unref
nua_stack.c:558 nua_signal() nua(0x6120000f28c0): sent signal r_handle_unref
nua.c:1157 nua_unref_user() nua: nua_unref_user: entering
nua_stack.c:599 nua_stack_signal() nua((nil)): recv signal r_unref
nua_stack.c:558 nua_signal() nua((nil)): sent signal r_unref
nua.c:365 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:365 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:1170 nua_handle_unref_user() nua nua_handle_unref_user(0x6120000f28c0): entering
nua_stack.c:599 nua_stack_signal() nua(0x6120000f28c0): recv signal r_handle_unref
nua_stack.c:558 nua_signal() nua(0x6120000f28c0): sent signal r_handle_unref
nua.c:1157 nua_unref_user() nua: nua_unref_user: entering
nua_stack.c:599 nua_stack_signal() nua((nil)): recv signal r_unref
nua_stack.c:558 nua_signal() nua((nil)): sent signal r_unref
04af4a7b-e0b7-449e-89ea-fb59839ffdec EXECUTE [depth=0] sofia/external/t_sipp@172.19.0.2:5062 set(park_after_bridge=true)
04af4a7b-e0b7-449e-89ea-fb59839ffdec 2023-11-03 20:28:44.324585 96.67% [DEBUG] mod_dptools.c:1671 SET sofia/external/t_sipp@172.19.0.2:5062 [park_after_bridge]=[true]
04af4a7b-e0b7-449e-89ea-fb59839ffdec EXECUTE [depth=0] sofia/external/t_sipp@172.19.0.2:5062 park()
nta.c:1317 agent_timer() nta: timer set next to 3377 ms
tport.c:2769 tport_wakeup_pri() tport_wakeup_pri(0x6160000f1b80): events IN
tport.c:2900 tport_recv_event() tport_recv_event(0x6160000f1b80)
tport.c:3237 tport_recv_iovec() tport_recv_iovec(0x6160000f1b80) msg 0x619000354380 from (udp/172.19.0.2:5080) has 349 bytes, veclen = 1
recv 349 bytes from udp/[172.19.0.2]:5062 at 20:28:45.691177:
------------------------------------------------------------------------
INVITE sip:1212121212@172.19.0.2:5080 SIP/2.0
Via: SIP/2.0/UDP 172.19.0.2:5062;branch=z9hG4bK-18762-1-6
From: t_sipp <sip:t_sipp@172.19.0.2:5062>;tag=1
To: sut <sip:1212121212@172.19.0.2:5080>
Call-ID: 1-18762@172.19.0.2
CSeq: 2 INVITE
Contact: sip:t_sipp@172.19.0.2:5062
Max-Forwards: 70
Subject: Performance Test
Content-Length:     0


tport.c:3055 tport_deliver() tport_deliver(0x6160000f1b80): msg 0x619000354380 (349 bytes) from udp/172.19.0.2:5080/sip next=(nil)
nta.c:2957 agent_recv_request() nta: received INVITE sip:1212121212@172.19.0.2:5080 SIP/2.0 (CSeq 2) (load: 1 rps)
nta.c:3326 agent_aliases() nta: canonizing sip:1212121212@172.19.0.2:5080 with contact
nta.c:3139 agent_recv_request() nta: INVITE (2) going to existing leg
nta.c:1369 set_timeout() nta: timer shortened to 200 ms
nua_server.c:102 nua_stack_process_request() nua: nua_stack_process_request: entering
soa.c:1301 soa_init_offer_answer() soa_init_offer_answer(static::0x6150000b0e80) called
nua_stack.c:301 nua_stack_event() nua(0x6120000f28c0): event i_invite 100 Trying
nua_session.c:4138 signal_call_state_change() nua(0x6120000f28c0): ready call updated: received
nua_stack.c:301 nua_stack_event() nua(0x6120000f28c0): event i_state 100 Trying
nua_stack.c:389 nua_application_event() nua: nua_application_event: entering
nua.c:1170 nua_handle_unref_user() nua nua_handle_unref_user(0x6120000f28c0): entering
nua_stack.c:558 nua_signal() nua(0x6120000f28c0): sent signal r_handle_unref
nua.c:1157 nua_unref_user() nua: nua_unref_user: entering
nua_stack.c:558 nua_signal() nua((nil)): sent signal r_unref
nua_stack.c:389 nua_application_event() nua: nua_application_event: entering
nua.c:1170 nua_handle_unref_user() nua nua_handle_unref_user(0x6120000f28c0): entering
nua_stack.c:558 nua_signal() nua(0x6120000f28c0): sent signal r_handle_unref
nua.c:1157 nua_unref_user() nua: nua_unref_user: entering
nua_stack.c:558 nua_signal() nua((nil)): sent signal r_unref
nua_stack.c:599 nua_stack_signal() nua(0x6120000f28c0): recv signal r_handle_unref
nua_stack.c:599 nua_stack_signal() nua((nil)): recv signal r_unref
nua_stack.c:599 nua_stack_signal() nua(0x6120000f28c0): recv signal r_handle_unref
nua_stack.c:599 nua_stack_signal() nua((nil)): recv signal r_unref
nua.c:365 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:878 nua_respond() nua: nua_respond: entering
nua_stack.c:601 nua_stack_signal() nua(0x6120000f28c0): recv signal r_respond 100 Trying
nua_params.c:484 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:402 soa_set_params() soa_set_params(static::0x6150000b0e80, ...) called
tport.c:3290 tport_tsend() tport_tsend(0x6160000f1b80) tpn = UDP/172.19.0.2:5062
tport.c:4076 tport_resolve() tport_resolve addrinfo = 172.19.0.2:5062
tport.c:4713 tport_by_addrinfo() tport_by_addrinfo(0x6160000f1b80): not found by name UDP/172.19.0.2:5062
tport.c:3625 tport_vsend() tport_vsend(0x6160000f1b80): 277 bytes of 277 to udp/172.19.0.2:5062
tport.c:3526 tport_send_msg() tport_vsend returned 277
send 277 bytes to udp/[172.19.0.2]:5062 at 20:28:45.694825:
------------------------------------------------------------------------
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 172.19.0.2:5062;branch=z9hG4bK-18762-1-6
From: t_sipp <sip:t_sipp@172.19.0.2:5062>;tag=1
To: sut <sip:1212121212@172.19.0.2:5080>;tag=BF0Z356DDK23p
Call-ID: 1-18762@172.19.0.2
CSeq: 2 INVITE
User-Agent: Unit Test
Content-Length: 0


nta.c:6879 incoming_reply() nta: sent 100 Trying for INVITE (2)
nua_stack.c:558 nua_signal() nua(0x6120000f28c0): sent signal r_respond
nua.c:365 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:1170 nua_handle_unref_user() nua nua_handle_unref_user(0x6120000f28c0): entering
nua_stack.c:558 nua_signal() nua(0x6120000f28c0): sent signal r_handle_unref
nua.c:1157 nua_unref_user() nua: nua_unref_user: entering
nua_stack.c:558 nua_signal() nua((nil)): sent signal r_unref
nua.c:365 nua_handle_magic() nua: nua_handle_magic: entering
04af4a7b-e0b7-449e-89ea-fb59839ffdec 2023-11-03 20:28:45.824579 93.33% [DEBUG] sofia.c:7493 Channel sofia/external/t_sipp@172.19.0.2:5062 entering state [received][100]
nua.c:878 nua_respond() nua: nua_respond: entering
nua_stack.c:558 nua_signal() nua(0x6120000f28c0): sent signal r_respond
nua.c:365 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:1170 nua_handle_unref_user() nua nua_handle_unref_user(0x6120000f28c0): entering
nua_stack.c:558 nua_signal() nua(0x6120000f28c0): sent signal r_handle_unref
nua.c:1157 nua_unref_user() nua: nua_unref_user: entering
nua_stack.c:558 nua_signal() nua((nil)): sent signal r_unref
nua_stack.c:599 nua_stack_signal() nua(0x6120000f28c0): recv signal r_handle_unref
nua_stack.c:599 nua_stack_signal() nua((nil)): recv signal r_unref
nua_stack.c:601 nua_stack_signal() nua(0x6120000f28c0): recv signal r_respond 200 OK
nua_params.c:484 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:402 soa_set_params() soa_set_params(static::0x6150000b0e80, ...) called
soa.c:1051 soa_set_user_sdp() soa_set_user_sdp(static::0x6150000b0e80, (nil), 0x61500017037f, -1) called
nua_session.c:2317 nua_invite_server_respond() nua: nua_invite_server_respond: entering
soa.c:1425 soa_generate_offer() soa_generate_offer(static::0x6150000b0e80, 0) called
soa_static.c:1147 offer_answer_step() soa_static_offer_answer_action(0x6150000b0e80, soa_generate_offer): called
soa_static.c:1216 offer_answer_step() soa_static(0x6150000b0e80, soa_generate_offer): upgrade with local description
soa_static.c:1028 soa_sdp_mode_set() soa_sdp_mode_set(0x7fd316caf720, (nil), ""): called
soa_static.c:1445 offer_answer_step() soa_static(0x6150000b0e80, soa_generate_offer): storing local description
soa.c:1268 soa_get_local_sdp() soa_get_local_sdp(static::0x6150000b0e80, [(nil)], [0x7fd316caf820], [0x7fd316caf81c]) called
tport.c:3290 tport_tsend() tport_tsend(0x6160000f1b80) tpn = UDP/172.19.0.2:5062
tport.c:4076 tport_resolve() tport_resolve addrinfo = 172.19.0.2:5062
tport.c:4713 tport_by_addrinfo() tport_by_addrinfo(0x6160000f1b80): not found by name UDP/172.19.0.2:5062
tport.c:3625 tport_vsend() tport_vsend(0x6160000f1b80): 761 bytes of 761 to udp/172.19.0.2:5062
tport.c:3526 tport_send_msg() tport_vsend returned 761
send 761 bytes to udp/[172.19.0.2]:5062 at 20:28:45.834358:
------------------------------------------------------------------------
SIP/2.0 200 OK
Via: SIP/2.0/UDP 172.19.0.2:5062;branch=z9hG4bK-18762-1-6
From: t_sipp <sip:t_sipp@172.19.0.2:5062>;tag=1
To: sut <sip:1212121212@172.19.0.2:5080>;tag=BF0Z356DDK23p
Call-ID: 1-18762@172.19.0.2
CSeq: 2 INVITE
Contact: <sip:1212121212@172.19.0.2:5080;transport=udp>
User-Agent: Unit Test
Accept: application/sdp
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
Supported: timer, path, replaces
Session-Expires: 600;refresher=uas
Content-Type: application/sdp
Content-Disposition: session
Content-Length: 183

v=0
o=FS 1699020340 1699020342 IN IP4 172.19.0.2
s=FS
c=IN IP4 172.19.0.2
t=0 0
m=audio 22984 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=ptime:20

nta.c:6879 incoming_reply() nta: sent 200 OK for INVITE (2)
nua_session.c:4138 signal_call_state_change() nua(0x6120000f28c0): ready call updated: completed sent offer
soa.c:1268 soa_get_local_sdp() soa_get_local_sdp(static::0x6150000b0e80, [0x7fd316caf8e8], [0x7fd316caf8e0], [(nil)]) called
nua_stack.c:301 nua_stack_event() nua(0x6120000f28c0): event i_state 200 OK
nua_stack.c:599 nua_stack_signal() nua(0x6120000f28c0): recv signal r_handle_unref
nua_stack.c:599 nua_stack_signal() nua((nil)): recv signal r_unref
nua_stack.c:389 nua_application_event() nua: nua_application_event: entering
nua.c:1170 nua_handle_unref_user() nua nua_handle_unref_user(0x6120000f28c0): entering
nua_stack.c:558 nua_signal() nua(0x6120000f28c0): sent signal r_handle_unref
nua.c:1157 nua_unref_user() nua: nua_unref_user: entering
nua_stack.c:558 nua_signal() nua((nil)): sent signal r_unref
tport.c:2769 tport_wakeup_pri() tport_wakeup_pri(0x6160000f1b80): events IN
tport.c:2900 tport_recv_event() tport_recv_event(0x6160000f1b80)
tport.c:3237 tport_recv_iovec() tport_recv_iovec(0x6160000f1b80) msg 0x619000356680 from (udp/172.19.0.2:5080) has 626 bytes, veclen = 1
recv 626 bytes from udp/[172.19.0.2]:5062 at 20:28:45.835922:
------------------------------------------------------------------------
ACK sip:1212121212@172.19.0.2:5080 SIP/2.0
Via: SIP/2.0/UDP 172.19.0.2:5062;branch=z9hG4bK-18762-1-9
From: t_sipp <sip:t_sipp@172.19.0.2:5062>;tag=1
To: sut <sip:1212121212@172.19.0.2:5080>;tag=BF0Z356DDK23p
Call-ID: 1-18762@172.19.0.2
CSeq: 2 ACK
Contact: sip:t_sipp@172.19.0.2:5062
Max-Forwards: 70
Subject: Performance Test
Content-Type: application/sdp
Content-Length:   234

v=0
o=user1 53655765 2353687637 IN IP4 172.19.0.2
s=
c=IN IP4 172.19.0.2
t=0 0
m=audio 6000 RTP/AVP 8 0 101
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=sendrecv
a=ptime:20

tport.c:3055 tport_deliver() tport_deliver(0x6160000f1b80): msg 0x619000356680 (626 bytes) from udp/172.19.0.2:5080/sip next=(nil)
nta.c:2957 agent_recv_request() nta: received ACK sip:1212121212@172.19.0.2:5080 SIP/2.0 (CSeq 2) (load: 1 rps)
nta.c:3097 agent_recv_request() nta: ACK (2) is going to INVITE (2)
nua_session.c:2566 process_ack_or_cancel() nua: process_ack_or_cancel: entering
soa.c:1170 soa_set_remote_sdp() soa_set_remote_sdp(static::0x6150000b0e80, (nil), 0x6160000f8308, 234) called
soa.c:1594 soa_process_answer() soa_process_answer(static::0x6150000b0e80) called
soa_static.c:1147 offer_answer_step() soa_static_offer_answer_action(0x6150000b0e80, soa_process_answer): called
soa_static.c:1028 soa_sdp_mode_set() soa_sdp_mode_set(0x6170000b4480, 0x6170000b5600, ""): called
soa_static.c:1303 offer_answer_step() soa_static(0x6150000b0e80, soa_process_answer): upgrade codecs with remote description
soa.c:1729 soa_activate() soa_activate(static::0x6150000b0e80, (nil)) called
soa.c:1213 soa_clear_remote_sdp() soa_clear_remote_sdp(static::0x6150000b0e80) called
nua_stack.c:301 nua_stack_event() nua(0x6120000f28c0): event i_ack 200 OK
nua_session.c:4138 signal_call_state_change() nua(0x6120000f28c0): ready call updated: ready received answer
nua.c:365 nua_handle_magic() nua: nua_handle_magic: entering
nua_stack.c:389 nua_application_event() nua: nua_application_event: entering
nua.c:1170 nua_handle_unref_user() nua nua_handle_unref_user(0x6120000f28c0): entering
nua_stack.c:558 nua_signal() nua(0x6120000f28c0): sent signal r_handle_unref
nua.c:1157 nua_unref_user() nua: nua_unref_user: entering
nua_stack.c:558 nua_signal() nua((nil)): sent signal r_unref
soa.c:1096 soa_get_remote_sdp() soa_get_remote_sdp(static::0x6150000b0e80, [0x7fd316caf4c8], [0x7fd316caf4c0], [(nil)]) called
soa.c:615 soa_get_params() soa_get_params(static::0x6150000b0e80, ...) called
nua_stack.c:301 nua_stack_event() nua(0x6120000f28c0): event i_state 200 OK
nua_stack.c:301 nua_stack_event() nua(0x6120000f28c0): event i_active 200 Call active
nua_dialog.c:563 nua_dialog_usage_set_refresh_range() nua(): refresh session after 298 seconds (in [295..305])
nua_stack.c:599 nua_stack_signal() nua(0x6120000f28c0): recv signal r_handle_unref
nua_stack.c:599 nua_stack_signal() nua((nil)): recv signal r_unref
nua_stack.c:599 nua_stack_signal() nua(0x6120000f28c0): recv signal r_handle_unref
nua_stack.c:599 nua_stack_signal() nua((nil)): recv signal r_unref
tport.c:2769 tport_wakeup_pri() tport_wakeup_pri(0x6160000f1b80): events IN
nua_stack.c:389 nua_application_event() nua: nua_application_event: entering
nua.c:1170 nua_handle_unref_user() nua nua_handle_unref_user(0x6120000f28c0): entering
nua_stack.c:558 nua_signal() nua(0x6120000f28c0): sent signal r_handle_unref
nua.c:1157 nua_unref_user() nua: nua_unref_user: entering
nua_stack.c:558 nua_signal() nua((nil)): sent signal r_unref
nua_stack.c:389 nua_application_event() nua: nua_application_event: entering
nua.c:1170 nua_handle_unref_user() nua nua_handle_unref_user(0x6120000f28c0): entering
nua_stack.c:558 nua_signal() nua(0x6120000f28c0): sent signal r_handle_unref
nua.c:1157 nua_unref_user() nua: nua_unref_user: entering
nua_stack.c:558 nua_signal() nua((nil)): sent signal r_unref
tport.c:2900 tport_recv_event() tport_recv_event(0x6160000f1b80)
tport.c:3237 tport_recv_iovec() tport_recv_iovec(0x6160000f1b80) msg 0x619000356b80 from (udp/172.19.0.2:5080) has 358 bytes, veclen = 1
04af4a7b-e0b7-449e-89ea-fb59839ffdec 2023-11-03 20:28:45.824579 93.33% [DEBUG] sofia.c:7493 Channel sofia/external/t_sipp@172.19.0.2:5062 entering state [completed][200]
nua.c:365 nua_handle_magic() nua: nua_handle_magic: entering
recv 358 bytes from udp/[172.19.0.2]:5062 at 20:28:45.839978:
------------------------------------------------------------------------
BYE sip:1212121212@172.19.0.2:5080 SIP/2.0
Via: SIP/2.0/UDP 172.19.0.2:5062;branch=z9hG4bK-18762-1-10
From: t_sipp <sip:t_sipp@172.19.0.2:5062>;tag=1
To: sut <sip:1212121212@172.19.0.2:5080>;tag=BF0Z356DDK23p
Call-ID: 1-18762@172.19.0.2
CSeq: 3 BYE
Contact: sip:t_sipp@172.19.0.2:5062
Max-Forwards: 70
Subject: Performance Test
Content-Length: 0


tport.c:3055 tport_deliver() tport_deliver(0x6160000f1b80): msg 0x619000356b80 (358 bytes) from udp/172.19.0.2:5080/sip next=(nil)
nta.c:2957 agent_recv_request() nta: received BYE sip:1212121212@172.19.0.2:5080 SIP/2.0 (CSeq 3) (load: 1 rps)
nta.c:3326 agent_aliases() nta: canonizing sip:1212121212@172.19.0.2:5080 with contact
nta.c:3139 agent_recv_request() nta: BYE (3) going to existing leg
nua_server.c:102 nua_stack_process_request() nua: nua_stack_process_request: entering
nua_stack.c:301 nua_stack_event() nua(0x6120000f28c0): event i_bye 100 Trying
nua_stack.c:389 nua_application_event() nua: nua_application_event: entering
nua.c:1170 nua_handle_unref_user() nua nua_handle_unref_user(0x6120000f28c0): entering
nua_stack.c:558 nua_signal() nua(0x6120000f28c0): sent signal r_handle_unref
nua.c:1157 nua_unref_user() nua: nua_unref_user: entering
nua_stack.c:558 nua_signal() nua((nil)): sent signal r_unref
nua_stack.c:599 nua_stack_signal() nua(0x6120000f28c0): recv signal r_handle_unref
nua_stack.c:599 nua_stack_signal() nua((nil)): recv signal r_unref
nua_stack.c:599 nua_stack_signal() nua(0x6120000f28c0): recv signal r_handle_unref
nua_stack.c:599 nua_stack_signal() nua((nil)): recv signal r_unref
nua.c:1170 nua_handle_unref_user() nua nua_handle_unref_user(0x6120000f28c0): entering
nua_stack.c:599 nua_stack_signal() nua(0x6120000f28c0): recv signal r_handle_unref
nua_stack.c:599 nua_stack_signal() nua((nil)): recv signal r_unref
nua_stack.c:599 nua_stack_signal() nua(0x6120000f28c0): recv signal r_handle_unref
nua_stack.c:558 nua_signal() nua(0x6120000f28c0): sent signal r_handle_unref
nua.c:1157 nua_unref_user() nua: nua_unref_user: entering
nua_stack.c:558 nua_signal() nua((nil)): sent signal r_unref
nua.c:365 nua_handle_magic() nua: nua_handle_magic: entering
nua_stack.c:599 nua_stack_signal() nua((nil)): recv signal r_unref
nua.c:365 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:1170 nua_handle_unref_user() nua nua_handle_unref_user(0x6120000f28c0): entering
nua_stack.c:599 nua_stack_signal() nua(0x6120000f28c0): recv signal r_handle_unref
nua_stack.c:558 nua_signal() nua(0x6120000f28c0): sent signal r_handle_unref
nua.c:1157 nua_unref_user() nua: nua_unref_user: entering
nua_stack.c:599 nua_stack_signal() nua((nil)): recv signal r_unref
nua_stack.c:558 nua_signal() nua((nil)): sent signal r_unref
nua.c:365 nua_handle_magic() nua: nua_handle_magic: entering
04af4a7b-e0b7-449e-89ea-fb59839ffdec 2023-11-03 20:28:45.864603 90.00% [DEBUG] sofia.c:7493 Channel sofia/external/t_sipp@172.19.0.2:5062 entering state [ready][200]
04af4a7b-e0b7-449e-89ea-fb59839ffdec 2023-11-03 20:28:45.864603 90.00% [DEBUG] sofia.c:7503 Remote SDP:
v=0
o=user1 53655765 2353687637 IN IP4 172.19.0.2
s=
c=IN IP4 172.19.0.2
t=0 0
m=audio 6000 RTP/AVP 8 0 101
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20

04af4a7b-e0b7-449e-89ea-fb59839ffdec 2023-11-03 20:28:45.864603 90.00% [DEBUG] switch_core_media.c:5526 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
04af4a7b-e0b7-449e-89ea-fb59839ffdec 2023-11-03 20:28:45.864603 90.00% [DEBUG] switch_core_media.c:5526 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
04af4a7b-e0b7-449e-89ea-fb59839ffdec 2023-11-03 20:28:45.864603 90.00% [DEBUG] switch_core_media.c:5588 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
04af4a7b-e0b7-449e-89ea-fb59839ffdec 2023-11-03 20:28:45.864603 90.00% [DEBUG] switch_core_media.c:5438 Set telephone-event payload to 101@8000
04af4a7b-e0b7-449e-89ea-fb59839ffdec 2023-11-03 20:28:45.864603 90.00% [DEBUG] switch_core_media.c:5798 Set telephone-event payload to 101@8000
04af4a7b-e0b7-449e-89ea-fb59839ffdec 2023-11-03 20:28:45.864603 90.00% [DEBUG] switch_core_media.c:5856 sofia/external/t_sipp@172.19.0.2:5062 Set 2833 dtmf send payload to 101 recv payload to 101
04af4a7b-e0b7-449e-89ea-fb59839ffdec 2023-11-03 20:28:45.864603 90.00% [DEBUG] switch_core_media.c:8642 Audio params are unchanged for sofia/external/t_sipp@172.19.0.2:5062.
nua.c:365 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:1170 nua_handle_unref_user() nua nua_handle_unref_user(0x6120000f28c0): entering
nua_stack.c:599 nua_stack_signal() nua(0x6120000f28c0): recv signal r_handle_unref
nua_stack.c:558 nua_signal() nua(0x6120000f28c0): sent signal r_handle_unref
nua.c:1157 nua_unref_user() nua: nua_unref_user: entering
nua_stack.c:599 nua_stack_signal() nua((nil)): recv signal r_unref
nua_stack.c:558 nua_signal() nua((nil)): sent signal r_unref
nua.c:365 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:365 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:1170 nua_handle_unref_user() nua nua_handle_unref_user(0x6120000f28c0): entering
nua_stack.c:599 nua_stack_signal() nua(0x6120000f28c0): recv signal r_handle_unref
nua_stack.c:558 nua_signal() nua(0x6120000f28c0): sent signal r_handle_unref
nua.c:1157 nua_unref_user() nua: nua_unref_user: entering
nua_stack.c:599 nua_stack_signal() nua((nil)): recv signal r_unref
nua_stack.c:558 nua_signal() nua((nil)): sent signal r_unref
nua.c:365 nua_handle_magic() nua: nua_handle_magic: entering
nta.c:1317 agent_timer() nta: timer set next to 2159 ms
04af4a7b-e0b7-449e-89ea-fb59839ffdec 2023-11-03 20:28:45.920877 90.00% [NOTICE] sofia.c:1065 Hangup sofia/external/t_sipp@172.19.0.2:5062 [CS_EXECUTE] [NORMAL_CLEARING]
nua.c:878 nua_respond() nua: nua_respond: entering
nua_stack.c:601 nua_stack_signal() nua(0x6120000f28c0): recv signal r_respond 200 OK
nua_params.c:484 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:402 soa_set_params() soa_set_params(static::0x6150000b0e80, ...) called
tport.c:3290 tport_tsend() tport_tsend(0x6160000f1b80) tpn = UDP/172.19.0.2:5062
tport.c:4076 tport_resolve() tport_resolve addrinfo = 172.19.0.2:5062
tport.c:4713 tport_by_addrinfo() tport_by_addrinfo(0x6160000f1b80): not found by name UDP/172.19.0.2:5062
tport.c:3625 tport_vsend() tport_vsend(0x6160000f1b80): 395 bytes of 395 to udp/172.19.0.2:5062
tport.c:3526 tport_send_msg() tport_vsend returned 395
send 395 bytes to udp/[172.19.0.2]:5062 at 20:28:45.962841:
------------------------------------------------------------------------
SIP/2.0 200 OK
Via: SIP/2.0/UDP 172.19.0.2:5062;branch=z9hG4bK-18762-1-10
From: t_sipp <sip:t_sipp@172.19.0.2:5062>;tag=1
To: sut <sip:1212121212@172.19.0.2:5080>;tag=BF0Z356DDK23p
Call-ID: 1-18762@172.19.0.2
CSeq: 3 BYE
User-Agent: Unit Test
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
Supported: timer, path, replaces
Content-Length: 0


nta.c:6879 incoming_reply() nta: sent 200 OK for BYE (3)
nua_dialog.c:395 nua_dialog_usage_remove_at() nua(0x6120000f28c0): removing session usage
nua_session.c:4131 signal_call_state_change() nua(0x6120000f28c0): call state changed: ready -> terminated
nua_stack.c:301 nua_stack_event() nua(0x6120000f28c0): event i_state 200 Session Terminated
nua_stack.c:301 nua_stack_event() nua(0x6120000f28c0): event i_terminated 200 Session Terminated
soa.c:355 soa_destroy() soa_destroy(static::0x6150000b0e80) called
nta.c:4550 nta_leg_destroy() nta_leg_destroy(0x60c000086740)
nua_stack.c:389 nua_application_event() nua: nua_application_event: entering
nua.c:1170 nua_handle_unref_user() nua nua_handle_unref_user(0x6120000f28c0): entering
nua.c:365 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:1170 nua_handle_unref_user() nua nua_handle_unref_user(0x6120000f28c0): entering
nua_stack.c:558 nua_signal() nua(0x6120000f28c0): sent signal r_handle_unref
nua.c:1157 nua_unref_user() nua: nua_unref_user: entering
nua_stack.c:558 nua_signal() nua((nil)): sent signal r_unref
nua_stack.c:599 nua_stack_signal() nua(0x6120000f28c0): recv signal r_handle_unref
nua_stack.c:599 nua_stack_signal() nua(0x6120000f28c0): recv signal r_handle_unref
nua_stack.c:558 nua_signal() nua(0x6120000f28c0): sent signal r_handle_unref
nua.c:1157 nua_unref_user() nua: nua_unref_user: entering
nua_stack.c:558 nua_signal() nua((nil)): sent signal r_unref
nua_stack.c:389 nua_application_event() nua: nua_application_event: entering
nua.c:1170 nua_handle_unref_user() nua nua_handle_unref_user(0x6120000f28c0): entering
nua_stack.c:558 nua_signal() nua(0x6120000f28c0): sent signal r_handle_unref
nua.c:1157 nua_unref_user() nua: nua_unref_user: entering
nua_stack.c:558 nua_signal() nua((nil)): sent signal r_unref
nua.c:365 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:1170 nua_handle_unref_user() nua nua_handle_unref_user(0x6120000f28c0): entering
nua_stack.c:558 nua_signal() nua(0x6120000f28c0): sent signal r_handle_unref
nua.c:1157 nua_unref_user() nua: nua_unref_user: entering
nua_stack.c:558 nua_signal() nua((nil)): sent signal r_unref
nua_stack.c:599 nua_stack_signal() nua((nil)): recv signal r_unref
nua_stack.c:599 nua_stack_signal() nua((nil)): recv signal r_unref
nua_stack.c:599 nua_stack_signal() nua(0x6120000f28c0): recv signal r_handle_unref
nua_stack.c:599 nua_stack_signal() nua((nil)): recv signal r_unref
nua_stack.c:599 nua_stack_signal() nua(0x6120000f28c0): recv signal r_handle_unref
nua_stack.c:558 nua_signal() nua(0x6120000f28c0): sent signal r_respond
nua_stack.c:599 nua_stack_signal() nua((nil)): recv signal r_unref
nua.c:341 nua_handle_bind() nua: nua_handle_bind: entering
nua.c:920 nua_handle_destroy() nua: nua_handle_destroy: entering
nua_stack.c:558 nua_signal() nua(0x6120000f28c0): sent signal r_destroy
nua.c:1170 nua_handle_unref_user() nua nua_handle_unref_user(0x6120000f28c0): entering
nua_stack.c:558 nua_signal() nua(0x6120000f28c0): sent signal r_handle_unref
nua.c:1157 nua_unref_user() nua: nua_unref_user: entering
nua_stack.c:558 nua_signal() nua((nil)): sent signal r_unref
nua_stack.c:599 nua_stack_signal() nua(0x6120000f28c0): recv signal r_destroy
nta.c:4550 nta_leg_destroy() nta_leg_destroy((nil))
nua_stack.c:599 nua_stack_signal() nua(0x6120000f28c0): recv signal r_handle_unref
nua_stack.c:599 nua_stack_signal() nua((nil)): recv signal r_unref
04af4a7b-e0b7-449e-89ea-fb59839ffdec 2023-11-03 20:28:45.964591 90.00% [DEBUG] switch_core_session.c:2979 sofia/external/t_sipp@172.19.0.2:5062 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
04af4a7b-e0b7-449e-89ea-fb59839ffdec 2023-11-03 20:28:45.964591 90.00% [DEBUG] switch_core_state_machine.c:647 (sofia/external/t_sipp@172.19.0.2:5062) State EXECUTE going to sleep
04af4a7b-e0b7-449e-89ea-fb59839ffdec 2023-11-03 20:28:45.964591 90.00% [DEBUG] switch_core_state_machine.c:581 (sofia/external/t_sipp@172.19.0.2:5062) Running State Change CS_HANGUP (Cur 1 Tot 1)
04af4a7b-e0b7-449e-89ea-fb59839ffdec 2023-11-03 20:28:45.984578 90.00% [DEBUG] switch_core_state_machine.c:844 (sofia/external/t_sipp@172.19.0.2:5062) Callstate Change ACTIVE -> HANGUP
04af4a7b-e0b7-449e-89ea-fb59839ffdec 2023-11-03 20:28:45.984578 90.00% [DEBUG] switch_core_state_machine.c:846 (sofia/external/t_sipp@172.19.0.2:5062) State HANGUP
04af4a7b-e0b7-449e-89ea-fb59839ffdec 2023-11-03 20:28:45.984578 90.00% [DEBUG] mod_sofia.c:469 Channel sofia/external/t_sipp@172.19.0.2:5062 hanging up, cause: NORMAL_CLEARING
04af4a7b-e0b7-449e-89ea-fb59839ffdec 2023-11-03 20:28:45.984578 90.00% [DEBUG] switch_core_state_machine.c:59 sofia/external/t_sipp@172.19.0.2:5062 Standard HANGUP, cause: NORMAL_CLEARING
04af4a7b-e0b7-449e-89ea-fb59839ffdec 2023-11-03 20:28:45.984578 90.00% [DEBUG] switch_core_state_machine.c:846 (sofia/external/t_sipp@172.19.0.2:5062) State HANGUP going to sleep
04af4a7b-e0b7-449e-89ea-fb59839ffdec 2023-11-03 20:28:46.004588 90.00% [DEBUG] switch_core_state_machine.c:616 (sofia/external/t_sipp@172.19.0.2:5062) State Change CS_HANGUP -> CS_REPORTING
04af4a7b-e0b7-449e-89ea-fb59839ffdec 2023-11-03 20:28:46.004588 90.00% [DEBUG] switch_core_state_machine.c:581 (sofia/external/t_sipp@172.19.0.2:5062) Running State Change CS_REPORTING (Cur 1 Tot 1)
04af4a7b-e0b7-449e-89ea-fb59839ffdec 2023-11-03 20:28:46.004588 90.00% [DEBUG] switch_core_state_machine.c:932 (sofia/external/t_sipp@172.19.0.2:5062) State REPORTING
04af4a7b-e0b7-449e-89ea-fb59839ffdec 2023-11-03 20:28:46.004588 90.00% [DEBUG] switch_core_state_machine.c:168 sofia/external/t_sipp@172.19.0.2:5062 Standard REPORTING, cause: NORMAL_CLEARING
04af4a7b-e0b7-449e-89ea-fb59839ffdec 2023-11-03 20:28:46.004588 90.00% [DEBUG] switch_core_state_machine.c:932 (sofia/external/t_sipp@172.19.0.2:5062) State REPORTING going to sleep
04af4a7b-e0b7-449e-89ea-fb59839ffdec 2023-11-03 20:28:46.004588 90.00% [DEBUG] switch_core_state_machine.c:607 (sofia/external/t_sipp@172.19.0.2:5062) State Change CS_REPORTING -> CS_DESTROY
04af4a7b-e0b7-449e-89ea-fb59839ffdec 2023-11-03 20:28:46.004588 90.00% [DEBUG] switch_core_session.c:1744 Session 1 (sofia/external/t_sipp@172.19.0.2:5062) Locked, Waiting on external entities
04af4a7b-e0b7-449e-89ea-fb59839ffdec 2023-11-03 20:28:46.021116 90.00% [NOTICE] switch_core_session.c:1762 Session 1 (sofia/external/t_sipp@172.19.0.2:5062) Ended
04af4a7b-e0b7-449e-89ea-fb59839ffdec 2023-11-03 20:28:46.021116 90.00% [NOTICE] switch_core_session.c:1766 Close Channel sofia/external/t_sipp@172.19.0.2:5062 [CS_DESTROY]
04af4a7b-e0b7-449e-89ea-fb59839ffdec 2023-11-03 20:28:46.021116 90.00% [DEBUG] switch_core_state_machine.c:735 (sofia/external/t_sipp@172.19.0.2:5062) Running State Change CS_DESTROY (Cur 0 Tot 1)
04af4a7b-e0b7-449e-89ea-fb59839ffdec 2023-11-03 20:28:46.021116 90.00% [DEBUG] switch_core_state_machine.c:745 (sofia/external/t_sipp@172.19.0.2:5062) State DESTROY
04af4a7b-e0b7-449e-89ea-fb59839ffdec 2023-11-03 20:28:46.042089 90.00% [DEBUG] mod_sofia.c:380 sofia/external/t_sipp@172.19.0.2:5062 SOFIA DESTROY
04af4a7b-e0b7-449e-89ea-fb59839ffdec 2023-11-03 20:28:46.042089 90.00% [DEBUG] switch_core_state_machine.c:175 sofia/external/t_sipp@172.19.0.2:5062 Standard DESTROY
04af4a7b-e0b7-449e-89ea-fb59839ffdec 2023-11-03 20:28:46.042089 90.00% [DEBUG] switch_core_state_machine.c:745 (sofia/external/t_sipp@172.19.0.2:5062) State DESTROY going to sleep
2023-11-03 20:28:46.064588 90.00% [WARNING] switch_core.c:3492 Exit status (256): pkill -x sipp
nua.c:138 nua_create() nua: nua_create: entering
su_epoll_port.c:540 su_epoll_port_create() su_port_create(0x611000180000): epoll_create() => 0: OK
su_socket_port.c:87 su_socket_port_init() su_socket_port_init(0x611000180000, 0x7fd315f49dc0) called
su_pthread_port.c:72 su_pthread_port_init() su_pthread_port_init(0x611000180000, 0x7fd315f49dc0) called
nua_stack.c:128 nua_stack_init() nua: nua_stack_init: entering
nua_params.c:484 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:228 soa_create() soa_create("default", 0x60600009ffe0, 0x615000180180) called
soa.c:402 soa_set_params() soa_set_params(static::0x615000180400, ...) called
soa.c:402 soa_set_params() soa_set_params(static::0x615000180400, ...) called
nta.c:978 nta_agent_create() nta_agent_create: initialized hash tables
nta.c:985 nta_agent_create() nta_agent_create: initialized transports
nta.c:991 nta_agent_create() nta_agent_create: initialized random identifiers
nta.c:997 nta_agent_create() nta_agent_create: initialized timer
nta.c:1007 nta_agent_create() nta_agent_create: initialized resolver
tport.c:498 tport_tcreate() tport_create(): 0x617000120900
nta.c:2335 agent_create_master_transport() nta: master transport created
tport.c:1625 tport_bind_server() tport_bind_server(0x617000120900) to */[0000:0000:0000:0000:0000:0000:0000:0001]:6060/sip
tport.c:1697 tport_bind_server() tport_bind_server(0x617000120900): calling tport_listen for udp
tport.c:625 tport_alloc_primary() tport_alloc_primary(0x617000120900): new primary tport 0x6160001d1980
tport.c:732 tport_listen() tport_listen(0x617000120900): bind(pf=10 udp/[::1]:6060): Cannot assign requested address
tport.c:1697 tport_bind_server() tport_bind_server(0x617000120900): calling tport_listen for tcp
tport.c:625 tport_alloc_primary() tport_alloc_primary(0x617000120900): new primary tport 0x6160001d1f80
tport.c:732 tport_listen() tport_listen(0x617000120900): bind(pf=10 tcp/[::1]:6060): Cannot assign requested address
nta.c:2279 nta_agent_add_tport() nta: bind([0000:0000:0000:0000:0000:0000:0000:0001]:6060;transport=*): Cannot assign requested address
nua_stack.c:195 nua_stack_init() nua: initializing SIP stack failed
nua_stack.c:214 nua_stack_deinit() nua: nua_stack_deinBackground mode - PID=[18860]
it: entering
sresolv.c:189 sres_sofia_update() sres_sofia_update(0x60c0001000c0, -1, -1)
sresolv.c:189 sres_sofia_update() sres_sofia_update((nil), -1, -1)
tport.c:555 tport_destroy() tport_destroy(0x617000120900)
soa.c:355 soa_destroy() soa_destroy(static::0x615000180400) called
su_epoll_port.c:166 su_epoll_port_deinit() su_epoll_port_deinit(0x611000180000) called
2023-11-03 20:28:46.920868 86.67% [ERR] sofia.c:3302 Error Creating SIP UA for profile: external-ipv6 (sip:mod_sofia@[0000:0000:0000:0000:0000:0000:0000:0001]:6060;transport=udp,tcp) ATTEMPT 2 (RETRY IN 5 SEC)
 PASS
uac_savp_check ....................................................sipp 172.19.0.2:5080 -nr -p 5062 -m 1 -s 1212121212 -recv_timeout 10000 -timeout 10s -sf sipp-scenarios/uac_savp_check.xml -bg 
2023-11-03 20:28:47.280877 86.67% [WARNING] switch_core.c:3492 Exit status (25344): sipp 172.19.0.2:5080 -nr -p 5062 -m 1 -s 1212121212 -recv_timeout 10000 -timeout 10s -sf sipp-scenarios/uac_savp_check.xml -bg 
tport.c:2769 tport_wakeup_pri() tport_wakeup_pri(0x6160000f1b80): events IN
tport.c:2900 tport_recv_event() tport_recv_event(0x6160000f1b80)
tport.c:3237 tport_recv_iovec() tport_recv_iovec(0x6160000f1b80) msg 0x619000357a80 from (udp/172.19.0.2:5080) has 757 bytes, veclen = 1
recv 757 bytes from udp/[172.19.0.2]:5062 at 20:28:47.404891:
------------------------------------------------------------------------
INVITE sip:1212121212@172.19.0.2:5080 SIP/2.0
Via: SIP/2.0/UDP 172.19.0.2:5062;branch=z9hG4bK-18859-1-0
From: s_sipp <sip:s_sipp@172.19.0.2:5062>;tag=1
To: sut <sip:1212121212@172.19.0.2:5080>
Call-ID: 1-18859@172.19.0.2
CSeq: 1 INVITE
Contact: sip:s_sipp@172.19.0.2:5062
Max-Forwards: 70
Subject: Performance Test
Content-Type: application/sdp
Content-Length:   377

v=0
o=CiscoSystemsCCM-SIP 1195507 1 IN IP4 172.19.0.2
s=SIP Call
c=IN IP4 172.19.0.2
b=TIAS:64000
b=AS:80
t=0 0
m=audio 6000 RTP/SAVP 18 0 8 100
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:100 telephone-event/8000
a=fmtp:100 0-15
a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:mSPPjYxzAEWkICVXidkYXFdsHr/J2NhpkqQepffH

tport.c:3055 tport_deliver() tport_deliver(0x6160000f1b80): msg 0x619000357a80 (757 bytes) from udp/172.19.0.2:5080/sip next=(nil)
nta.c:2957 agent_recv_request() nta: received INVITE sip:1212121212@172.19.0.2:5080 SIP/2.0 (CSeq 1) (load: 1 rps)
nta.c:3326 agent_aliases() nta: canonizing sip:1212121212@172.19.0.2:5080 with contact
nta.c:3164 agent_recv_request() nta: INVITE (1) going to a default leg
nta.c:1369 set_timeout() nta: timer shortened to 200 ms
nua_server.c:102 nua_stack_process_request() nua: nua_stack_process_request: entering
nua_stack.c:938 nh_create() nua: nh_create: entering
nua_common.c:108 nh_create_handle() nua: nh_create_handle: entering
nua_params.c:484 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:278 soa_clone() soa_clone(static::0x6150000b0480, 0x606000050000, 0x6120000f9640) called
soa.c:402 soa_set_params() soa_set_params(static::0x6150000b3180, ...) called
nta.c:4497 nta_leg_tcreate() nta_leg_tcreate(0x60c000087940)
soa.c:1301 soa_init_offer_answer() soa_init_offer_answer(static::0x6150000b3180) called
soa.c:1170 soa_set_remote_sdp() soa_set_remote_sdp(static::0x6150000b3180, (nil), 0x6170000b6c7c, 377) called
nua_dialog.c:336 nua_dialog_usage_add() nua(0x6120000f9640): adding session usage
nua_stack.c:301 nua_stack_event() nua(0x6120000f9640): event i_invite 100 Trying
nua_session.c:4131 signal_call_state_change() nua(0x6120000f9640): call state changed: init -> received, received offer
soa.c:1096 soa_get_remote_sdp() soa_get_remote_sdp(static::0x6150000b3180, [0x7fd316caf398], [0x7fd316caf390], [(nil)]) called
nua_stack.c:301 nua_stack_event() nua(0x6120000f9640): event i_state 100 Trying
nua_stack.c:389 nua_application_event() nua: nua_application_event: entering
nua.c:341 nua_handle_bind() nua: nua_handle_bind: entering
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe 2023-11-03 20:28:47.400886 86.67% [NOTICE] switch_channel.c:1143 New Channel sofia/external/s_sipp@172.19.0.2:5062 [8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe]
nua.c:1170 nua_handle_unref_user() nua nua_handle_unref_user(0x6120000f9640): entering
nua_stack.c:558 nua_signal() nua(0x6120000f9640): sent signal r_handle_unref
nua.c:1157 nua_unref_user() nua: nua_unref_user: entering
nua_stack.c:558 nua_signal() nua((nil)): sent signal r_unref
nua_stack.c:389 nua_application_event() nua: nua_application_event: entering
nua.c:1170 nua_handle_unref_user() nua nua_handle_unref_user(0x6120000f9640): entering
nua_stack.c:558 nua_signal() nua(0x6120000f9640): sent signal r_handle_unref
nua.c:1157 nua_unref_user() nua: nua_unref_user: entering
nua_stack.c:558 nua_signal() nua((nil)): sent signal r_unref
nua_stack.c:599 nua_stack_signal() nua(0x6120000f9640): recv signal r_handle_unref
nua_stack.c:599 nua_stack_signal() nua((nil)): recv signal r_unref
nua_stack.c:599 nua_stack_signal() nua(0x6120000f9640): recv signal r_handle_unref
nua_stack.c:599 nua_stack_signal() nua((nil)): recv signal r_unref
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe 2023-11-03 20:28:47.400886 86.67% [DEBUG] switch_core_state_machine.c:581 (sofia/external/s_sipp@172.19.0.2:5062) Running State Change CS_NEW (Cur 1 Tot 2)
nua.c:365 nua_handle_magic() nua: nua_handle_magic: entering
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe 2023-11-03 20:28:47.400886 86.67% [INFO] sofia.c:10459 sofia/external/s_sipp@172.19.0.2:5062 receiving invite from 172.19.0.2:5062 version: 1.10.11-dev git 583788b 2023-11-03 20:19:48Z 64bit call-id: 1-18859@172.19.0.2
nua.c:365 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:1170 nua_handle_unref_user() nua nua_handle_unref_user(0x6120000f9640): entering
nua_stack.c:558 nua_signal() nua(0x6120000f9640): sent signal r_handle_unref
nua.c:1157 nua_unref_user() nua: nua_unref_user: entering
nua_stack.c:558 nua_signal() nua((nil)): sent signal r_unref
nua.c:365 nua_handle_magic() nua: nua_handle_magic: entering
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe 2023-11-03 20:28:47.400886 86.67% [DEBUG] sofia.c:7493 Channel sofia/external/s_sipp@172.19.0.2:5062 entering state [received][100]
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe 2023-11-03 20:28:47.400886 86.67% [DEBUG] sofia.c:7503 Remote SDP:
v=0
o=CiscoSystemsCCM-SIP 1195507 1 IN IP4 172.19.0.2
s=SIP Call
c=IN IP4 172.19.0.2
b=TIAS:64000
b=AS:80
t=0 0
m=audio 6000 RTP/SAVP 18 0 8 100
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:100 telephone-event/8000
a=fmtp:100 0-15
a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:mSPPjYxzAEWkICVXidkYXFdsHr/J2NhpkqQepffH

8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe 2023-11-03 20:28:47.400886 86.67% [DEBUG] sofia.c:7906 (sofia/external/s_sipp@172.19.0.2:5062) State Change CS_NEW -> CS_INIT
nua.c:365 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:1170 nua_handle_unref_user() nua nua_handle_unref_user(0x6120000f9640): entering
nua_stack.c:558 nua_signal() nua(0x6120000f9640): sent signal r_handle_unref
nua.c:1157 nua_unref_user() nua: nua_unref_user: entering
nua_stack.c:558 nua_signal() nua((nil)): sent signal r_unref
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe 2023-11-03 20:28:47.400886 86.67% [DEBUG] switch_core_state_machine.c:600 (sofia/external/s_sipp@172.19.0.2:5062) State NEW
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe 2023-11-03 20:28:47.400886 86.67% [DEBUG] switch_core_state_machine.c:581 (sofia/external/s_sipp@172.19.0.2:5062) Running State Change CS_INIT (Cur 1 Tot 2)
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe 2023-11-03 20:28:47.400886 86.67% [DEBUG] switch_core_state_machine.c:624 (sofia/external/s_sipp@172.19.0.2:5062) State INIT
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe 2023-11-03 20:28:47.400886 86.67% [DEBUG] mod_sofia.c:97 sofia/external/s_sipp@172.19.0.2:5062 SOFIA INIT
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe 2023-11-03 20:28:47.400886 86.67% [DEBUG] switch_core_state_machine.c:40 sofia/external/s_sipp@172.19.0.2:5062 Standard INIT
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe 2023-11-03 20:28:47.400886 86.67% [DEBUG] switch_core_state_machine.c:48 (sofia/external/s_sipp@172.19.0.2:5062) State Change CS_INIT -> CS_ROUTING
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe 2023-11-03 20:28:47.400886 86.67% [DEBUG] switch_core_state_machine.c:624 (sofia/external/s_sipp@172.19.0.2:5062) State INIT going to sleep
nua_stack.c:599 nua_stack_signal() nua(0x6120000f9640): recv signal r_handle_unref
nua_stack.c:599 nua_stack_signal() nua((nil)): recv signal r_unref
nua_stack.c:599 nua_stack_signal() nua(0x6120000f9640): recv signal r_handle_unref
nua_stack.c:599 nua_stack_signal() nua((nil)): recv signal r_unref
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe 2023-11-03 20:28:47.421793 86.67% [DEBUG] switch_core_state_machine.c:581 (sofia/external/s_sipp@172.19.0.2:5062) Running State Change CS_ROUTING (Cur 1 Tot 2)
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe 2023-11-03 20:28:47.421793 86.67% [DEBUG] switch_channel.c:2400 (sofia/external/s_sipp@172.19.0.2:5062) Callstate Change DOWN -> RINGING
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe 2023-11-03 20:28:47.421793 86.67% [DEBUG] switch_core_state_machine.c:640 (sofia/external/s_sipp@172.19.0.2:5062) State ROUTING
nua.c:878 nua_respond() nua: nua_respond: entering
nua_stack.c:558 nua_signal() nua(0x6120000f9640): sent signal r_respond
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe 2023-11-03 20:28:47.421793 86.67% [DEBUG] mod_sofia.c:158 sofia/external/s_sipp@172.19.0.2:5062 SOFIA ROUTING
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe 2023-11-03 20:28:47.421793 86.67% [DEBUG] switch_core_state_machine.c:230 sofia/external/s_sipp@172.19.0.2:5062 Standard ROUTING
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe 2023-11-03 20:28:47.421793 86.67% [INFO] mod_dialplan_xml.c:642 Processing s_sipp <s_sipp>->1212121212 in context default
nua_stack.c:601 nua_stack_signal() nua(0x6120000f9640): recv signal r_respond 100 Trying
nua_params.c:484 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:402 soa_set_params() soa_set_params(static::0x6150000b3180, ...) called
tport.c:3290 tport_tsend() tport_tsend(0x6160000f1b80) tpn = UDP/172.19.0.2:5062
tport.c:4076 tport_resolve() tport_resolve addrinfo = 172.19.0.2:5062
tport.c:4713 tport_by_addrinfo() tport_by_addrinfo(0x6160000f1b80): not found by name UDP/172.19.0.2:5062
tport.c:3625 tport_vsend() tport_vsend(0x6160000f1b80): 259 bytes of 259 to udp/172.19.0.2:5062
tport.c:3526 tport_send_msg() tport_vsend returned 259
send 259 bytes to udp/[172.19.0.2]:5062 at 20:28:47.437220:
------------------------------------------------------------------------
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 172.19.0.2:5062;branch=z9hG4bK-18859-1-0
From: s_sipp <sip:s_sipp@172.19.0.2:5062>;tag=1
To: sut <sip:1212121212@172.19.0.2:5080>
Call-ID: 1-18859@172.19.0.2
CSeq: 1 INVITE
User-Agent: Unit Test
Content-Length: 0


nta.c:6879 incoming_reply() nta: sent 100 Trying for INVITE (1)
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe Dialplan: sofia/external/s_sipp@172.19.0.2:5062 parsing [default->unit_test_sipp-uac-digest-leak] continue=false
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe Dialplan: sofia/external/s_sipp@172.19.0.2:5062 Regex (FAIL) [unit_test_sipp-uac-digest-leak] destination_number(1212121212) =~ /^\+15553334444$/ break=on-false
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe Dialplan: sofia/external/s_sipp@172.19.0.2:5062 parsing [default->sipp_telephone_check] continue=false
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe Dialplan: sofia/external/s_sipp@172.19.0.2:5062 Regex (PASS) [sipp_telephone_check] destination_number(1212121212) =~ /^1212121212$/ break=on-false
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe Dialplan: sofia/external/s_sipp@172.19.0.2:5062 Action answer() 
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe Dialplan: sofia/external/s_sipp@172.19.0.2:5062 Action set(park_after_bridge=true) 
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe Dialplan: sofia/external/s_sipp@172.19.0.2:5062 Action park() 
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe 2023-11-03 20:28:47.441783 86.67% [DEBUG] switch_core_state_machine.c:281 (sofia/external/s_sipp@172.19.0.2:5062) State Change CS_ROUTING -> CS_EXECUTE
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe 2023-11-03 20:28:47.441783 86.67% [DEBUG] switch_core_state_machine.c:640 (sofia/external/s_sipp@172.19.0.2:5062) State ROUTING going to sleep
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe 2023-11-03 20:28:47.441783 86.67% [DEBUG] switch_core_state_machine.c:581 (sofia/external/s_sipp@172.19.0.2:5062) Running State Change CS_EXECUTE (Cur 1 Tot 2)
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe 2023-11-03 20:28:47.441783 86.67% [DEBUG] switch_core_state_machine.c:647 (sofia/external/s_sipp@172.19.0.2:5062) State EXECUTE
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe 2023-11-03 20:28:47.441783 86.67% [DEBUG] mod_sofia.c:213 sofia/external/s_sipp@172.19.0.2:5062 SOFIA EXECUTE
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe 2023-11-03 20:28:47.464590 86.67% [DEBUG] switch_core_state_machine.c:323 sofia/external/s_sipp@172.19.0.2:5062 Standard EXECUTE
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe EXECUTE [depth=0] sofia/external/s_sipp@172.19.0.2:5062 answer()
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe 2023-11-03 20:28:47.464590 86.67% [DEBUG] switch_core_media.c:1701 looking for crypto suite [AEAD_AES_256_GCM_8]alias=[] in [1 AES_CM_128_HMAC_SHA1_80 inline:mSPPjYxzAEWkICVXidkYXFdsHr/J2NhpkqQepffH]
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe 2023-11-03 20:28:47.464590 86.67% [DEBUG] switch_core_media.c:1701 looking for crypto suite [AEAD_AES_256_GCM]alias=[] in [1 AES_CM_128_HMAC_SHA1_80 inline:mSPPjYxzAEWkICVXidkYXFdsHr/J2NhpkqQepffH]
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe 2023-11-03 20:28:47.464590 86.67% [DEBUG] switch_core_media.c:1701 looking for crypto suite [AEAD_AES_128_GCM_8]alias=[] in [1 AES_CM_128_HMAC_SHA1_80 inline:mSPPjYxzAEWkICVXidkYXFdsHr/J2NhpkqQepffH]
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe 2023-11-03 20:28:47.464590 86.67% [DEBUG] switch_core_media.c:1701 looking for crypto suite [AEAD_AES_128_GCM]alias=[] in [1 AES_CM_128_HMAC_SHA1_80 inline:mSPPjYxzAEWkICVXidkYXFdsHr/J2NhpkqQepffH]
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe 2023-11-03 20:28:47.464590 86.67% [DEBUG] switch_core_media.c:1701 looking for crypto suite [AES_256_CM_HMAC_SHA1_80]alias=[AES_CM_256_HMAC_SHA1_80] in [1 AES_CM_128_HMAC_SHA1_80 inline:mSPPjYxzAEWkICVXidkYXFdsHr/J2NhpkqQepffH]
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe 2023-11-03 20:28:47.464590 86.67% [DEBUG] switch_core_media.c:1701 looking for crypto suite [AES_192_CM_HMAC_SHA1_80]alias=[AES_CM_192_HMAC_SHA1_80] in [1 AES_CM_128_HMAC_SHA1_80 inline:mSPPjYxzAEWkICVXidkYXFdsHr/J2NhpkqQepffH]
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe 2023-11-03 20:28:47.464590 86.67% [DEBUG] switch_core_media.c:1701 looking for crypto suite [AES_CM_128_HMAC_SHA1_80]alias=[] in [1 AES_CM_128_HMAC_SHA1_80 inline:mSPPjYxzAEWkICVXidkYXFdsHr/J2NhpkqQepffH]
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe 2023-11-03 20:28:47.464590 86.67% [DEBUG] switch_core_media.c:1710 Found suite AES_CM_128_HMAC_SHA1_80
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe 2023-11-03 20:28:47.464590 86.67% [DEBUG] switch_core_media.c:1780 Set Remote Key [1 AES_CM_128_HMAC_SHA1_80 inline:mSPPjYxzAEWkICVXidkYXFdsHr/J2NhpkqQepffH]
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe 2023-11-03 20:28:47.464590 86.67% [DEBUG] switch_core_media.c:1096 Set Local audio crypto Key [1 AES_CM_128_HMAC_SHA1_80 inline:qtg+wlTpNvALWzFqXtZyeTeUXWOTcfMyHBa+dkS3]
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe 2023-11-03 20:28:47.464590 86.67% [DEBUG] switch_core_media.c:5526 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMU:0:8000:20:64000:1]
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe 2023-11-03 20:28:47.464590 86.67% [DEBUG] switch_core_media.c:5526 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe 2023-11-03 20:28:47.464590 86.67% [DEBUG] switch_core_media.c:5588 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe 2023-11-03 20:28:47.464590 86.67% [DEBUG] switch_core_media.c:5526 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe 2023-11-03 20:28:47.464590 86.67% [DEBUG] switch_core_media.c:5438 Set telephone-event payload to 100@8000
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe 2023-11-03 20:28:47.481788 86.67% [DEBUG] switch_core_media.c:3731 Set Codec sofia/external/s_sipp@172.19.0.2:5062 PCMU/8000 20 ms 160 samples 64000 bits 1 channels
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe 2023-11-03 20:28:47.481788 86.67% [DEBUG] switch_core_codec.c:111 sofia/external/s_sipp@172.19.0.2:5062 Original read codec set to PCMU:0
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe 2023-11-03 20:28:47.481788 86.67% [DEBUG] switch_core_media.c:5798 Set telephone-event payload to 100@8000
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe 2023-11-03 20:28:47.481788 86.67% [DEBUG] switch_core_media.c:5856 sofia/external/s_sipp@172.19.0.2:5062 Set 2833 dtmf send payload to 100 recv payload to 100
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe 2023-11-03 20:28:47.502950 86.67% [DEBUG] switch_core_media.c:8660 AUDIO RTP [sofia/external/s_sipp@172.19.0.2:5062] 172.19.0.2 port 28954 -> 172.19.0.2 port 6000 codec: 0 ms: 20
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe 2023-11-03 20:28:47.520865 86.67% [DEBUG] switch_rtp.c:4535 Starting timer [soft] 160 bytes per 20ms
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe 2023-11-03 20:28:47.520865 86.67% [DEBUG] switch_core_media.c:8973 sofia/external/s_sipp@172.19.0.2:5062 Set 2833 dtmf send payload to 100
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe 2023-11-03 20:28:47.520865 86.67% [DEBUG] switch_core_media.c:8980 sofia/external/s_sipp@172.19.0.2:5062 Set 2833 dtmf receive payload to 100
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe 2023-11-03 20:28:47.520865 86.67% [DEBUG] switch_core_media.c:9003 sofia/external/s_sipp@172.19.0.2:5062 Set rtp dtmf delay to 40
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe 2023-11-03 20:28:47.520865 86.67% [INFO] switch_rtp.c:4338 Activating audio Secure RTP SEND
2023-11-03 20:28:47.520865 86.67% [DEBUG] switch_core_sqldb.c:2778 Secure Type: srtp:sdes:AES_CM_128_HMAC_SHA1_80
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe 2023-11-03 20:28:47.520865 86.67% [INFO] switch_rtp.c:4316 Activating audio Secure RTP RECV
2023-11-03 20:28:47.520865 86.67% [DEBUG] switch_core_sqldb.c:2778 Secure Type: srtp:sdes:AES_CM_128_HMAC_SHA1_80
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe 2023-11-03 20:28:47.520865 86.67% [NOTICE] sofia_media.c:90 Pre-Answer sofia/external/s_sipp@172.19.0.2:5062!
nta.c:1317 agent_timer() nta: timer set next to 447 ms
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe 2023-11-03 20:28:47.640899 86.67% [DEBUG] switch_channel.c:3586 (sofia/external/s_sipp@172.19.0.2:5062) Callstate Change RINGING -> EARLY
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe 2023-11-03 20:28:47.640899 86.67% [DEBUG] switch_core_media.c:8642 Audio params are unchanged for sofia/external/s_sipp@172.19.0.2:5062.
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe 2023-11-03 20:28:47.640899 86.67% [DEBUG] mod_sofia.c:914 Local SDP sofia/external/s_sipp@172.19.0.2:5062:
v=0
o=FS 1699014373 1699014374 IN IP4 172.19.0.2
s=FS
c=IN IP4 172.19.0.2
t=0 0
m=audio 28954 RTP/SAVP 0 100
a=rtpmap:0 PCMU/8000
a=rtpmap:100 telephone-event/8000
a=fmtp:100 0-15
a=ptime:20
a=sendrecv
a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:qtg+wlTpNvALWzFqXtZyeTeUXWOTcfMyHBa+dkS3

nua.c:878 nua_respond() nua: nua_respond: entering
nua_stack.c:558 nua_signal() nua(0x6120000f9640): sent signal r_respond
nua_stack.c:601 nua_stack_signal() nua(0x6120000f9640): recv signal r_respond 200 OK
nua_params.c:484 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:402 soa_set_params() soa_set_params(static::0x6150000b3180, ...) called
soa.c:1051 soa_set_user_sdp() soa_set_user_sdp(static::0x6150000b3180, (nil), 0x6180000e024e, -1) called
soa.c:889 soa_set_capability_sdp() soa_set_capability_sdp(static::0x6150000b3180, (nil), 0x6180000e024e, -1) called
nua_session.c:2317 nua_invite_server_respond() nua: nua_invite_server_respond: entering
soa.c:1514 soa_generate_answer() soa_generate_answer(static::0x6150000b3180) called
soa_static.c:1147 offer_answer_step() soa_static_offer_answer_action(0x6150000b3180, soa_generate_answer): called
soa_static.c:1188 offer_answer_step() soa_static(0x6150000b3180, soa_generate_answer): generating local description
soa_static.c:1229 offer_answer_step() soa_static(0x6150000b3180, soa_generate_answer): upgrade with remote description
soa_static.c:1028 soa_sdp_mode_set() soa_sdp_mode_set(0x7fd316caf730, 0x619000358980, ""): called
soa_static.c:1445 offer_answer_step() soa_static(0x6150000b3180, soa_generate_answer): storing local description
soa.c:1729 soa_activate() soa_activate(static::0x6150000b3180, (nil)) called
soa.c:1268 soa_get_local_sdp() soa_get_local_sdp(static::0x6150000b3180, [(nil)], [0x7fd316caf820], [0x7fd316caf81c]) called
tport.c:3290 tport_tsend() tport_tsend(0x6160000f1b80) tpn = UDP/172.19.0.2:5062
tport.c:4076 tport_resolve() tport_resolve addrinfo = 172.19.0.2:5062
tport.c:4713 tport_by_addrinfo() tport_by_addrinfo(0x6160000f1b80): not found by name UDP/172.19.0.2:5062
tport.c:3625 tport_vsend() tport_vsend(0x6160000f1b80): 1003 bytes of 1003 to udp/172.19.0.2:5062
tport.c:3526 tport_send_msg() tport_vsend returned 1003
send 1003 bytes to udp/[172.19.0.2]:5062 at 20:28:47.659646:
------------------------------------------------------------------------
SIP/2.0 200 OK
Via: SIP/2.0/UDP 172.19.0.2:5062;branch=z9hG4bK-18859-1-0
From: s_sipp <sip:s_sipp@172.19.0.2:5062>;tag=1
To: sut <sip:1212121212@172.19.0.2:5080>;tag=crSr50QHavrpj
Call-ID: 1-18859@172.19.0.2
CSeq: 1 INVITE
Contact: <sip:1212121212@172.19.0.2:5080;transport=udp>
User-Agent: Unit Test
Accept: application/sdp
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
Supported: timer, path, replaces
Allow-Events: talk, hold, conference, refer
Session-Expires: 600;refresher=uas
Content-Type: application/sdp
Content-Disposition: session
Content-Length: 285
Remote-Party-ID: "1212121212" <sip:1212121212@172.19.0.2>;party=calling;privacy=off;screen=no

v=0
o=FS 1699014373 1699014374 IN IP4 172.19.0.2
s=FS
c=IN IP4 172.19.0.2
t=0 0
m=audio 28954 RTP/SAVP 0 100
a=rtpmap:0 PCMU/8000
a=rtpmap:100 telephone-event/8000
a=fmtp:100 0-15
a=ptime:20
a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:qtg+wlTpNvALWzFqXtZyeTeUXWOTcfMyHBa+dkS3

nta.c:6879 incoming_reply() nta: sent 200 OK for INVITE (1)
nua_session.c:4131 signal_call_state_change() nua(0x6120000f9640): call state changed: received -> completed, sent answer
soa.c:1268 soa_get_local_sdp() soa_get_local_sdp(static::0x6150000b3180, [0x7fd316caf8e8], [0x7fd316caf8e0], [(nil)]) called
soa.c:615 soa_get_params() soa_get_params(static::0x6150000b3180, ...) called
nua_stack.c:301 nua_stack_event() nua(0x6120000f9640): event i_state 200 OK
nua_stack.c:389 nua_application_event() nua: nua_application_event: entering
nua.c:1170 nua_handle_unref_user() nua nua_handle_unref_user(0x6120000f9640): entering
nua_stack.c:558 nua_signal() nua(0x6120000f9640): sent signal r_handle_unref
nua.c:1157 nua_unref_user() nua: nua_unref_user: entering
nua_stack.c:558 nua_signal() nua((nil)): sent signal r_unref
nua_stack.c:599 nua_stack_signal() nua(0x6120000f9640): recv signal r_handle_unref
nua_stack.c:599 nua_stack_signal() nua((nil)): recv signal r_unref
tport.c:2769 tport_wakeup_pri() tport_wakeup_pri(0x6160000f1b80): events IN
tport.c:2900 tport_recv_event() tport_recv_event(0x6160000f1b80)
tport.c:3237 tport_recv_iovec() tport_recv_iovec(0x6160000f1b80) msg 0x61900035a780 from (udp/172.19.0.2:5080) has 357 bytes, veclen = 1
recv 357 bytes from udp/[172.19.0.2]:5062 at 20:28:47.664081:
------------------------------------------------------------------------
ACK sip:1212121212@172.19.0.2:5080 SIP/2.0
Via: SIP/2.0/UDP 172.19.0.2:5062;branch=z9hG4bK-18859-1-5
From: s_sipp <sip:s_sipp@172.19.0.2:5062>;tag=1
To: sut <sip:1212121212@172.19.0.2:5080>;tag=crSr50QHavrpj
Call-ID: 1-18859@172.19.0.2
CSeq: 1 ACK
Contact: sip:s_sipp@172.19.0.2:5062
Max-Forwards: 70
Subject: Performance Test
Content-Length: 0


tport.c:3055 tport_deliver() tport_deliver(0x6160000f1b80): msg 0x61900035a780 (357 bytes) from udp/172.19.0.2:5080/sip next=(nil)
nta.c:2957 agent_recv_request() nta: received ACK sip:1212121212@172.19.0.2:5080 SIP/2.0 (CSeq 1) (load: 1 rps)
nta.c:3097 agent_recv_request() nta: ACK (1) is going to INVITE (1)
nua_session.c:2566 process_ack_or_cancel() nua: process_ack_or_cancel: entering
soa.c:1213 soa_clear_remote_sdp() soa_clear_remote_sdp(static::0x6150000b3180) called
nua_stack.c:301 nua_stack_event() nua(0x6120000f9640): event i_ack 200 OK
nua_session.c:4131 signal_call_state_change() nua(0x6120000f9640): call state changed: completed -> ready
nua_stack.c:301 nua_stack_event() nua(0x6120000f9640): event i_state 200 OK
nua_stack.c:301 nua_stack_event() nua(0x6120000f9640): event i_active 200 Call active
nua_dialog.c:563 nua_dialog_usage_set_refresh_range() nua(): refresh session after 301 seconds (in [295..305])
nua_stack.c:389 nua_application_event() nua: nua_application_event: entering
nua.c:1170 nua_handle_unref_user() nua nua_handle_unref_user(0x6120000f9640): entering
nua_stack.c:558 nua_signal() nua(0x6120000f9640): sent signal r_handle_unref
nua.c:1157 nua_unref_user() nua: nua_unref_user: entering
nua_stack.c:558 nua_signal() nua((nil)): sent signal r_unref
nua_stack.c:389 nua_application_event() nua: nua_application_event: entering
nua.c:1170 nua_handle_unref_user() nua nua_handle_unref_user(0x6120000f9640): entering
nua_stack.c:558 nua_signal() nua(0x6120000f9640): sent signal r_handle_unref
nua.c:1157 nua_unref_user() nua: nua_unref_user: entering
nua_stack.c:558 nua_signal() nua((nil)): sent signal r_unref
nua_stack.c:389 nua_application_event() nua: nua_application_event: entering
nua.c:1170 nua_handle_unref_user() nua nua_handle_unref_user(0x6120000f9640): entering
nua_stack.c:558 nua_signal() nua(0x6120000f9640): sent signal r_handle_unref
nua.c:1157 nua_unref_user() nua: nua_unref_user: entering
nua_stack.c:558 nua_signal() nua((nil)): sent signal r_unref
nua_stack.c:599 nua_stack_signal() nua(0x6120000f9640): recv signal r_handle_unref
nua_stack.c:599 nua_stack_signal() nua((nil)): recv signal r_unref
nua_stack.c:599 nua_stack_signal() nua(0x6120000f9640): recv signal r_handle_unref
nua_stack.c:599 nua_stack_signal() nua((nil)): recv signal r_unref
nua_stack.c:599 nua_stack_signal() nua(0x6120000f9640): recv signal r_handle_unref
nua_stack.c:599 nua_stack_signal() nua((nil)): recv signal r_unref
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe 2023-11-03 20:28:47.660893 86.67% [NOTICE] mod_dptools.c:1406 Channel [sofia/external/s_sipp@172.19.0.2:5062] has been answered
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe 2023-11-03 20:28:47.683300 86.67% [DEBUG] switch_channel.c:3913 (sofia/external/s_sipp@172.19.0.2:5062) Callstate Change EARLY -> ACTIVE
nua.c:365 nua_handle_magic() nua: nua_handle_magic: entering
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe 2023-11-03 20:28:47.702781 86.67% [DEBUG] sofia.c:7493 Channel sofia/external/s_sipp@172.19.0.2:5062 entering state [completed][200]
nua.c:365 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:1170 nua_handle_unref_user() nua nua_handle_unref_user(0x6120000f9640): entering
nua_stack.c:599 nua_stack_signal() nua(0x6120000f9640): recv signal r_handle_unref
nua_stack.c:558 nua_signal() nua(0x6120000f9640): sent signal r_handle_unref
nua.c:1157 nua_unref_user() nua: nua_unref_user: entering
nua_stack.c:599 nua_stack_signal() nua((nil)): recv signal r_unref
nua_stack.c:558 nua_signal() nua((nil)): sent signal r_unref
nua.c:365 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:365 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:1170 nua_handle_unref_user() nua nua_handle_unref_user(0x6120000f9640): entering
nua_stack.c:599 nua_stack_signal() nua(0x6120000f9640): recv signal r_handle_unref
nua_stack.c:558 nua_signal() nua(0x6120000f9640): sent signal r_handle_unref
nua.c:1157 nua_unref_user() nua: nua_unref_user: entering
nua_stack.c:599 nua_stack_signal() nua((nil)): recv signal r_unref
nua_stack.c:558 nua_signal() nua((nil)): sent signal r_unref
nua.c:365 nua_handle_magic() nua: nua_handle_magic: entering
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe 2023-11-03 20:28:47.702781 86.67% [DEBUG] sofia.c:7493 Channel sofia/external/s_sipp@172.19.0.2:5062 entering state [ready][200]
nua.c:365 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:1170 nua_handle_unref_user() nua nua_handle_unref_user(0x6120000f9640): entering
nua_stack.c:599 nua_stack_signal() nua(0x6120000f9640): recv signal r_handle_unref
nua_stack.c:558 nua_signal() nua(0x6120000f9640): sent signal r_handle_unref
nua.c:1157 nua_unref_user() nua: nua_unref_user: entering
nua_stack.c:599 nua_stack_signal() nua((nil)): recv signal r_unref
nua_stack.c:558 nua_signal() nua((nil)): sent signal r_unref
nua.c:365 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:365 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:1170 nua_handle_unref_user() nua nua_handle_unref_user(0x6120000f9640): entering
nua_stack.c:599 nua_stack_signal() nua(0x6120000f9640): recv signal r_handle_unref
nua_stack.c:558 nua_signal() nua(0x6120000f9640): sent signal r_handle_unref
nua.c:1157 nua_unref_user() nua: nua_unref_user: entering
nua_stack.c:599 nua_stack_signal() nua((nil)): recv signal r_unref
nua_stack.c:558 nua_signal() nua((nil)): sent signal r_unref
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe EXECUTE [depth=0] sofia/external/s_sipp@172.19.0.2:5062 set(park_after_bridge=true)
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe 2023-11-03 20:28:47.723603 86.67% [DEBUG] mod_dptools.c:1671 SET sofia/external/s_sipp@172.19.0.2:5062 [park_after_bridge]=[true]
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe EXECUTE [depth=0] sofia/external/s_sipp@172.19.0.2:5062 park()
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe 2023-11-03 20:28:47.763076 86.67% [DEBUG] switch_ivr.c:1032 Codec Activated L16@8000hz 1 channels 20ms
nta.c:9233 outgoing_timer_dk() nta: timer K fired, terminate REGISTER (74967869)
nta.c:8905 outgoing_reclaim_queued() outgoing_reclaim_all((nil), (nil), 0x7fd316caf9c0)
nta.c:9045 _nta_outgoing_timer() nta_outgoing_timer: 0/0 resent, 0/0 tout, 1/1 term, 1/1 free
nta.c:1317 agent_timer() nta: timer set next to 1116 ms
tport.c:2769 tport_wakeup_pri() tport_wakeup_pri(0x6160000f1b80): events IN
tport.c:2900 tport_recv_event() tport_recv_event(0x6160000f1b80)
tport.c:3237 tport_recv_iovec() tport_recv_iovec(0x6160000f1b80) msg 0x61900035ac80 from (udp/172.19.0.2:5080) has 349 bytes, veclen = 1
recv 349 bytes from udp/[172.19.0.2]:5062 at 20:28:48.666691:
------------------------------------------------------------------------
INVITE sip:1212121212@172.19.0.2:5080 SIP/2.0
Via: SIP/2.0/UDP 172.19.0.2:5062;branch=z9hG4bK-18859-1-7
From: s_sipp <sip:s_sipp@172.19.0.2:5062>;tag=1
To: sut <sip:1212121212@172.19.0.2:5080>
Call-ID: 1-18859@172.19.0.2
CSeq: 2 INVITE
Contact: sip:s_sipp@172.19.0.2:5062
Max-Forwards: 70
Subject: Performance Test
Content-Length:     0


tport.c:3055 tport_deliver() tport_deliver(0x6160000f1b80): msg 0x61900035ac80 (349 bytes) from udp/172.19.0.2:5080/sip next=(nil)
nta.c:2957 agent_recv_request() nta: received INVITE sip:1212121212@172.19.0.2:5080 SIP/2.0 (CSeq 2) (load: 1 rps)
nta.c:3326 agent_aliases() nta: canonizing sip:1212121212@172.19.0.2:5080 with contact
nta.c:3139 agent_recv_request() nta: INVITE (2) going to existing leg
nta.c:1369 set_timeout() nta: timer shortened to 200 ms
nua_server.c:102 nua_stack_process_request() nua: nua_stack_process_request: entering
soa.c:1301 soa_init_offer_answer() soa_init_offer_answer(static::0x6150000b3180) called
nua_stack.c:301 nua_stack_event() nua(0x6120000f9640): event i_invite 100 Trying
nua_session.c:4138 signal_call_state_change() nua(0x6120000f9640): ready call updated: received
nua_stack.c:301 nua_stack_event() nua(0x6120000f9640): event i_state 100 Trying
nua_stack.c:389 nua_application_event() nua: nua_application_event: entering
nua.c:1170 nua_handle_unref_user() nua nua_handle_unref_user(0x6120000f9640): entering
nua_stack.c:558 nua_signal() nua(0x6120000f9640): sent signal r_handle_unref
nua.c:1157 nua_unref_user() nua: nua_unref_user: entering
nua_stack.c:558 nua_signal() nua((nil)): sent signal r_unref
nua_stack.c:389 nua_application_event() nua: nua_application_event: entering
nua.c:1170 nua_handle_unref_user() nua nua_handle_unref_user(0x6120000f9640): entering
nua_stack.c:558 nua_signal() nua(0x6120000f9640): sent signal r_handle_unref
nua.c:1157 nua_unref_user() nua: nua_unref_user: entering
nua_stack.c:558 nua_signal() nua((nil)): sent signal r_unref
nua_stack.c:599 nua_stack_signal() nua(0x6120000f9640): recv signal r_handle_unref
nua_stack.c:599 nua_stack_signal() nua((nil)): recv signal r_unref
nua_stack.c:599 nua_stack_signal() nua(0x6120000f9640): recv signal r_handle_unref
nua_stack.c:599 nua_stack_signal() nua((nil)): recv signal r_unref
nua.c:365 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:878 nua_respond() nua: nua_respond: entering
nua_stack.c:558 nua_signal() nua(0x6120000f9640): sent signal r_respond
nua_stack.c:601 nua_stack_signal() nua(0x6120000f9640): recv signal r_respond 100 Trying
nua_params.c:484 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:402 soa_set_params() soa_set_params(static::0x6150000b3180, ...) called
tport.c:3290 tport_tsend() tport_tsend(0x6160000f1b80) tpn = UDP/172.19.0.2:5062
tport.c:4076 tport_resolve() tport_resolve addrinfo = 172.19.0.2:5062
tport.c:4713 tport_by_addrinfo() tport_by_addrinfo(0x6160000f1b80): not found by name UDP/172.19.0.2:5062
tport.c:3625 tport_vsend() tport_vsend(0x6160000f1b80): 277 bytes of 277 to udp/172.19.0.2:5062
tport.c:3526 tport_send_msg() tport_vsend returned 277
send 277 bytes to udp/[172.19.0.2]:5062 at 20:28:48.682979:
------------------------------------------------------------------------
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 172.19.0.2:5062;branch=z9hG4bK-18859-1-7
From: s_sipp <sip:s_sipp@172.19.0.2:5062>;tag=1
To: sut <sip:1212121212@172.19.0.2:5080>;tag=crSr50QHavrpj
Call-ID: 1-18859@172.19.0.2
CSeq: 2 INVITE
User-Agent: Unit Test
Content-Length: 0


nta.c:6879 incoming_reply() nta: sent 100 Trying for INVITE (2)
nua.c:365 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:1170 nua_handle_unref_user() nua nua_handle_unref_user(0x6120000f9640): entering
nua_stack.c:599 nua_stack_signal() nua(0x6120000f9640): recv signal r_handle_unref
nua_stack.c:558 nua_signal() nua(0x6120000f9640): sent signal r_handle_unref
nua.c:1157 nua_unref_user() nua: nua_unref_user: entering
nua_stack.c:599 nua_stack_signal() nua((nil)): recv signal r_unref
nua_stack.c:558 nua_signal() nua((nil)): sent signal r_unref
nua.c:365 nua_handle_magic() nua: nua_handle_magic: entering
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe 2023-11-03 20:28:48.720882 83.33% [DEBUG] sofia.c:7493 Channel sofia/external/s_sipp@172.19.0.2:5062 entering state [received][100]
nua.c:878 nua_respond() nua: nua_respond: entering
nua_stack.c:601 nua_stack_signal() nua(0x6120000f9640): recv signal r_respond 200 OK
nua_params.c:484 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:402 soa_set_params() soa_set_params(static::0x6150000b3180, ...) called
soa.c:1051 soa_set_user_sdp() soa_set_user_sdp(static::0x6150000b3180, (nil), 0x6170001011ff, -1) called
nua_session.c:2317 nua_invite_server_respond() nua: nua_invite_server_respond: entering
soa.c:1425 soa_generate_offer() soa_generate_offer(static::0x6150000b3180, 0) called
soa_static.c:1147 offer_answer_step() soa_static_offer_answer_action(0x6150000b3180, soa_generate_offer): called
soa_static.c:1216 offer_answer_step() soa_static(0x6150000b3180, soa_generate_offer): upgrade with local description
soa_static.c:1028 soa_sdp_mode_set() soa_sdp_mode_set(0x7fd316caf720, (nil), ""): called
soa_static.c:1445 offer_answer_step() soa_static(0x6150000b3180, soa_generate_offer): storing local description
soa.c:1268 soa_get_local_sdp() soa_get_local_sdp(static::0x6150000b3180, [(nil)], [0x7fd316caf820], [0x7fd316caf81c]) called
tport.c:3290 tport_tsend() tport_tsend(0x6160000f1b80) tpn = UDP/172.19.0.2:5062
tport.c:4076 tport_resolve() tport_resolve addrinfo = 172.19.0.2:5062
tport.c:4713 tport_by_addrinfo() tport_by_addrinfo(0x6160000f1b80): not found by name UDP/172.19.0.2:5062
tport.c:3625 tport_vsend() tport_vsend(0x6160000f1b80): 944 bytes of 944 to udp/172.19.0.2:5062
tport.c:3526 tport_send_msg() tport_vsend returned 944
send 944 bytes to udp/[172.19.0.2]:5062 at 20:28:48.740622:
------------------------------------------------------------------------
SIP/2.0 200 OK
Via: SIP/2.0/UDP 172.19.0.2:5062;branch=z9hG4bK-18859-1-7
From: s_sipp <sip:s_sipp@172.19.0.2:5062>;tag=1
To: sut <sip:1212121212@172.19.0.2:5080>;tag=crSr50QHavrpj
Call-ID: 1-18859@172.19.0.2
CSeq: 2 INVITE
Contact: <sip:1212121212@172.19.0.2:5080;transport=udp>
User-Agent: Unit Test
Accept: application/sdp
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
Supported: timer, path, replaces
Session-Expires: 600;refresher=uas
Content-Type: application/sdp
Content-Disposition: session
Content-Length: 366

v=0
o=FS 1699014373 1699014375 IN IP4 172.19.0.2
s=FS
c=IN IP4 172.19.0.2
t=0 0
m=audio 28954 RTP/SAVP 0 100
a=rtpmap:0 PCMU/8000
a=rtpmap:100 telephone-event/8000
a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:qtg+wlTpNvALWzFqXtZyeTeUXWOTcfMyHBa+dkS3
a=ptime:20
m=audio 28954 RTP/AVP 0 100
a=rtpmap:0 PCMU/8000
a=rtpmap:100 telephone-event/8000
a=ptime:20

nta.c:6879 incoming_reply() nta: sent 200 OK for INVITE (2)
nua_session.c:4138 signal_call_state_change() nua(0x6120000f9640): ready call updated: completed sent offer
soa.c:1268 soa_get_local_sdp() soa_get_local_sdp(static::0x6150000b3180, [0x7fd316caf8e8], [0x7fd316caf8e0], [(nil)]) called
nua_stack.c:301 nua_stack_event() nua(0x6120000f9640): event i_state 200 OK
tport.c:2769 tport_wakeup_pri() tport_wakeup_pri(0x6160000f1b80): events IN
tport.c:2900 tport_recv_event() tport_recv_event(0x6160000f1b80)
tport.c:3237 tport_recv_iovec() tport_recv_iovec(0x6160000f1b80) msg 0x61900035d980 from (udp/172.19.0.2:5080) has 393 bytes, veclen = 1
recv 393 bytes from udp/[172.19.0.2]:5062 at 20:28:48.741588:
------------------------------------------------------------------------
ACK sip:1212121212@172.19.0.2:5080 SIP/2.0
Via: SIP/2.0/UDP 172.19.0.2:5062;branch=z9hG4bK-18859-1-10
From: s_sipp <sip:s_sipp@172.19.0.2:5062>;tag=1
To: sut <sip:1212121212@172.19.0.2:5080>;tag=crSr50QHavrpj
Call-ID: 1-18859@172.19.0.2
CSeq: 2 ACK
Contact: sip:s_sipp@172.19.0.2:5062
Max-Forwards: 70
Subject: Performance Test
Content-Type: application/sdp
Content-Length:     0


tport.c:3055 tport_deliver() tport_deliver(0x6160000f1b80): msg 0x61900035d980 (393 bytes) from udp/172.19.0.2:5080/sip next=(nil)
nta.c:2957 agent_recv_request() nta: received ACK sip:1212121212@172.19.0.2:5080 SIP/2.0 (CSeq 2) (load: 1 rps)
nta.c:3097 agent_recv_request() nta: ACK (2) is going to INVITE (2)
nua_session.c:2566 process_ack_or_cancel() nua: process_ack_or_cancel: entering
nua_stack.c:389 nua_application_event() nua: nua_application_event: entering
nua.c:1170 nua_handle_unref_user() nua nua_handle_unref_user(0x6120000f9640): entering
nua_stack.c:558 nua_signal() nua(0x6120000f9640): sent signal r_handle_unref
nua.c:1157 nua_unref_user() nua: nua_unref_user: entering
nua_stack.c:558 nua_signal() nua((nil)): sent signal r_unref
nua_stack.c:301 nua_stack_event() nua(0x6120000f9640): event i_ack 488 Offer-Answer error
nua_stack.c:301 nua_stack_event() nua(0x6120000f9640): event i_media_error 488 Offer-Answer error
nua_params.c:484 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:1783 soa_terminate() soa_terminate(static::0x6150000b3180) called
soa.c:1301 soa_init_offer_answer() soa_init_offer_answer(static::0x6150000b3180) called
nta.c:2716 nta_tpn_by_url() nta: selecting scheme sip
tport.c:3290 tport_tsend() tport_tsend(0x6160000f1b80) tpn = */172.19.0.2:5062
tport.c:4076 tport_resolve() tport_resolve addrinfo = 172.19.0.2:5062
tport.c:4713 tport_by_addrinfo() tport_by_addrinfo(0x6160000f1b80): not found by name */172.19.0.2:5062
tport.c:3625 tport_vsend() tport_vsend(0x6160000f1b80): 558 bytes of 558 to udp/172.19.0.2:5062
tport.c:3526 tport_send_msg() tport_vsend returned 558
send 558 bytes to udp/[172.19.0.2]:5062 at 20:28:48.744587:
------------------------------------------------------------------------
BYE sip:s_sipp@172.19.0.2:5062 SIP/2.0
Via: SIP/2.0/UDP 172.19.0.2:5080;rport;branch=z9hG4bKarXmeQ7m3yv2K
Max-Forwards: 70
From: sut <sip:1212121212@172.19.0.2:5080>;tag=crSr50QHavrpj
To: s_sipp <sip:s_sipp@172.19.0.2:5062>;tag=1
Call-ID: 1-18859@172.19.0.2
CSeq: 74967872 BYE
Contact: <sip:1212121212@172.19.0.2:5080;transport=udp>
User-Agent: Unit Test
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
Supported: timer, path, replaces
Reason: SIP;cause=488;text="No answer to offer"
Content-Length: 0


nta.c:8400 outgoing_send() nta: sent BYE (74967872) to */172.19.0.2:5062
tport.c:4191 tport_pend() tport_pend(0x6160000f1b80): pending 0x61900035e380 for udp/172.19.0.2:5080 (already 0)
nua_session.c:4131 signal_call_state_change() nua(0x6120000f9640): call state changed: ready -> terminating
nua_stack.c:301 nua_stack_event() nua(0x6120000f9640): event i_state 488 Offer-Answer Error
nua_stack.c:599 nua_stack_signal() nua(0x6120000f9640): recv signal r_handle_unref
nua_stack.c:599 nua_stack_signal() nua((nil)): recv signal r_unref
tport.c:2769 tport_wakeup_pri() tport_wakeup_pri(0x6160000f1b80): events IN
tport.c:2900 tport_recv_event() tport_recv_event(0x6160000f1b80)
tport.c:3237 tport_recv_iovec() tport_recv_iovec(0x6160000f1b80) msg 0x61900035ed80 from (udp/172.19.0.2:5080) has 358 bytes, veclen = 1
recv 358 bytes from udp/[172.19.0.2]:5062 at 20:28:48.745385:
------------------------------------------------------------------------
BYE sip:1212121212@172.19.0.2:5080 SIP/2.0
Via: SIP/2.0/UDP 172.19.0.2:5062;branch=z9hG4bK-18859-1-11
From: s_sipp <sip:s_sipp@172.19.0.2:5062>;tag=1
To: sut <sip:1212121212@172.19.0.2:5080>;tag=crSr50QHavrpj
Call-ID: 1-18859@172.19.0.2
CSeq: 3 BYE
Contact: sip:s_sipp@172.19.0.2:5062
Max-Forwards: 70
Subject: Performance Test
Content-Length: 0


tport.c:3055 tport_deliver() tport_deliver(0x6160000f1b80): msg 0x61900035ed80 (358 bytes) from udp/172.19.0.2:5080/sip next=(nil)
nta.c:2957 agent_recv_request() nta: received BYE sip:1212121212@172.19.0.2:5080 SIP/2.0 (CSeq 3) (load: 1 rps)
nta.c:3326 agent_aliases() nta: canonizing sip:1212121212@172.19.0.2:5080 with contact
nta.c:3139 agent_recv_request() nta: BYE (3) going to existing leg
nua_server.c:102 nua_stack_process_request() nua: nua_stack_process_request: entering
nua_stack.c:301 nua_stack_event() nua(0x6120000f9640): event i_bye 100 Trying
nua_stack.c:389 nua_application_event() nua: nua_application_event: entering
nua.c:1170 nua_handle_unref_user() nua nua_handle_unref_user(0x6120000f9640): entering
nua_stack.c:558 nua_signal() nua(0x6120000f9640): sent signal r_handle_unref
nua.c:1157 nua_unref_user() nua: nua_unref_user: entering
nua_stack.c:558 nua_signal() nua((nil)): sent signal r_unref
nua_stack.c:389 nua_application_event() nua: nua_application_event: entering
nua.c:1170 nua_handle_unref_user() nua nua_handle_unref_user(0x6120000f9640): entering
nua_stack.c:558 nua_signal() nua(0x6120000f9640): sent signal r_handle_unref
nua.c:1157 nua_unref_user() nua: nua_unref_user: entering
nua_stack.c:558 nua_signal() nua((nil)): sent signal r_unref
nua_stack.c:389 nua_application_event() nua: nua_application_event: entering
nua.c:1170 nua_handle_unref_user() nua nua_handle_unref_user(0x6120000f9640): entering
nua_stack.c:558 nua_signal() nua(0x6120000f9640): sent signal r_handle_unref
nua.c:1157 nua_unref_user() nua: nua_unref_user: entering
nua_stack.c:558 nua_signal() nua((nil)): sent signal r_unref
nua_stack.c:389 nua_application_event() nua: nua_application_event: entering
nua.c:1170 nua_handle_unref_user() nua nua_handle_unref_user(0x6120000f9640): entering
nua_stack.c:558 nua_signal() nua(0x6120000f9640): sent signal r_handle_unref
nua.c:1157 nua_unref_user() nua: nua_unref_user: entering
nua_stack.c:558 nua_signal() nua((nil)): sent signal r_unref
nua_stack.c:599 nua_stack_signal() nua(0x6120000f9640): recv signal r_handle_unref
nua_stack.c:599 nua_stack_signal() nua((nil)): recv signal r_unref
nua_stack.c:599 nua_stack_signal() nua(0x6120000f9640): recv signal r_handle_unref
nua_stack.c:599 nua_stack_signal() nua((nil)): recv signal r_unref
nua_stack.c:599 nua_stack_signal() nua(0x6120000f9640): recv signal r_handle_unref
nua_stack.c:599 nua_stack_signal() nua((nil)): recv signal r_unref
nua_stack.c:599 nua_stack_signal() nua(0x6120000f9640): recv signal r_handle_unref
nua_stack.c:599 nua_stack_signal() nua((nil)): recv signal r_unref
tport.c:2769 tport_wakeup_pri() tport_wakeup_pri(0x6160000f1b80): events IN
tport.c:2900 tport_recv_event() tport_recv_event(0x6160000f1b80)
tport.c:3237 tport_recv_iovec() tport_recv_iovec(0x6160000f1b80) msg 0x61900035f780 from (udp/172.19.0.2:5080) has 309 bytes, veclen = 1
recv 309 bytes from udp/[172.19.0.2]:5062 at 20:28:48.748285:
------------------------------------------------------------------------
SIP/2.0 200 OK
Via: SIP/2.0/UDP 172.19.0.2:5080;rport;branch=z9hG4bKarXmeQ7m3yv2K
From: sut <sip:1212121212@172.19.0.2:5080>;tag=crSr50QHavrpj
To: s_sipp <sip:s_sipp@172.19.0.2:5062>;tag=1
Call-ID: 1-18859@172.19.0.2
CSeq: 74967872 BYE
Contact: <sip:172.19.0.2:5062;transport=UDP>
Content-Length: 0


tport.c:3055 tport_deliver() tport_deliver(0x6160000f1b80): msg 0x61900035f780 (309 bytes) from udp/172.19.0.2:5080/sip next=(nil)
nta.c:3378 agent_recv_response() nta: received 200 OK for BYE (74967872)
nta.c:3445 agent_recv_response() nta: 200 OK is going to a transaction
nta.c:9697 outgoing_estimate_delay() nta_outgoing: RTT is 4.549 ms
tport.c:4253 tport_release() tport_release(0x6160000f1b80): 0x61900035e380 by 0x613000091d00 with 0x61900035f780
nua_stack.c:301 nua_stack_event() nua(0x6120000f9640): event r_bye 200 OK
nua_stack.c:389 nua_application_event() nua: nua_application_event: entering
nua.c:1170 nua_handle_unref_user() nua nua_handle_unref_user(0x6120000f9640): entering
nua_stack.c:558 nua_signal() nua(0x6120000f9640): sent signal r_handle_unref
nua.c:1157 nua_unref_user() nua: nua_unref_user: entering
nua_stack.c:558 nua_signal() nua((nil)): sent signal r_unref
nua_session.c:4131 signal_call_state_change() nua(0x6120000f9640): call state changed: terminating -> terminated
nua_stack.c:301 nua_stack_event() nua(0x6120000f9640): event i_state 200 to BYE
nua_stack.c:389 nua_application_event() nua: nua_application_event: entering
nua.c:1170 nua_handle_unref_user() nua nua_handle_unref_user(0x6120000f9640): entering
nua_stack.c:558 nua_signal() nua(0x6120000f9640): sent signal r_handle_unref
nua.c:1157 nua_unref_user() nua: nua_unref_user: entering
nua_stack.c:558 nua_signal() nua((nil)): sent signal r_unref
nua_stack.c:301 nua_stack_event() nua(0x6120000f9640): event i_terminated 200 to BYE
nua_stack.c:389 nua_application_event() nua: nua_application_event: entering
nua.c:1170 nua_handle_unref_user() nua nua_handle_unref_user(0x6120000f9640): entering
nua_stack.c:558 nua_signal() nua(0x6120000f9640): sent signal r_handle_unref
nua.c:1157 nua_unref_user() nua: nua_unref_user: entering
nua_stack.c:558 nua_signal() nua((nil)): sent signal r_unref
nua_dialog.c:395 nua_dialog_usage_remove_at() nua(0x6120000f9640): removing session usage
soa.c:355 soa_destroy() soa_destroy(static::0x6150000b3180) called
nta.c:4550 nta_leg_destroy() nta_leg_destroy(0x60c000087940)
nua_session.c:351 nua_session_usage_destroy() nua: terminated session 0x6120000f9640
nua_stack.c:599 nua_stack_signal() nua(0x6120000f9640): recv signal r_handle_unref
nua_stack.c:599 nua_stack_signal() nua((nil)): recv signal r_unref
nua_stack.c:599 nua_stack_signal() nua(0x6120000f9640): recv signal r_handle_unref
nua_stack.c:599 nua_stack_signal() nua((nil)): recv signal r_unref
nua_stack.c:599 nua_stack_signal() nua(0x6120000f9640): recv signal r_handle_unref
nua_stack.c:599 nua_stack_signal() nua((nil)): recv signal r_unref
nua_stack.c:558 nua_signal() nua(0x6120000f9640): sent signal r_respond
nua.c:365 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:1170 nua_handle_unref_user() nua nua_handle_unref_user(0x6120000f9640): entering
nua_stack.c:558 nua_signal() nua(0x6120000f9640): sent signal r_handle_unref
nua_stack.c:599 nua_stack_signal() nua(0x6120000f9640): recv signal r_handle_unref
nua.c:1157 nua_unref_user() nua: nua_unref_user: entering
nua_stack.c:558 nua_signal() nua((nil)): sent signal r_unref
nua_stack.c:599 nua_stack_signal() nua((nil)): recv signal r_unref
nua.c:365 nua_handle_magic() nua: nua_handle_magic: entering
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe 2023-11-03 20:28:48.740873 83.33% [DEBUG] sofia.c:7493 Channel sofia/external/s_sipp@172.19.0.2:5062 entering state [completed][200]
nua.c:365 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:1170 nua_handle_unref_user() nua nua_handle_unref_user(0x6120000f9640): entering
nua_stack.c:599 nua_stack_signal() nua(0x6120000f9640): recv signal r_handle_unref
nua_stack.c:558 nua_signal() nua(0x6120000f9640): sent signal r_handle_unref
nua.c:1157 nua_unref_user() nua: nua_unref_user: entering
nua_stack.c:599 nua_stack_signal() nua((nil)): recv signal r_unref
nua_stack.c:558 nua_signal() nua((nil)): sent signal r_unref
nua.c:365 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:365 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:1170 nua_handle_unref_user() nua nua_handle_unref_user(0x6120000f9640): entering
nua_stack.c:599 nua_stack_signal() nua(0x6120000f9640): recv signal r_handle_unref
nua_stack.c:558 nua_signal() nua(0x6120000f9640): sent signal r_handle_unref
nua.c:1157 nua_unref_user() nua: nua_unref_user: entering
nua_stack.c:599 nua_stack_signal() nua((nil)): recv signal r_unref
nua_stack.c:558 nua_signal() nua((nil)): sent signal r_unref
nua.c:365 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:365 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:1170 nua_handle_unref_user() nua nua_handle_unref_user(0x6120000f9640): entering
nua_stack.c:599 nua_stack_signal() nua(0x6120000f9640): recv signal r_handle_unref
nua_stack.c:558 nua_signal() nua(0x6120000f9640): sent signal r_handle_unref
nua.c:1157 nua_unref_user() nua: nua_unref_user: entering
nua_stack.c:599 nua_stack_signal() nua((nil)): recv signal r_unref
nua_stack.c:558 nua_signal() nua((nil)): sent signal r_unref
nua.c:365 nua_handle_magic() nua: nua_handle_magic: entering
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe 2023-11-03 20:28:48.740873 83.33% [DEBUG] sofia.c:7493 Channel sofia/external/s_sipp@172.19.0.2:5062 entering state [terminating][488]
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe 2023-11-03 20:28:48.740873 83.33% [NOTICE] sofia.c:8735 Hangup sofia/external/s_sipp@172.19.0.2:5062 [CS_EXECUTE] [MANDATORY_IE_MISSING]
nua.c:341 nua_handle_bind() nua: nua_handle_bind: entering
nua.c:920 nua_handle_destroy() nua: nua_handle_destroy: entering
nua_stack.c:599 nua_stack_signal() nua(0x6120000f9640): recv signal r_destroy
tport.c:3290 tport_tsend() tport_tsend(0x6160000f1b80) tpn = UDP/172.19.0.2:5062
tport.c:4076 tport_resolve() tport_resolve addrinfo = 172.19.0.2:5062
tport.c:4713 tport_by_addrinfo() tport_by_addrinfo(0x6160000f1b80): not found by name UDP/172.19.0.2:5062
tport.c:3625 tport_vsend() tport_vsend(0x6160000f1b80): 248 bytes of 248 to udp/172.19.0.2:5062
tport.c:3526 tport_send_msg() tport_vsend returned 248
send 248 bytes to udp/[172.19.0.2]:5062 at 20:28:48.762849:
------------------------------------------------------------------------
SIP/2.0 200 OK
Via: SIP/2.0/UDP 172.19.0.2:5062;branch=z9hG4bK-18859-1-11
From: s_sipp <sip:s_sipp@172.19.0.2:5062>;tag=1
To: sut <sip:1212121212@172.19.0.2:5080>;tag=crSr50QHavrpj
Call-ID: 1-18859@172.19.0.2
CSeq: 3 BYE
Content-Length: 0


nta.c:6879 incoming_reply() nta: sent 200 OK for BYE (3)
nta.c:4550 nta_leg_destroy() nta_leg_destroy((nil))
tport.c:2769 tport_wakeup_pri() tport_wakeup_pri(0x6160000f1b80): events ERR
tport_type_udp.c:517 tport_udp_error() tport_udp_error: Connection refused (111) [icmp type=3 code=3]
tport_type_udp.c:521 tport_udp_error() 	reported by [172.19.0.2]:0
nta.c:2767 agent_tp_error() nta_agent: tport: 172.19.0.2:5062: Connection refused
nua_stack.c:558 nua_signal() nua(0x6120000f9640): sent signal r_destroy
nua.c:365 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:341 nua_handle_bind() nua: nua_handle_bind: entering
nua.c:920 nua_handle_destroy() nua: nua_handle_destroy: entering
nua.c:1170 nua_handle_unref_user() nua nua_handle_unref_user(0x6120000f9640): entering
nua_stack.c:599 nua_stack_signal() nua(0x6120000f9640): recv signal r_handle_unref
nua_stack.c:558 nua_signal() nua(0x6120000f9640): sent signal r_handle_unref
nua.c:1157 nua_unref_user() nua: nua_unref_user: entering
nua_stack.c:599 nua_stack_signal() nua((nil)): recv signal r_unref
nua_stack.c:558 nua_signal() nua((nil)): sent signal r_unref
nua.c:365 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:365 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:920 nua_handle_destroy() nua: nua_handle_destroy: entering
nua.c:1170 nua_handle_unref_user() nua nua_handle_unref_user(0x6120000f9640): entering
nua_stack.c:599 nua_stack_signal() nua(0x6120000f9640): recv signal r_handle_unref
nua_stack.c:558 nua_signal() nua(0x6120000f9640): sent signal r_handle_unref
nua.c:1157 nua_unref_user() nua: nua_unref_user: entering
nua_stack.c:599 nua_stack_signal() nua((nil)): recv signal r_unref
nua_stack.c:558 nua_signal() nua((nil)): sent signal r_unref
nua.c:365 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:365 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:920 nua_handle_destroy() nua: nua_handle_destroy: entering
nua.c:1170 nua_handle_unref_user() nua nua_handle_unref_user(0x6120000f9640): entering
nua_stack.c:599 nua_stack_signal() nua(0x6120000f9640): recv signal r_handle_unref
nua_stack.c:558 nua_signal() nua(0x6120000f9640): sent signal r_handle_unref
nua.c:1157 nua_unref_user() nua: nua_unref_user: entering
nua_stack.c:599 nua_stack_signal() nua((nil)): recv signal r_unref
nua_stack.c:558 nua_signal() nua((nil)): sent signal r_unref
nua.c:365 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:365 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:920 nua_handle_destroy() nua: nua_handle_destroy: entering
nua.c:1170 nua_handle_unref_user() nua nua_handle_unref_user(0x6120000f9640): entering
nua_stack.c:599 nua_stack_signal() nua(0x6120000f9640): recv signal r_handle_unref
nua_stack.c:558 nua_signal() nua(0x6120000f9640): sent signal r_handle_unref
nua.c:1157 nua_unref_user() nua: nua_unref_user: entering
nua_stack.c:599 nua_stack_signal() nua((nil)): recv signal r_unref
nua_stack.c:558 nua_signal() nua((nil)): sent signal r_unref
nua.c:365 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:365 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:920 nua_handle_destroy() nua: nua_handle_destroy: entering
nua.c:1170 nua_handle_unref_user() nua nua_handle_unref_user(0x6120000f9640): entering
nua_stack.c:599 nua_stack_signal() nua(0x6120000f9640): recv signal r_handle_unref
nua_stack.c:558 nua_signal() nua(0x6120000f9640): sent signal r_handle_unref
nua.c:1157 nua_unref_user() nua: nua_unref_user: entering
nua_stack.c:599 nua_stack_signal() nua((nil)): recv signal r_unref
nua_stack.c:558 nua_signal() nua((nil)): sent signal r_unref
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe 2023-11-03 20:28:48.760879 83.33% [DEBUG] switch_core_session.c:2979 sofia/external/s_sipp@172.19.0.2:5062 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe 2023-11-03 20:28:48.760879 83.33% [DEBUG] switch_core_state_machine.c:647 (sofia/external/s_sipp@172.19.0.2:5062) State EXECUTE going to sleep
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe 2023-11-03 20:28:48.760879 83.33% [DEBUG] switch_core_state_machine.c:581 (sofia/external/s_sipp@172.19.0.2:5062) Running State Change CS_HANGUP (Cur 1 Tot 2)
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe 2023-11-03 20:28:48.780869 83.33% [DEBUG] switch_core_state_machine.c:844 (sofia/external/s_sipp@172.19.0.2:5062) Callstate Change ACTIVE -> HANGUP
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe 2023-11-03 20:28:48.780869 83.33% [DEBUG] switch_core_state_machine.c:846 (sofia/external/s_sipp@172.19.0.2:5062) State HANGUP
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe 2023-11-03 20:28:48.780869 83.33% [DEBUG] mod_sofia.c:469 Channel sofia/external/s_sipp@172.19.0.2:5062 hanging up, cause: MANDATORY_IE_MISSING
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe 2023-11-03 20:28:48.780869 83.33% [DEBUG] switch_core_state_machine.c:59 sofia/external/s_sipp@172.19.0.2:5062 Standard HANGUP, cause: MANDATORY_IE_MISSING
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe 2023-11-03 20:28:48.780869 83.33% [DEBUG] switch_core_state_machine.c:846 (sofia/external/s_sipp@172.19.0.2:5062) State HANGUP going to sleep
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe 2023-11-03 20:28:48.780869 83.33% [DEBUG] switch_core_state_machine.c:616 (sofia/external/s_sipp@172.19.0.2:5062) State Change CS_HANGUP -> CS_REPORTING
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe 2023-11-03 20:28:48.780869 83.33% [DEBUG] switch_core_state_machine.c:581 (sofia/external/s_sipp@172.19.0.2:5062) Running State Change CS_REPORTING (Cur 1 Tot 2)
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe 2023-11-03 20:28:48.780869 83.33% [DEBUG] switch_core_state_machine.c:932 (sofia/external/s_sipp@172.19.0.2:5062) State REPORTING
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe 2023-11-03 20:28:48.780869 83.33% [DEBUG] switch_core_state_machine.c:168 sofia/external/s_sipp@172.19.0.2:5062 Standard REPORTING, cause: MANDATORY_IE_MISSING
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe 2023-11-03 20:28:48.780869 83.33% [DEBUG] switch_core_state_machine.c:932 (sofia/external/s_sipp@172.19.0.2:5062) State REPORTING going to sleep
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe 2023-11-03 20:28:48.780869 83.33% [DEBUG] switch_core_state_machine.c:607 (sofia/external/s_sipp@172.19.0.2:5062) State Change CS_REPORTING -> CS_DESTROY
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe 2023-11-03 20:28:48.780869 83.33% [DEBUG] switch_core_session.c:1744 Session 2 (sofia/external/s_sipp@172.19.0.2:5062) Locked, Waiting on external entities
nta.c:1317 agent_timer() nta: timer set next to 314 ms
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe 2023-11-03 20:28:48.902125 80.03% [NOTICE] switch_core_session.c:1762 Session 2 (sofia/external/s_sipp@172.19.0.2:5062) Ended
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe 2023-11-03 20:28:48.920872 80.03% [NOTICE] switch_core_session.c:1766 Close Channel sofia/external/s_sipp@172.19.0.2:5062 [CS_DESTROY]
2023-11-03 20:28:48.920872 80.03% [WARNING] switch_core.c:3492 Exit status (256): pkill -x sipp
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe 2023-11-03 20:28:48.920872 80.03% [DEBUG] switch_core_state_machine.c:735 (sofia/external/s_sipp@172.19.0.2:5062) Running State Change CS_DESTROY (Cur 0 Tot 2)
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe 2023-11-03 20:28:48.920872 80.03% [DEBUG] switch_core_state_machine.c:745 (sofia/external/s_sipp@172.19.0.2:5062) State DESTROY
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe 2023-11-03 20:28:48.920872 80.03% [DEBUG] mod_sofia.c:380 sofia/external/s_sipp@172.19.0.2:5062 SOFIA DESTROY
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe 2023-11-03 20:28:48.920872 80.03% [DEBUG] switch_core_state_machine.c:175 sofia/external/s_sipp@172.19.0.2:5062 Standard DESTROY
8e3d83bf-7d25-4e8f-bfc5-76e5773dc2fe 2023-11-03 20:28:48.920872 80.03% [DEBUG] switch_core_state_machine.c:745 (sofia/external/s_sipp@172.19.0.2:5062) State DESTROY going to sleep
nta.c:7223 _nta_incoming_timer() nta: timer I fired, terminate 200 response
nta.c:5904 incoming_reclaim_queued() incoming_reclaim_all((nil), (nil), 0x7fd316caf9d0)
nta.c:7270 _nta_incoming_timer() nta_incoming_timer: 0/0 resent, 0/0 tout, 1/6 term, 1/6 free
nta.c:1317 agent_timer() nta: timer set next to 1654 ms
 PASS
uac_digest_leak_udp ...............................................2023-11-03 20:28:50.144578 76.70% [DEBUG] switch_ivr_originate.c:2301 Parsing global variables
1a55dac0-28da-4576-a808-7c42d954e58a 2023-11-03 20:28:50.144578 76.70% [NOTICE] switch_channel.c:1143 New Channel loopback/+15553334444-a [1a55dac0-28da-4576-a808-7c42d954e58a]
1a55dac0-28da-4576-a808-7c42d954e58a 2023-11-03 20:28:50.144578 76.70% [DEBUG] mod_loopback.c:166 loopback/+15553334444-a setup codec L16/8000/20
1a55dac0-28da-4576-a808-7c42d954e58a 2023-11-03 20:28:50.144578 76.70% [NOTICE] switch_channel.c:1141 Rename Channel loopback/+15553334444-a->loopback/+15553334444-a [1a55dac0-28da-4576-a808-7c42d954e58a]
1a55dac0-28da-4576-a808-7c42d954e58a 2023-11-03 20:28:50.144578 76.70% [DEBUG] mod_loopback.c:1262 (loopback/+15553334444-a) State Change CS_NEW -> CS_INIT
1a55dac0-28da-4576-a808-7c42d954e58a 2023-11-03 20:28:50.144578 76.70% [DEBUG] switch_core_state_machine.c:581 (loopback/+15553334444-a) Running State Change CS_INIT (Cur 1 Tot 3)
1a55dac0-28da-4576-a808-7c42d954e58a 2023-11-03 20:28:50.144578 76.70% [DEBUG] switch_core_state_machine.c:624 (loopback/+15553334444-a) State INIT
95dd4f25-6196-4730-82c1-2d5e16ec3ad9 2023-11-03 20:28:50.144578 76.70% [NOTICE] switch_channel.c:1143 New Channel loopback/+15553334444-b [95dd4f25-6196-4730-82c1-2d5e16ec3ad9]
95dd4f25-6196-4730-82c1-2d5e16ec3ad9 2023-11-03 20:28:50.144578 76.70% [DEBUG] mod_loopback.c:166 loopback/+15553334444-b setup codec L16/8000/20
95dd4f25-6196-4730-82c1-2d5e16ec3ad9 2023-11-03 20:28:50.160868 76.70% [DEBUG] mod_loopback.c:288 (loopback/+15553334444-b) State Change CS_NEW -> CS_INIT
95dd4f25-6196-4730-82c1-2d5e16ec3ad9 2023-11-03 20:28:50.160868 76.70% [DEBUG] mod_loopback.c:356 setting other_loopback_from_uuid on b leg to (null)
1a55dac0-28da-4576-a808-7c42d954e58a 2023-11-03 20:28:50.160868 76.70% [DEBUG] mod_loopback.c:380 (loopback/+15553334444-a) State Change CS_INIT -> CS_ROUTING
1a55dac0-28da-4576-a808-7c42d954e58a 2023-11-03 20:28:50.160868 76.70% [DEBUG] switch_core_state_machine.c:624 (loopback/+15553334444-a) State INIT going to sleep
95dd4f25-6196-4730-82c1-2d5e16ec3ad9 2023-11-03 20:28:50.160868 76.70% [DEBUG] switch_core_state_machine.c:581 (loopback/+15553334444-b) Running State Change CS_INIT (Cur 2 Tot 4)
95dd4f25-6196-4730-82c1-2d5e16ec3ad9 2023-11-03 20:28:50.160868 76.70% [DEBUG] switch_core_state_machine.c:624 (loopback/+15553334444-b) State INIT
95dd4f25-6196-4730-82c1-2d5e16ec3ad9 2023-11-03 20:28:50.160868 76.70% [DEBUG] mod_loopback.c:380 (loopback/+15553334444-b) State Change CS_INIT -> CS_ROUTING
95dd4f25-6196-4730-82c1-2d5e16ec3ad9 2023-11-03 20:28:50.160868 76.70% [DEBUG] switch_core_state_machine.c:624 (loopback/+15553334444-b) State INIT going to sleep
95dd4f25-6196-4730-82c1-2d5e16ec3ad9 2023-11-03 20:28:50.160868 76.70% [DEBUG] switch_core_state_machine.c:581 (loopback/+15553334444-b) Running State Change CS_ROUTING (Cur 2 Tot 4)
95dd4f25-6196-4730-82c1-2d5e16ec3ad9 2023-11-03 20:28:50.160868 76.70% [DEBUG] switch_channel.c:2400 (loopback/+15553334444-b) Callstate Change DOWN -> RINGING
1a55dac0-28da-4576-a808-7c42d954e58a 2023-11-03 20:28:50.184578 76.70% [DEBUG] switch_core_state_machine.c:581 (loopback/+15553334444-a) Running State Change CS_ROUTING (Cur 2 Tot 4)
1a55dac0-28da-4576-a808-7c42d954e58a 2023-11-03 20:28:50.184578 76.70% [DEBUG] switch_core_state_machine.c:640 (loopback/+15553334444-a) State ROUTING
1a55dac0-28da-4576-a808-7c42d954e58a 2023-11-03 20:28:50.184578 76.70% [DEBUG] mod_loopback.c:412 loopback/+15553334444-a CHANNEL ROUTING
1a55dac0-28da-4576-a808-7c42d954e58a 2023-11-03 20:28:50.184578 76.70% [DEBUG] switch_ivr_originate.c:67 (loopback/+15553334444-a) State Change CS_ROUTING -> CS_CONSUME_MEDIA
95dd4f25-6196-4730-82c1-2d5e16ec3ad9 2023-11-03 20:28:50.184578 76.70% [DEBUG] switch_core_state_machine.c:640 (loopback/+15553334444-b) State ROUTING
95dd4f25-6196-4730-82c1-2d5e16ec3ad9 2023-11-03 20:28:50.184578 76.70% [DEBUG] mod_loopback.c:412 loopback/+15553334444-b CHANNEL ROUTING
95dd4f25-6196-4730-82c1-2d5e16ec3ad9 2023-11-03 20:28:50.184578 76.70% [DEBUG] switch_core_state_machine.c:230 loopback/+15553334444-b Standard ROUTING
1a55dac0-28da-4576-a808-7c42d954e58a 2023-11-03 20:28:50.184578 76.70% [DEBUG] switch_core_state_machine.c:640 (loopback/+15553334444-a) State ROUTING going to sleep
1a55dac0-28da-4576-a808-7c42d954e58a 2023-11-03 20:28:50.184578 76.70% [DEBUG] switch_core_state_machine.c:581 (loopback/+15553334444-a) Running State Change CS_CONSUME_MEDIA (Cur 2 Tot 4)
1a55dac0-28da-4576-a808-7c42d954e58a 2023-11-03 20:28:50.184578 76.70% [DEBUG] switch_core_state_machine.c:659 (loopback/+15553334444-a) State CONSUME_MEDIA
1a55dac0-28da-4576-a808-7c42d954e58a 2023-11-03 20:28:50.184578 76.70% [DEBUG] mod_loopback.c:681 CHANNEL CONSUME_MEDIA
1a55dac0-28da-4576-a808-7c42d954e58a 2023-11-03 20:28:50.184578 76.70% [DEBUG] switch_core_state_machine.c:659 (loopback/+15553334444-a) State CONSUME_MEDIA going to sleep
95dd4f25-6196-4730-82c1-2d5e16ec3ad9 2023-11-03 20:28:50.184578 76.70% [INFO] mod_dialplan_xml.c:642 Processing  <0000000000>->+15553334444 in context default
95dd4f25-6196-4730-82c1-2d5e16ec3ad9 Dialplan: loopback/+15553334444-b parsing [default->unit_test_sipp-uac-digest-leak] continue=false
95dd4f25-6196-4730-82c1-2d5e16ec3ad9 Dialplan: loopback/+15553334444-b Regex (PASS) [unit_test_sipp-uac-digest-leak] destination_number(+15553334444) =~ /^\+15553334444$/ break=on-false
95dd4f25-6196-4730-82c1-2d5e16ec3ad9 Dialplan: loopback/+15553334444-b Action info() 
95dd4f25-6196-4730-82c1-2d5e16ec3ad9 Dialplan: loopback/+15553334444-b Action answer() 
95dd4f25-6196-4730-82c1-2d5e16ec3ad9 Dialplan: loopback/+15553334444-b Action playback(silence_stream://-1) 
95dd4f25-6196-4730-82c1-2d5e16ec3ad9 2023-11-03 20:28:50.184578 76.70% [DEBUG] switch_core_state_machine.c:281 (loopback/+15553334444-b) State Change CS_ROUTING -> CS_EXECUTE
95dd4f25-6196-4730-82c1-2d5e16ec3ad9 2023-11-03 20:28:50.184578 76.70% [DEBUG] switch_core_state_machine.c:640 (loopback/+15553334444-b) State ROUTING going to sleep
95dd4f25-6196-4730-82c1-2d5e16ec3ad9 2023-11-03 20:28:50.184578 76.70% [DEBUG] switch_core_state_machine.c:581 (loopback/+15553334444-b) Running State Change CS_EXECUTE (Cur 2 Tot 4)
95dd4f25-6196-4730-82c1-2d5e16ec3ad9 2023-11-03 20:28:50.202746 76.70% [DEBUG] switch_core_state_machine.c:647 (loopback/+15553334444-b) State EXECUTE
95dd4f25-6196-4730-82c1-2d5e16ec3ad9 2023-11-03 20:28:50.202746 76.70% [DEBUG] mod_loopback.c:454 loopback/+15553334444-b CHANNEL EXECUTE
95dd4f25-6196-4730-82c1-2d5e16ec3ad9 2023-11-03 20:28:50.202746 76.70% [DEBUG] switch_core_state_machine.c:323 loopback/+15553334444-b Standard EXECUTE
95dd4f25-6196-4730-82c1-2d5e16ec3ad9 EXECUTE [depth=0] loopback/+15553334444-b info()
95dd4f25-6196-4730-82c1-2d5e16ec3ad9 2023-11-03 20:28:50.202746 76.70% [INFO] mod_dptools.c:1884 CHANNEL_DATA:
Channel-State: [CS_EXECUTE]
Channel-Call-State: [RINGING]
Channel-State-Number: [4]
Channel-Name: [loopback/+15553334444-b]
Unique-ID: [95dd4f25-6196-4730-82c1-2d5e16ec3ad9]
Call-Direction: [inbound]
Presence-Call-Direction: [inbound]
Channel-HIT-Dialplan: [true]
Channel-Call-UUID: [95dd4f25-6196-4730-82c1-2d5e16ec3ad9]
Answer-State: [ringing]
Channel-Read-Codec-Name: [L16]
Channel-Read-Codec-Rate: [8000]
Channel-Read-Codec-Bit-Rate: [128000]
Channel-Write-Codec-Name: [L16]
Channel-Write-Codec-Rate: [8000]
Channel-Write-Codec-Bit-Rate: [128000]
Caller-Direction: [inbound]
Caller-Logical-Direction: [inbound]
Caller-Dialplan: [xml]
Caller-Caller-ID-Number: [0000000000]
Caller-Orig-Caller-ID-Number: [0000000000]
Caller-Callee-ID-Name: [Outbound Call]
Caller-Callee-ID-Number: [+15553334444]
Caller-ANI: [0000000000]
Caller-Destination-Number: [+15553334444]
Caller-Unique-ID: [95dd4f25-6196-4730-82c1-2d5e16ec3ad9]
Caller-Source: [mod_loopback]
Caller-Context: [default]
Caller-Channel-Name: [loopback/+15553334444-b]
Caller-Profile-Index: [1]
Caller-Profile-Created-Time: [1699043330160868]
Caller-Channel-Created-Time: [1699043330160868]
Caller-Channel-Answered-Time: [0]
Caller-Channel-Progress-Time: [0]
Caller-Channel-Progress-Media-Time: [0]
Caller-Channel-Hangup-Time: [0]
Caller-Channel-Transfer-Time: [0]
Caller-Channel-Resurrect-Time: [0]
Caller-Channel-Bridged-Time: [0]
Caller-Channel-Last-Hold: [0]
Caller-Channel-Hold-Accum: [0]
Caller-Screen-Bit: [true]
Caller-Privacy-Hide-Name: [false]
Caller-Privacy-Hide-Number: [false]
variable_direction: [inbound]
variable_uuid: [95dd4f25-6196-4730-82c1-2d5e16ec3ad9]
variable_session_id: [4]
variable_channel_name: [loopback/+15553334444-b]
variable_read_codec: [L16]
variable_read_rate: [8000]
variable_write_codec: [L16]
variable_write_rate: [8000]
variable_other_loopback_leg_uuid: [1a55dac0-28da-4576-a808-7c42d954e58a]
variable_loopback_leg: [B]
variable_call_uuid: [95dd4f25-6196-4730-82c1-2d5e16ec3ad9]
vBackground mode - PID=[18886]
ariable_current_application: [info]


95dd4f25-6196-4730-82c1-2d5e16ec3ad9 EXECUTE [depth=0] loopback/+15553334444-b answer()
1a55dac0-28da-4576-a808-7c42d954e58a 2023-11-03 20:28:50.220871 76.70% [NOTICE] mod_loopback.c:1021 Channel [loopback/+15553334444-a] has been answered
1a55dac0-28da-4576-a808-7c42d954e58a 2023-11-03 20:28:50.244576 76.70% [DEBUG] switch_channel.c:3913 (loopback/+15553334444-a) Callstate Change DOWN -> ACTIVE
95dd4f25-6196-4730-82c1-2d5e16ec3ad9 2023-11-03 20:28:50.244576 76.70% [NOTICE] mod_dptools.c:1406 Channel [loopback/+15553334444-b] has been answered
2023-11-03 20:28:50.244576 76.70% [DEBUG] switch_ivr_originate.c:3913 Originate Resulted in Success: [loopback/+15553334444-a] Peer UUID: 1a55dac0-28da-4576-a808-7c42d954e58a
95dd4f25-6196-4730-82c1-2d5e16ec3ad9 2023-11-03 20:28:50.263819 76.70% [DEBUG] switch_channel.c:3913 (loopback/+15553334444-b) Callstate Change RINGING -> ACTIVE
95dd4f25-6196-4730-82c1-2d5e16ec3ad9 EXECUTE [depth=0] loopback/+15553334444-b playback(silence_stream://-1)
2023-11-03 20:28:50.284580 76.70% [WARNING] switch_core.c:3492 Exit status (25344): sipp 172.19.0.2:5080 -nr -p 5062 -m 1 -s 1001 -recv_timeout 10000 -timeout 10s -sf sipp-scenarios/uac_digest_leak.xml -bg 
sipp 172.19.0.2:5080 -nr -p 5062 -m 1 -s 1001 -recv_timeout 10000 -timeout 10s -sf sipp-scenarios/uac_digest_leak.xml -bg 
95dd4f25-6196-4730-82c1-2d5e16ec3ad9 2023-11-03 20:28:50.284580 76.70% [DEBUG] switch_ivr_play_say.c:1562 Codec Activated L16@8000hz 1 channels 20ms
tport.c:2769 tport_wakeup_pri() tport_wakeup_pri(0x6160000f1b80): events IN
tport.c:2900 tport_recv_event() tport_recv_event(0x6160000f1b80)
tport.c:3237 tport_recv_iovec() tport_recv_iovec(0x6160000f1b80) msg 0x6190003e0880 from (udp/172.19.0.2:5080) has 490 bytes, veclen = 1
recv 490 bytes from udp/[172.19.0.2]:5062 at 20:28:50.384213:
------------------------------------------------------------------------
INVITE sip:1001@172.19.0.2:5080 SIP/2.0
Via: SIP/2.0/UDP 127.0.0.1:5062;branch=z9hG4bK-18885-1-0
From: sipp <sip:1001@127.0.0.1:5062>;tag=1
To: sut <sip:1001@172.19.0.2:5080>
Call-ID: 1-18885@172.19.0.2
CSeq: 1 INVITE
Contact: sip:1001@127.0.0.1:5062
Max-Forwards: 70
Subject: Performance Test
Content-Type: application/sdp
Content-Length:   131

v=0
o=user1 53655765 2353687637 IN IP4 172.19.0.2
s=-
c=IN IP4 172.19.0.2
t=0 0
m=audio 6000 RTP/AVP 0
a=rtpmap:0 PCMU/8000

tport.c:3055 tport_deliver() tport_deliver(0x6160000f1b80): msg 0x6190003e0880 (490 bytes) from udp/172.19.0.2:5080/sip next=(nil)
nta.c:2957 agent_recv_request() nta: received INVITE sip:1001@172.19.0.2:5080 SIP/2.0 (CSeq 1) (load: 1 rps)
nta.c:3254 agent_check_request_via() nta: Via check: received=172.19.0.2
nta.c:3326 agent_aliases() nta: canonizing sip:1001@172.19.0.2:5080 with contact
nta.c:3164 agent_recv_request() nta: INVITE (1) going to a default leg
nta.c:1369 set_timeout() nta: timer shortened to 200 ms
nua_server.c:102 nua_stack_process_request() nua: nua_stack_process_request: entering
nua_stack.c:938 nh_create() nua: nh_create: entering
nua_common.c:108 nh_create_handle() nua: nh_create_handle: entering
nua_params.c:484 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:278 soa_clone() soa_clone(static::0x6150000b0480, 0x606000050000, 0x6120001d4ac0) called
soa.c:402 soa_set_params() soa_set_params(static::0x6150000b5c00, ...) called
nta.c:4497 nta_leg_tcreate() nta_leg_tcreate(0x60c000088b40)
soa.c:1301 soa_init_offer_answer() soa_init_offer_answer(static::0x6150000b5c00) called
soa.c:1170 soa_set_remote_sdp() soa_set_remote_sdp(static::0x6150000b5c00, (nil), 0x6150000b5ae7, 131) called
nua_dialog.c:336 nua_dialog_usage_add() nua(0x6120001d4ac0): adding session usage
nua_stack.c:301 nua_stack_event() nua(0x6120001d4ac0): event i_invite 100 Trying
nua_session.c:4131 signal_call_state_change() nua(0x6120001d4ac0): call state changed: init -> received, received offer
soa.c:1096 soa_get_remote_sdp() soa_get_remote_sdp(static::0x6150000b5c00, [0x7fd316caf398], [0x7fd316caf390], [(nil)]) called
nua_stack.c:301 nua_stack_event() nua(0x6120001d4ac0): event i_state 100 Trying
nua_stack.c:389 nua_application_event() nua: nua_application_event: entering
nua.c:341 nua_handle_bind() nua: nua_handle_bind: entering
7b363765-0252-4ec5-a2ef-7f518831b6cf 2023-11-03 20:28:50.384576 76.70% [NOTICE] switch_channel.c:1143 New Channel sofia/external/1001@127.0.0.1:5062 [7b363765-0252-4ec5-a2ef-7f518831b6cf]
nua.c:1170 nua_handle_unref_user() nua nua_handle_unref_user(0x6120001d4ac0): entering
nua_stack.c:558 nua_signal() nua(0x6120001d4ac0): sent signal r_handle_unref
nua.c:1157 nua_unref_user() nua: nua_unref_user: entering
nua_stack.c:558 nua_signal() nua((nil)): sent signal r_unref
nua_stack.c:389 nua_application_event() nua: nua_application_event: entering
nua.c:1170 nua_handle_unref_user() nua nua_handle_unref_user(0x6120001d4ac0): entering
nua_stack.c:558 nua_signal() nua(0x6120001d4ac0): sent signal r_handle_unref
nua.c:1157 nua_unref_user() nua: nua_unref_user: entering
nua_stack.c:558 nua_signal() nua((nil)): sent signal r_unref
nua_stack.c:599 nua_stack_signal() nua(0x6120001d4ac0): recv signal r_handle_unref
nua_stack.c:599 nua_stack_signal() nua((nil)): recv signal r_unref
nua_stack.c:599 nua_stack_signal() nua(0x6120001d4ac0): recv signal r_handle_unref
nua_stack.c:599 nua_stack_signal() nua((nil)): recv signal r_unref
7b363765-0252-4ec5-a2ef-7f518831b6cf 2023-11-03 20:28:50.384576 76.70% [DEBUG] switch_core_state_machine.c:581 (sofia/external/1001@127.0.0.1:5062) Running State Change CS_NEW (Cur 3 Tot 5)
nua.c:365 nua_handle_magic() nua: nua_handle_magic: entering
7b363765-0252-4ec5-a2ef-7f518831b6cf 2023-11-03 20:28:50.384576 76.70% [INFO] sofia.c:10459 sofia/external/1001@127.0.0.1:5062 receiving invite from 172.19.0.2:5062 version: 1.10.11-dev git 583788b 2023-11-03 20:19:48Z 64bit call-id: 1-18885@172.19.0.2
nua.c:365 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:1170 nua_handle_unref_user() nua nua_handle_unref_user(0x6120001d4ac0): entering
nua_stack.c:599 nua_stack_signal() nua(0x6120001d4ac0): recv signal r_handle_unref
nua_stack.c:558 nua_signal() nua(0x6120001d4ac0): sent signal r_handle_unref
nua.c:1157 nua_unref_user() nua: nua_unref_user: entering
nua_stack.c:599 nua_stack_signal() nua((nil)): recv signal r_unref
nua_stack.c:558 nua_signal() nua((nil)): sent signal r_unref
nua.c:365 nua_handle_magic() nua: nua_handle_magic: entering
7b363765-0252-4ec5-a2ef-7f518831b6cf 2023-11-03 20:28:50.384576 76.70% [DEBUG] sofia.c:7493 Channel sofia/external/1001@127.0.0.1:5062 entering state [received][100]
7b363765-0252-4ec5-a2ef-7f518831b6cf 2023-11-03 20:28:50.384576 76.70% [DEBUG] sofia.c:7503 Remote SDP:
v=0
o=user1 53655765 2353687637 IN IP4 172.19.0.2
s=-
c=IN IP4 172.19.0.2
t=0 0
m=audio 6000 RTP/AVP 0
a=rtpmap:0 PCMU/8000

7b363765-0252-4ec5-a2ef-7f518831b6cf 2023-11-03 20:28:50.384576 76.70% [DEBUG] sofia.c:7906 (sofia/external/1001@127.0.0.1:5062) State Change CS_NEW -> CS_INIT
nua.c:365 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:1170 nua_handle_unref_user() nua nua_handle_unref_user(0x6120001d4ac0): entering
nua_stack.c:599 nua_stack_signal() nua(0x6120001d4ac0): recv signal r_handle_unref
nua_stack.c:558 nua_signal() nua(0x6120001d4ac0): sent signal r_handle_unref
nua.c:1157 nua_unref_user() nua: nua_unref_user: entering
nua_stack.c:599 nua_stack_signal() nua((nil)): recv signal r_unref
nua_stack.c:558 nua_signal() nua((nil)): sent signal r_unref
7b363765-0252-4ec5-a2ef-7f518831b6cf 2023-11-03 20:28:50.384576 76.70% [DEBUG] switch_core_state_machine.c:600 (sofia/external/1001@127.0.0.1:5062) State NEW
7b363765-0252-4ec5-a2ef-7f518831b6cf 2023-11-03 20:28:50.384576 76.70% [DEBUG] switch_core_state_machine.c:581 (sofia/external/1001@127.0.0.1:5062) Running State Change CS_INIT (Cur 3 Tot 5)
7b363765-0252-4ec5-a2ef-7f518831b6cf 2023-11-03 20:28:50.384576 76.70% [DEBUG] switch_core_state_machine.c:624 (sofia/external/1001@127.0.0.1:5062) State INIT
7b363765-0252-4ec5-a2ef-7f518831b6cf 2023-11-03 20:28:50.384576 76.70% [DEBUG] mod_sofia.c:97 sofia/external/1001@127.0.0.1:5062 SOFIA INIT
7b363765-0252-4ec5-a2ef-7f518831b6cf 2023-11-03 20:28:50.384576 76.70% [DEBUG] switch_core_state_machine.c:40 sofia/external/1001@127.0.0.1:5062 Standard INIT
7b363765-0252-4ec5-a2ef-7f518831b6cf 2023-11-03 20:28:50.384576 76.70% [DEBUG] switch_core_state_machine.c:48 (sofia/external/1001@127.0.0.1:5062) State Change CS_INIT -> CS_ROUTING
7b363765-0252-4ec5-a2ef-7f518831b6cf 2023-11-03 20:28:50.384576 76.70% [DEBUG] switch_core_state_machine.c:624 (sofia/external/1001@127.0.0.1:5062) State INIT going to sleep
7b363765-0252-4ec5-a2ef-7f518831b6cf 2023-11-03 20:28:50.384576 76.70% [DEBUG] switch_core_state_machine.c:581 (sofia/external/1001@127.0.0.1:5062) Running State Change CS_ROUTING (Cur 3 Tot 5)
7b363765-0252-4ec5-a2ef-7f518831b6cf 2023-11-03 20:28:50.384576 76.70% [DEBUG] switch_channel.c:2400 (sofia/external/1001@127.0.0.1:5062) Callstate Change DOWN -> RINGING
7b363765-0252-4ec5-a2ef-7f518831b6cf 2023-11-03 20:28:50.404578 76.70% [DEBUG] switch_core_state_machine.c:640 (sofia/external/1001@127.0.0.1:5062) State ROUTING
nua.c:878 nua_respond() nua: nua_respond: entering
nua_stack.c:601 nua_stack_signal() nua(0x6120001d4ac0): recv signal r_respond 100 Trying
nua_params.c:484 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:402 soa_set_params() soa_set_params(static::0x6150000b5c00, ...) called
tport.c:3290 tport_tsend() tport_tsend(0x6160000f1b80) tpn = UDP/172.19.0.2:5062
tport.c:4076 tport_resolve() tport_resolve addrinfo = 172.19.0.2:5062
tport.c:4713 tport_by_addrinfo() tport_by_addrinfo(0x6160000f1b80): not found by name UDP/172.19.0.2:5062
tport.c:3625 tport_vsend() tport_vsend(0x6160000f1b80): 267 bytes of 267 to udp/172.19.0.2:5062
tport.c:3526 tport_send_msg() tport_vsend returned 267
send 267 bytes to udp/[172.19.0.2]:5062 at 20:28:50.414231:
------------------------------------------------------------------------
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 127.0.0.1:5062;branch=z9hG4bK-18885-1-0;received=172.19.0.2
From: sipp <sip:1001@127.0.0.1:5062>;tag=1
To: sut <sip:1001@172.19.0.2:5080>
Call-ID: 1-18885@172.19.0.2
CSeq: 1 INVITE
User-Agent: Unit Test
Content-Length: 0


nta.c:6879 incoming_reply() nta: sent 100 Trying for INVITE (1)
nua_stack.c:558 nua_signal() nua(0x6120001d4ac0): sent signal r_respond
7b363765-0252-4ec5-a2ef-7f518831b6cf 2023-11-03 20:28:50.404578 76.70% [DEBUG] mod_sofia.c:158 sofia/external/1001@127.0.0.1:5062 SOFIA ROUTING
7b363765-0252-4ec5-a2ef-7f518831b6cf 2023-11-03 20:28:50.404578 76.70% [DEBUG] switch_core_state_machine.c:230 sofia/external/1001@127.0.0.1:5062 Standard ROUTING
7b363765-0252-4ec5-a2ef-7f518831b6cf 2023-11-03 20:28:50.404578 76.70% [INFO] mod_dialplan_xml.c:642 Processing sipp <1001>->1001 in context default
7b363765-0252-4ec5-a2ef-7f518831b6cf Dialplan: sofia/external/1001@127.0.0.1:5062 parsing [default->unit_test_sipp-uac-digest-leak] continue=false
7b363765-0252-4ec5-a2ef-7f518831b6cf Dialplan: sofia/external/1001@127.0.0.1:5062 Regex (FAIL) [unit_test_sipp-uac-digest-leak] destination_number(1001) =~ /^\+15553334444$/ break=on-false
7b363765-0252-4ec5-a2ef-7f518831b6cf Dialplan: sofia/external/1001@127.0.0.1:5062 parsing [default->sipp_telephone_check] continue=false
7b363765-0252-4ec5-a2ef-7f518831b6cf Dialplan: sofia/external/1001@127.0.0.1:5062 Regex (FAIL) [sipp_telephone_check] destination_number(1001) =~ /^1212121212$/ break=on-false
7b363765-0252-4ec5-a2ef-7f518831b6cf Dialplan: sofia/external/1001@127.0.0.1:5062 parsing [default->sipp] continue=false
7b363765-0252-4ec5-a2ef-7f518831b6cf Dialplan: sofia/external/1001@127.0.0.1:5062 Absolute Condition [sipp]
7b363765-0252-4ec5-a2ef-7f518831b6cf Dialplan: sofia/external/1001@127.0.0.1:5062 Action info() 
7b363765-0252-4ec5-a2ef-7f518831b6cf Dialplan: sofia/external/1001@127.0.0.1:5062 Action answer() 
7b363765-0252-4ec5-a2ef-7f518831b6cf Dialplan: sofia/external/1001@127.0.0.1:5062 Action voicemail(default  1001) 
7b363765-0252-4ec5-a2ef-7f518831b6cf 2023-11-03 20:28:50.404578 76.70% [DEBUG] switch_core_state_machine.c:281 (sofia/external/1001@127.0.0.1:5062) State Change CS_ROUTING -> CS_EXECUTE
7b363765-0252-4ec5-a2ef-7f518831b6cf 2023-11-03 20:28:50.404578 76.70% [DEBUG] switch_core_state_machine.c:640 (sofia/external/1001@127.0.0.1:5062) State ROUTING going to sleep
7b363765-0252-4ec5-a2ef-7f518831b6cf 2023-11-03 20:28:50.404578 76.70% [DEBUG] switch_core_state_machine.c:581 (sofia/external/1001@127.0.0.1:5062) Running State Change CS_EXECUTE (Cur 3 Tot 5)
7b363765-0252-4ec5-a2ef-7f518831b6cf 2023-11-03 20:28:50.421562 76.70% [DEBUG] switch_core_state_machine.c:647 (sofia/external/1001@127.0.0.1:5062) State EXECUTE
7b363765-0252-4ec5-a2ef-7f518831b6cf 2023-11-03 20:28:50.421562 76.70% [DEBUG] mod_sofia.c:213 sofia/external/1001@127.0.0.1:5062 SOFIA EXECUTE
7b363765-0252-4ec5-a2ef-7f518831b6cf 2023-11-03 20:28:50.421562 76.70% [DEBUG] switch_core_state_machine.c:323 sofia/external/1001@127.0.0.1:5062 Standard EXECUTE
7b363765-0252-4ec5-a2ef-7f518831b6cf EXECUTE [depth=0] sofia/external/1001@127.0.0.1:5062 info()
7b363765-0252-4ec5-a2ef-7f518831b6cf 2023-11-03 20:28:50.421562 76.70% [INFO] mod_dptools.c:1884 CHANNEL_DATA:
Channel-State: [CS_EXECUTE]
Channel-Call-State: [RINGING]
Channel-State-Number: [4]
Channel-Name: [sofia/external/1001@127.0.0.1:5062]
Unique-ID: [7b363765-0252-4ec5-a2ef-7f518831b6cf]
Call-Direction: [inbound]
Presence-Call-Direction: [inbound]
Channel-HIT-Dialplan: [true]
Channel-Call-UUID: [7b363765-0252-4ec5-a2ef-7f518831b6cf]
Answer-State: [ringing]
Caller-Direction: [inbound]
Caller-Logical-Direction: [inbound]
Caller-Username: [1001]
Caller-Dialplan: [XML]
Caller-Caller-ID-Name: [sipp]
Caller-Caller-ID-Number: [1001]
Caller-Orig-Caller-ID-Name: [sipp]
Caller-Orig-Caller-ID-Number: [1001]
Caller-Network-Addr: [172.19.0.2]
Caller-ANI: [1001]
Caller-Destination-Number: [1001]
Caller-Unique-ID: [7b363765-0252-4ec5-a2ef-7f518831b6cf]
Caller-Source: [mod_sofia]
Caller-Context: [default]
Caller-Channel-Name: [sofia/external/1001@127.0.0.1:5062]
Caller-Profile-Index: [1]
Caller-Profile-Created-Time: [1699043330384576]
Caller-Channel-Created-Time: [1699043330384576]
Caller-Channel-Answered-Time: [0]
Caller-Channel-Progress-Time: [0]
Caller-Channel-Progress-Media-Time: [0]
Caller-Channel-Hangup-Time: [0]
Caller-Channel-Transfer-Time: [0]
Caller-Channel-Resurrect-Time: [0]
Caller-Channel-Bridged-Time: [0]
Caller-Channel-Last-Hold: [0]
Caller-Channel-Hold-Accum: [0]
Caller-Screen-Bit: [true]
Caller-Privacy-Hide-Name: [false]
Caller-Privacy-Hide-Number: [false]
variable_direction: [inbound]
variable_uuid: [7b363765-0252-4ec5-a2ef-7f518831b6cf]
variable_session_id: [5]
variable_sip_from_user: [1001]
variable_sip_from_port: [5062]
variable_sip_from_uri: [1001@127.0.0.1:5062]
variable_sip_from_host: [127.0.0.1]
variable_video_media_flow: [disabled]
variable_audio_media_flow: [disabled]
variable_text_media_flow: [disabled]
variable_channel_name: [sofia/external/1001@127.0.0.1:5062]
variable_sip_call_id: [1-18885@172.19.0.2]
variable_sip_local_network_addr: [172.19.0.2]
variable_sip_network_ip: [172.19.0.2]
variable_sip_network_port: [5062]
variable_sip_invite_stamp: [1699043330384576]
variable_sip_received_ip: [172.19.0.2]
variable_sip_received_port: [5062]
variable_sip_via_protocol: [udp]
variable_sip_from_user_stripped: [1001]
variable_sip_from_tag: [1]
variable_sofia_profile_name: [external]
variable_sofia_profile_url: [sip:mod_sofia@172.19.0.2:5080]
variable_recovery_profile_name: [external]
variable_sip_full_via: [SIP/2.0/UDP 127.0.0.1:5062;branch=z9hG4bK-18885-1-0;received=172.19.0.2]
variable_sip_from_display: [sipp]
variable_sip_full_from: [sipp <sip:1001@127.0.0.1:5062>;tag=1]
variable_sip_to_display: [sut]
variable_sip_full_to: [sut <sip:1001@172.19.0.2:5080>]
variable_sip_req_user: [1001]
variable_sip_req_port: [5080]
variable_sip_req_uri: [1001@172.19.0.2:5080]
variable_sip_req_host: [172.19.0.2]
variable_sip_to_user: [1001]
variable_sip_to_port: [5080]
variable_sip_to_uri: [1001@172.19.0.2:5080]
variable_sip_to_host: [172.19.0.2]
variable_sip_contact_user: [1001]
variable_sip_contact_port: [5062]
variable_sip_contact_uri: [1001@127.0.0.1:5062]
variable_sip_contact_host: [127.0.0.1]
variable_rtp_use_codec_string: [PCMU]
variable_sip_subject: [Performance Test]
variable_sip_via_host: [127.0.0.1]
variable_sip_via_port: [5062]
variable_max_forwards: [70]
variable_switch_r_sdp: [v=0
o=user1 53655765 2353687637 IN IP4 172.19.0.2
s=-
c=IN IP4 172.19.0.2
t=0 0
m=audio 6000 RTP/AVP 0
a=rtpmap:0 PCMU/8000
]
variable_ep_codec_string: [CORE_PCM_MODULE.PCMU@8000h@20i@64000b]
variable_endpoint_disposition: [DELAYED NEGOTIATION]
variable_call_uuid: [7b363765-0252-4ec5-a2ef-7f518831b6cf]
variable_current_application: [info]


7b363765-0252-4ec5-a2ef-7f518831b6cf EXECUTE [depth=0] sofia/external/1001@127.0.0.1:5062 answer()
7b363765-0252-4ec5-a2ef-7f518831b6cf 2023-11-03 20:28:50.440872 76.70% [DEBUG] switch_core_media.c:5526 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
7b363765-0252-4ec5-a2ef-7f518831b6cf 2023-11-03 20:28:50.440872 76.70% [DEBUG] switch_core_media.c:5588 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
7b363765-0252-4ec5-a2ef-7f518831b6cf 2023-11-03 20:28:50.440872 76.70% [DEBUG] switch_core_media.c:3731 Set Codec sofia/external/1001@127.0.0.1:5062 PCMU/8000 20 ms 160 samples 64000 bits 1 channels
7b363765-0252-4ec5-a2ef-7f518831b6cf 2023-11-03 20:28:50.440872 76.70% [DEBUG] switch_core_codec.c:111 sofia/external/1001@127.0.0.1:5062 Original read codec set to PCMU:0
7b363765-0252-4ec5-a2ef-7f518831b6cf 2023-11-03 20:28:50.440872 76.70% [DEBUG] switch_core_media.c:5863 No 2833 in SDP.  Disable 2833 dtmf and switch to INFO
7b363765-0252-4ec5-a2ef-7f518831b6cf 2023-11-03 20:28:50.440872 76.70% [DEBUG] switch_core_media.c:8660 AUDIO RTP [sofia/external/1001@127.0.0.1:5062] 172.19.0.2 port 26824 -> 172.19.0.2 port 6000 codec: 0 ms: 20
7b363765-0252-4ec5-a2ef-7f518831b6cf 2023-11-03 20:28:50.440872 76.70% [DEBUG] switch_rtp.c:4535 Starting timer [soft] 160 bytes per 20ms
7b363765-0252-4ec5-a2ef-7f518831b6cf 2023-11-03 20:28:50.440872 76.70% [DEBUG] switch_core_media.c:9003 sofia/external/1001@127.0.0.1:5062 Set rtp dtmf delay to 40
7b363765-0252-4ec5-a2ef-7f518831b6cf 2023-11-03 20:28:50.440872 76.70% [NOTICE] sofia_media.c:90 Pre-Answer sofia/external/1001@127.0.0.1:5062!
7b363765-0252-4ec5-a2ef-7f518831b6cf 2023-11-03 20:28:50.520871 76.70% [DEBUG] switch_channel.c:3586 (sofia/external/1001@127.0.0.1:5062) Callstate Change RINGING -> EARLY
7b363765-0252-4ec5-a2ef-7f518831b6cf 2023-11-03 20:28:50.540867 76.70% [DEBUG] switch_core_media.c:8642 Audio params are unchanged for sofia/external/1001@127.0.0.1:5062.
7b363765-0252-4ec5-a2ef-7f518831b6cf 2023-11-03 20:28:50.540867 76.70% [DEBUG] mod_sofia.c:914 Local SDP sofia/external/1001@127.0.0.1:5062:
v=0
o=FS 1699016506 1699016507 IN IP4 172.19.0.2
s=FS
c=IN IP4 172.19.0.2
t=0 0
m=audio 26824 RTP/AVP 0
a=rtpmap:0 PCMU/8000
a=ptime:20
a=sendrecv

nua.c:878 nua_respond() nua: nua_respond: entering
nua_stack.c:558 nua_signal() nua(0x6120001d4ac0): sent signal r_respond
nua_stack.c:601 nua_stack_signal() nua(0x6120001d4ac0): recv signal r_respond 200 OK
nua_params.c:484 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:402 soa_set_params() soa_set_params(static::0x6150000b5c00, ...) called
soa.c:1051 soa_set_user_sdp() soa_set_user_sdp(static::0x6150000b5c00, (nil), 0x6160001e0b3c, -1) called
soa.c:889 soa_set_capability_sdp() soa_set_capability_sdp(static::0x6150000b5c00, (nil), 0x6160001e0b3c, -1) called
nua_session.c:2317 nua_invite_server_respond() nua: nua_invite_server_respond: entering
soa.c:1514 soa_generate_answer() soa_generate_answer(static::0x6150000b5c00) called
soa_static.c:1147 offer_answer_step() soa_static_offer_answer_action(0x6150000b5c00, soa_generate_answer): called
soa_static.c:1188 offer_answer_step() soa_static(0x6150000b5c00, soa_generate_answer): generating local description
soa_static.c:1229 offer_answer_step() soa_static(0x6150000b5c00, soa_generate_answer): upgrade with remote description
soa_static.c:1028 soa_sdp_mode_set() soa_sdp_mode_set(0x7fd316caf730, 0x6160001d3480, ""): called
soa_static.c:1445 offer_answer_step() soa_static(0x6150000b5c00, soa_generate_answer): storing local description
soa.c:1729 soa_activate() soa_activate(static::0x6150000b5c00, (nil)) called
soa.c:1268 soa_get_local_sdp() soa_get_local_sdp(static::0x6150000b5c00, [(nil)], [0x7fd316caf820], [0x7fd316caf81c]) called
tport.c:3290 tport_tsend() tport_tsend(0x6160000f1b80) tpn = UDP/172.19.0.2:5062
tport.c:4076 tport_resolve() tport_resolve addrinfo = 172.19.0.2:5062
tport.c:4713 tport_by_addrinfo() tport_by_addrinfo(0x6160000f1b80): not found by name UDP/172.19.0.2:5062
tport.c:3625 tport_vsend() tport_vsend(0x6160000f1b80): 852 bytes of 852 to udp/172.19.0.2:5062
tport.c:3526 tport_send_msg() tport_vsend returned 852
send 852 bytes to udp/[172.19.0.2]:5062 at 20:28:50.556688:
------------------------------------------------------------------------
SIP/2.0 200 OK
Via: SIP/2.0/UDP 127.0.0.1:5062;branch=z9hG4bK-18885-1-0;received=172.19.0.2
From: sipp <sip:1001@127.0.0.1:5062>;tag=1
To: sut <sip:1001@172.19.0.2:5080>;tag=D1jH7U8m74e9D
Call-ID: 1-18885@172.19.0.2
CSeq: 1 INVITE
Contact: <sip:1001@172.19.0.2:5080;transport=udp>
User-Agent: Unit Test
Accept: application/sdp
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
Supported: timer, path, replaces
Allow-Events: talk, hold, conference, refer
Session-Expires: 600;refresher=uas
Content-Type: application/sdp
Content-Disposition: session
Content-Length: 144
Remote-Party-ID: "1001" <sip:1001@172.19.0.2>;party=calling;privacy=off;screen=no

v=0
o=FS 1699016506 1699016507 IN IP4 172.19.0.2
s=FS
c=IN IP4 172.19.0.2
t=0 0
m=audio 26824 RTP/AVP 0
a=rtpmap:0 PCMU/8000
a=ptime:20

nta.c:6879 incoming_reply() nta: sent 200 OK for INVITE (1)
nua_session.c:4131 signal_call_state_change() nua(0x6120001d4ac0): call state changed: received -> completed, sent answer
soa.c:1268 soa_get_local_sdp() soa_get_local_sdp(static::0x6150000b5c00, [0x7fd316caf8e8], [0x7fd316caf8e0], [(nil)]) called
soa.c:615 soa_get_params() soa_get_params(static::0x6150000b5c00, ...) called
nua_stack.c:301 nua_stack_event() nua(0x6120001d4ac0): event i_state 200 OK
tport.c:2769 tport_wakeup_pri() tport_wakeup_pri(0x6160000f1b80): events IN
tport.c:2900 tport_recv_event() tport_recv_event(0x6160000f1b80)
tport.c:3237 tport_recv_iovec() tport_recv_iovec(0x6160000f1b80) msg 0x6190003e3580 from (udp/172.19.0.2:5080) has 336 bytes, veclen = 1
recv 336 bytes from udp/[172.19.0.2]:5062 at 20:28:50.557608:
------------------------------------------------------------------------
ACK sip:1001@172.19.0.2:5080 SIP/2.0
Via: SIP/2.0/UDP 127.0.0.1:5062;branch=z9hG4bK-18885-1-5
From: sipp <sip:sipp@127.0.0.1:5062>;tag=1
To: sut <sip:1001@172.19.0.2:5080>;tag=D1jH7U8m74e9D
Call-ID: 1-18885@172.19.0.2
CSeq: 1 ACK
Contact: sip:1001@127.0.0.1:5062
Max-Forwards: 70
Subject: Performance Test
Content-Length: 0


tport.c:3055 tport_deliver() tport_deliver(0x6160000f1b80): msg 0x6190003e3580 (336 bytes) from udp/172.19.0.2:5080/sip next=(nil)
nta.c:2957 agent_recv_request() nta: received ACK sip:1001@172.19.0.2:5080 SIP/2.0 (CSeq 1) (load: 1 rps)
nta.c:3254 agent_check_request_via() nta: Via check: received=172.19.0.2
nta.c:3097 agent_recv_request() nta: ACK (1) is going to INVITE (1)
nua_session.c:2566 process_ack_or_cancel() nua: process_ack_or_cancel: entering
soa.c:1213 soa_clear_remote_sdp() soa_clear_remote_sdp(static::0x6150000b5c00) called
nua_stack.c:301 nua_stack_event() nua(0x6120001d4ac0): event i_ack 200 OK
nua_session.c:4131 signal_call_state_change() nua(0x6120001d4ac0): call state changed: completed -> ready
nua_stack.c:301 nua_stack_event() nua(0x6120001d4ac0): event i_state 200 OK
nua_stack.c:301 nua_stack_event() nua(0x6120001d4ac0): event i_active 200 Call active
nua_dialog.c:563 nua_dialog_usage_set_refresh_range() nua(): refresh session after 299 seconds (in [295..305])
nua_stack.c:389 nua_application_event() nua: nua_application_event: entering
nua.c:1170 nua_handle_unref_user() nua nua_handle_unref_user(0x6120001d4ac0): entering
nua_stack.c:558 nua_signal() nua(0x6120001d4ac0): sent signal r_handle_unref
nua.c:1157 nua_unref_user() nua: nua_unref_user: entering
nua_stack.c:558 nua_signal() nua((nil)): sent signal r_unref
nua_stack.c:389 nua_application_event() nua: nua_application_event: entering
nua.c:1170 nua_handle_unref_user() nua nua_handle_unref_user(0x6120001d4ac0): entering
nua_stack.c:558 nua_signal() nua(0x6120001d4ac0): sent signal r_handle_unref
nua.c:1157 nua_unref_user() nua: nua_unref_user: entering
nua_stack.c:558 nua_signal() nua((nil)): sent signal r_unref
nua_stack.c:389 nua_application_event() nua: nua_application_event: entering
nua.c:1170 nua_handle_unref_user() nua nua_handle_unref_user(0x6120001d4ac0): entering
nua_stack.c:558 nua_signal() nua(0x6120001d4ac0): sent signal r_handle_unref
nua.c:1157 nua_unref_user() nua: nua_unref_user: entering
nua_stack.c:558 nua_signal() nua((nil)): sent signal r_unref
nua_stack.c:389 nua_application_event() nua: nua_application_event: entering
nua.c:1170 nua_handle_unref_user() nua nua_handle_unref_user(0x6120001d4ac0): entering
nua_stack.c:558 nua_signal() nua(0x6120001d4ac0): sent signal r_handle_unref
nua.c:1157 nua_unref_user() nua: nua_unref_user: entering
nua_stack.c:558 nua_signal() nua((nil)): sent signal r_unref
nua_stack.c:599 nua_stack_signal() nua(0x6120001d4ac0): recv signal r_handle_unref
nua_stack.c:599 nua_stack_signal() nua((nil)): recv signal r_unref
nua_stack.c:599 nua_stack_signal() nua(0x6120001d4ac0): recv signal r_handle_unref
nua_stack.c:599 nua_stack_signal() nua((nil)): recv signal r_unref
nua_stack.c:599 nua_stack_signal() nua(0x6120001d4ac0): recv signal r_handle_unref
nua_stack.c:599 nua_stack_signal() nua((nil)): recv signal r_unref
nua_stack.c:599 nua_stack_signal() nua(0x6120001d4ac0): recv signal r_handle_unref
nua_stack.c:599 nua_stack_signal() nua((nil)): recv signal r_unref
7b363765-0252-4ec5-a2ef-7f518831b6cf 2023-11-03 20:28:50.561698 76.70% [NOTICE] mod_dptools.c:1406 Channel [sofia/external/1001@127.0.0.1:5062] has been answered
nta.c:1317 agent_timer() nta: timer set next to 248 ms
7b363765-0252-4ec5-a2ef-7f518831b6cf 2023-11-03 20:28:50.584576 76.70% [DEBUG] switch_channel.c:3913 (sofia/external/1001@127.0.0.1:5062) Callstate Change EARLY -> ACTIVE
nua.c:365 nua_handle_magic() nua: nua_handle_magic: entering
7b363765-0252-4ec5-a2ef-7f518831b6cf 2023-11-03 20:28:50.584576 76.70% [DEBUG] sofia.c:7493 Channel sofia/external/1001@127.0.0.1:5062 entering state [completed][200]
nua.c:365 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:1170 nua_handle_unref_user() nua nua_handle_unref_user(0x6120001d4ac0): entering
nua_stack.c:558 nua_signal() nua(0x6120001d4ac0): sent signal r_handle_unref
nua.c:1157 nua_unref_user() nua: nua_unref_user: entering
nua_stack.c:558 nua_signal() nua((nil)): sent signal r_unref
nua.c:365 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:365 nua_handle_magic() nua: nua_handle_magic: entering
nua_stack.c:599 nua_stack_signal() nua(0x6120001d4ac0): recv signal r_handle_unref
nua_stack.c:599 nua_stack_signal() nua((nil)): recv signal r_unref
nua.c:1170 nua_handle_unref_user() nua nua_handle_unref_user(0x6120001d4ac0): entering
nua_stack.c:558 nua_signal() nua(0x6120001d4ac0): sent signal r_handle_unref
nua.c:1157 nua_unref_user() nua: nua_unref_user: entering
nua_stack.c:558 nua_signal() nua((nil)): sent signal r_unref
nua_stack.c:599 nua_stack_signal() nua(0x6120001d4ac0): recv signal r_handle_unref
nua.c:365 nua_handle_magic() nua: nua_handle_magic: entering
nua_stack.c:599 nua_stack_signal() nua((nil)): recv signal r_unref
7b363765-0252-4ec5-a2ef-7f518831b6cf 2023-11-03 20:28:50.584576 76.70% [DEBUG] sofia.c:7493 Channel sofia/external/1001@127.0.0.1:5062 entering state [ready][200]
nua.c:365 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:1170 nua_handle_unref_user() nua nua_handle_unref_user(0x6120001d4ac0): entering
nua_stack.c:558 nua_signal() nua(0x6120001d4ac0): sent signal r_handle_unref
nua.c:1157 nua_unref_user() nua: nua_unref_user: entering
nua_stack.c:558 nua_signal() nua((nil)): sent signal r_unref
nua.c:365 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:365 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:1170 nua_handle_unref_user() nua nua_handle_unref_user(0x6120001d4ac0): entering
nua_stack.c:558 nua_signal() nua(0x6120001d4ac0): sent signal r_handle_unref
nua.c:1157 nua_unref_user() nua: nua_unref_user: entering
nua_stack.c:558 nua_signal() nua((nil)): sent signal r_unref
nua_stack.c:599 nua_stack_signal() nua(0x6120001d4ac0): recv signal r_handle_unref
nua_stack.c:599 nua_stack_signal() nua((nil)): recv signal r_unref
nua_stack.c:599 nua_stack_signal() nua(0x6120001d4ac0): recv signal r_handle_unref
nua_stack.c:599 nua_stack_signal() nua((nil)): recv signal r_unref
7b363765-0252-4ec5-a2ef-7f518831b6cf EXECUTE [depth=0] sofia/external/1001@127.0.0.1:5062 voicemail(default  1001)
7b363765-0252-4ec5-a2ef-7f518831b6cf 2023-11-03 20:28:50.744575 76.70% [DEBUG] switch_ivr_play_say.c:70 No language specified - Using [en]
7b363765-0252-4ec5-a2ef-7f518831b6cf 2023-11-03 20:28:50.820868 76.70% [DEBUG] switch_ivr_play_say.c:251 Handle play-file:[voicemail/vm-person.wav] (en:en)
7b363765-0252-4ec5-a2ef-7f518831b6cf 2023-11-03 20:28:50.820868 76.70% [DEBUG] switch_ivr_play_say.c:263 Setting playback volume to 0
7b363765-0252-4ec5-a2ef-7f518831b6cf 2023-11-03 20:28:50.820868 76.70% [DEBUG] switch_ivr_play_say.c:1562 Codec Activated L16@8000hz 1 channels 20ms
nta.c:7223 _nta_incoming_timer() nta: timer I fired, terminate 200 response
nta.c:5904 incoming_reclaim_queued() incoming_reclaim_all((nil), (nil), 0x7fd316caf9d0)
nta.c:7270 _nta_incoming_timer() nta_incoming_timer: 0/0 resent, 0/0 tout, 1/6 term, 1/6 free
nta.c:1317 agent_timer() nta: timer set next to 1820 ms
nua.c:138 nua_create() nua: nua_create: entering
su_epoll_port.c:540 su_epoll_port_create() su_port_create(0x6110001eff40): epoll_create() => 0: OK
su_socket_port.c:87 su_socket_port_init() su_socket_port_init(0x6110001eff40, 0x7fd315f49dc0) called
su_pthread_port.c:72 su_pthread_port_init() su_pthread_port_init(0x6110001eff40, 0x7fd315f49dc0) called
nua_stack.c:128 nua_stack_init() nua: nua_stack_init: entering
nua_params.c:484 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:228 soa_create() soa_create("default", 0x6060000b000=================================================================
==17515==ERROR: AddressSanitizer: attempting free on address which was not malloc()-ed: 0x6030001efd78 in thread T28
18886
    #0 0x7fd31d750b6f in __interceptor_free ../../../../src/libsanitizer/asan/asan_malloc_linux.cpp:123
    #1 0x7fd31ccf1154 in switch_perform_substitution src/switch_regex.c:213
    #2 0x7fd31cdad53f in switch_ivr_phrase_macro_event src/switch_ivr_play_say.c:233
    #3 0x7fd30d3718b5 in voicemail_leave_main /drone/src/src/mod/applications/mod_voicemail/mod_voicemail.c:3546
    #4 0x7fd30d373131 in voicemail_function /drone/src/src/mod/applications/mod_voicemail/mod_voicemail.c:3793
    #5 0x7fd31cbbc29c in switch_core_session_exec src/switch_core_session.c:2965
    #6 0x7fd31cbbd2da in switch_core_session_execute_application_get_flags src/switch_core_session.c:2825
    #7 0x7fd31cbc5049 in switch_core_standard_on_execute src/switch_core_state_machine.c:350
    #8 0x7fd31cbc5049 in switch_core_session_run src/switch_core_state_machine.c:647
    #9 0x7fd31cbb69f0 in switch_core_session_thread src/switch_core_session.c:1727
    #10 0x7fd31cbab202 in switch_core_session_thread_pool_worker src/switch_core_session.c:1791
    #11 0x7fd31d40b896 in dummy_worker threadproc/unix/thread.c:151
    #12 0x7fd31d68cea6 in start_thread nptl/pthread_create.c:477
    #13 0x7fd31c927a2e in __clone (/lib/x86_64-linux-gnu/libc.so.6+0xfca2e)

0x6030001efd78 is located 24 bytes inside of 32-byte region [0x6030001efd60,0x6030001efd80)
allocated by thread T28 here:
    #0 0x7fd31d750e8f in __interceptor_malloc ../../../../src/libsanitizer/asan/asan_malloc_linux.cpp:145
    #1 0x7fd31c3b4eae  (/usr/lib/x86_64-linux-gnu/libpcre2-8.so.0+0x10eae)
    #2 0x7fd31c40fb48 in pcre2_substring_get_bynumber_8 (/usr/lib/x86_64-linux-gnu/libpcre2-8.so.0+0x6bb48)
    #3 0x7fd31ccf0fde in switch_perform_substitution src/switch_regex.c:197
    #4 0x7fd31cdad53f in switch_ivr_phrase_macro_event src/switch_ivr_play_say.c:233
    #5 0x7fd30d3718b5 in voicemail_leave_main /drone/src/src/mod/applications/mod_voicemail/mod_voicemail.c:3546
    #6 0x7fd30d373131 in voicemail_function /drone/src/src/mod/applications/mod_voicemail/mod_voicemail.c:3793
    #7 0x7fd31cbbc29c in switch_core_session_exec src/switch_core_session.c:2965
    #8 0x7fd31cbbd2da in switch_core_session_execute_application_get_flags src/switch_core_session.c:2825
    #9 0x7fd31cbc5049 in switch_core_standard_on_execute src/switch_core_state_machine.c:350
    #10 0x7fd31cbc5049 in switch_core_session_run src/switch_core_state_machine.c:647
    #11 0x7fd31cbb69f0 in switch_core_session_thread src/switch_core_session.c:1727
    #12 0x7fd31cbab202 in switch_core_session_thread_pool_worker src/switch_core_session.c:1791
    #13 0x7fd31d40b896 in dummy_worker threadproc/unix/thread.c:151
    #14 0x7fd31d68cea6 in start_thread nptl/pthread_create.c:477
    #15 0x7fd31c927a2e in __clone (/lib/x86_64-linux-gnu/libc.so.6+0xfca2e)

Thread T28 created by T10 here:
    #0 0x7fd31d6fc2a2 in __interceptor_pthread_create ../../../../src/libsanitizer/asan/asan_interceptors.cpp:214
    #1 0x7fd31d40bec5 in fspr_thread_create threadproc/unix/thread.c:194
    #2 0x7fd31cbba6d8 in check_queue src/switch_core_session.c:1875
    #3 0x7fd31cbba93f in switch_core_session_thread_pool_launch src/switch_core_session.c:1935
    #4 0x7fd31cbbac57 in switch_core_session_thread_launch src/switch_core_session.c:1955
    #5 0x7fd315d3fff2 in sofia_event_callback /drone/src/src/mod/endpoints/mod_sofia/sofia.c:2605
    #6 0x7fd315dfafd7 in nua_application_event (/usr/local/freeswitch/mod/mod_sofia.so+0x20cfd7)
    #7 0x7fd315e9a9e2 in su_base_port_execute_msgs (/usr/local/freeswitch/mod/mod_sofia.so+0x2ac9e2)
    #8 0x7fd315e9a76c in su_base_port_getmsgs (/usr/local/freeswitch/mod/mod_sofia.so+0x2ac76c)
    #9 0x7fd315e9ad24 in su_base_port_step (/usr/local/freeswitch/mod/mod_sofia.so+0x2acd24)
    #10 0x7fd315e33abf in su_port_step (/usr/local/freeswitch/mod/mod_sofia.so+0x245abf)
    #11 0x7fd315e34c06 in su_root_step (/usr/local/freeswitch/mod/mod_sofia.so+0x246c06)
    #12 0x7fd315d0f0e4 in sofia_profile_thread_run /drone/src/src/mod/endpoints/mod_sofia/sofia.c:3471
    #13 0x7fd31d40b896 in dummy_worker threadproc/unix/thread.c:151
    #14 0x7fd31d68cea6 in start_thread nptl/pthread_create.c:477

Thread T10 created by T0 here:
    #0 0x7fd31d6fc2a2 in __interceptor_pthread_create ../../../../src/libsanitizer/asan/asan_interceptors.cpp:214
    #1 0x7fd31d40bec5 in fspr_thread_create threadproc/unix/thread.c:194
    #2 0x7fd315cfa2ef in launch_sofia_profile_thread /drone/src/src/mod/endpoints/mod_sofia/sofia.c:3629
    #3 0x7fd315cfd4e5 in config_sofia /drone/src/src/mod/endpoints/mod_sofia/sofia.c:6345
    #4 0x7fd315cdc53f in mod_sofia_load /drone/src/src/mod/endpoints/mod_sofia/mod_sofia.c:6673
    #5 0x7fd31ccb86d9 in switch_loadable_module_load_file src/switch_loadable_module.c:1720
    #6 0x7fd31ccb86d9 in switch_loadable_module_load_module_ex src/switch_loadable_module.c:1827
    #7 0x7fd31ccbf45f in switch_loadable_module_init src/switch_loadable_module.c:2245
    #8 0x7fd31cbe0c20 in switch_core_init_and_modload src/switch_core.c:2470
    #9 0x55b7aa307f52 in fst_init_core_and_modload ../../../../src/include/test/switch_test.h:123
    #10 0x55b7aa307f52 in main test/sipp-based-tests.c:219
    #11 0x7fd31c84ed09 in __libc_start_main ../csu/libc-start.c:308

SUMMARY: AddressSanitizer: bad-free ../../../../src/libsanitizer/asan/asan_malloc_linux.cpp:123 in __interceptor_free
==17515==ABORTING
AddressSanitizer:DEADLYSIGNAL