<div dir="ltr"><div dir="ltr"><div>Just further to this, I'm pretty sure this is a regression introduced in <a href="https://github.com/OpenSIPS/opensips/commit/c11f92698c6f345d8921d645177f71aa36c9791d">https://github.com/OpenSIPS/opensips/commit/c11f92698c6f345d8921d645177f71aa36c9791d</a>.</div></div><br><div class="gmail_quote"><div dir="ltr" class="gmail_attr">On Tue, 28 Sept 2021 at 19:04, Andrew Yager <<a href="mailto:andrew@rwts.com.au">andrew@rwts.com.au</a>> wrote:<br></div><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex">Hi,<br>
<br>
Since testing 3.2.2 we've noticed a segfault affecting registrations<br>
pretty regularly through mid_registrar.<br>
<br>
The issue occurs intermittently, but seemingly when the contact<br>
doesn't exist and needs to be created. We are currently using<br>
in-memory mid_registrar without DB backing to test; although we have<br>
previously had DB backing.<br>
<br>
We can "more commonly" trigger this with Zoiper as the client; but we<br>
can't see any specific reason. Have checked the github issues and<br>
can't see any particular reason why this would be happening in 3.2.2<br>
but not 3.2.0.<br>
<br>
Host OS is Ubuntu 20.04.<br>
<br>
We're seeing the following trace from the info log.<br>
<br>
Sep 28 18:50:55 hvprxy-dev osips[1134252]: DBG:core:parse_headers:<br>
flags=ffffffffffffffff<br>
Sep 28 18:50:55 hvprxy-dev osips[1134252]: DBG:core:parse_params:<br>
Parsing params for:[expires=3599]<br>
Sep 28 18:50:55 hvprxy-dev osips[1134252]:<br>
DBG:mid_registrar:save_restore_req_contacts: saving + restoring all<br>
contact URIs ...<br>
Sep 28 18:50:55 hvprxy-dev osips[1134252]:<br>
DBG:mid_registrar:calc_contact_expires: expires: 3599<br>
Sep 28 18:50:55 hvprxy-dev osips[1134252]: DBG:core:evi_param_set: set<br>
str domain='location'<br>
Sep 28 18:50:55 hvprxy-dev osips[1134252]: DBG:core:evi_param_set: set<br>
str aor='1000'<br>
Sep 28 18:50:55 hvprxy-dev osips[1134252]: DBG:core:get_dummy_sip_msg:<br>
reusing the static sip msg 0x7f343336a7c8<br>
Sep 28 18:50:55 hvprxy-dev osips[1134252]:<br>
DBG:core:release_dummy_sip_msg: cleaning the static sip msg<br>
0x7f343336a7c8<br>
Sep 28 18:50:55 hvprxy-dev osips[1134252]: DBG:core:destroy_avp_list:<br>
destroying list (nil)<br>
Sep 28 18:50:55 hvprxy-dev osips[1134252]:<br>
DBG:usrloc:run_ul_callbacks: contact=0x7f3431eb4598, callback type<br>
16/208, id 1 entered<br>
Sep 28 18:50:55 hvprxy-dev osips[1134252]:<br>
DBG:mid_registrar:mid_reg_aor_event: AOR callback (16): contact='1000'<br>
Sep 28 18:50:55 hvprxy-dev osips[1134252]:<br>
DBG:mid_registrar:save_restore_req_contacts: INSERTING contact with<br>
expires 1632819655<br>
Sep 28 18:50:55 hvprxy-dev osips[1134252]: DBG:core:evi_param_set: set<br>
str domain='location'<br>
Sep 28 18:50:55 hvprxy-dev osips[1134252]: DBG:core:evi_param_set: set<br>
str aor='1000'<br>
Sep 28 18:50:55 hvprxy-dev osips[1134252]: DBG:core:evi_param_set: set<br>
str uri='<a href="http://sip:1000@1.1.1.1:53149" target="_blank">sip:1000@1.1.1.1:53149</a>;rinstance=718be353c21105be;transport=tls'<br>
Sep 28 18:50:55 hvprxy-dev osips[1134252]: DBG:core:evi_param_set: set<br>
str received=''<br>
Sep 28 18:50:55 hvprxy-dev osips[1134252]: DBG:core:evi_param_set: set<br>
str path=''<br>
Sep 28 18:50:55 hvprxy-dev osips[1134252]: DBG:core:evi_param_set: set<br>
int qval=-1<br>
Sep 28 18:50:55 hvprxy-dev osips[1134252]: DBG:core:evi_param_set: set<br>
str user_agent='Z 5.5.5 v2.10.15.2'<br>
Sep 28 18:50:55 hvprxy-dev osips[1134252]: DBG:core:evi_param_set: set<br>
str socket='tls:<a href="http://2.2.2.2:5061" rel="noreferrer" target="_blank">2.2.2.2:5061</a>'<br>
Sep 28 18:50:55 hvprxy-dev osips[1134252]: DBG:core:evi_param_set: set<br>
int bflags=14<br>
Sep 28 18:50:55 hvprxy-dev osips[1134252]: DBG:core:evi_param_set: set<br>
int expires=1632819655<br>
Sep 28 18:50:55 hvprxy-dev osips[1134252]: DBG:core:evi_param_set: set<br>
str callid='c77MPaFAE7pAVYD5R-s1-w..'<br>
Sep 28 18:50:55 hvprxy-dev osips[1134252]: DBG:core:evi_param_set: set<br>
int cseq=2<br>
Sep 28 18:50:55 hvprxy-dev osips[1134252]: DBG:core:evi_param_set: set<br>
str attr=''<br>
Sep 28 18:50:55 hvprxy-dev osips[1134252]: DBG:core:evi_param_set: set<br>
int latency=0<br>
Sep 28 18:50:55 hvprxy-dev osips[1134252]: DBG:core:evi_param_set: set<br>
str shtag=''<br>
Sep 28 18:50:55 hvprxy-dev osips[1134252]: DBG:core:get_dummy_sip_msg:<br>
reusing the static sip msg 0x7f343336a7c8<br>
Sep 28 18:50:55 hvprxy-dev osips[1134252]:<br>
DBG:core:release_dummy_sip_msg: cleaning the static sip msg<br>
0x7f343336a7c8<br>
Sep 28 18:50:55 hvprxy-dev osips[1134252]: DBG:core:destroy_avp_list:<br>
destroying list (nil)<br>
Sep 28 18:50:55 hvprxy-dev osips[1134252]: CRITICAL:core:sig_usr:<br>
segfault in process pid: 1134252, id: 4<br>
Sep 28 18:50:55 hvprxy-dev osips[1134252]:<br>
DBG:core:restore_segv_handler: restoring SIGSEGV handler...<br>
<br>
BT says:<br>
<br>
Core was generated by `/usr/sbin/opensips -P<br>
/run/opensips/opensips.pid -f /etc/opensips/opensips.cfg'.<br>
Program terminated with signal SIGSEGV, Segmentation fault.<br>
#0 __memmove_avx_unaligned_erms () at<br>
../sysdeps/x86_64/multiarch/memmove-vec-unaligned-erms.S:287<br>
287 ../sysdeps/x86_64/multiarch/memmove-vec-unaligned-erms.S: No such<br>
file or directory.<br>
(gdb) bt<br>
#0 __memmove_avx_unaligned_erms () at<br>
../sysdeps/x86_64/multiarch/memmove-vec-unaligned-erms.S:287<br>
#1 0x00007fcd40357065 in memcpy (__len=<optimized out>,<br>
__src=<optimized out>, __dest=<optimized out>) at<br>
/usr/include/x86_64-linux-gnu/bits/string_fortified.h:34<br>
#2 kv_put (_store=<optimized out>, _key=<optimized out>,<br>
_val=0x7fff9752f750) at kv_store.c:87<br>
#3 0x00007fcd3dfc11e5 in store_ucontact_data (c=0x7fcd4434f458,<br>
mri=0x7fcd4585fb80 <main_arena>, ct_uri=0x6152d9d6, expires=<optimized<br>
out>, expires_out=21925, last_reg_ts=94, last_cseq=0) at<br>
ul_storage.c:201<br>
#4 0x00007fcd3dfc7349 in mid_reg_store_ct_data (c=<optimized out>,<br>
info=<optimized out>) at save.c:243<br>
#5 0x00007fcd4034adf1 in insert_ucontact (_r=0x7fcd43b2f768,<br>
_contact=0x7fcd44020a48, _ci=0x7fcd3dff4060 <ci>,<br>
match=0x7fcd44352e30, skip_replication=<optimized out>,<br>
_c=0x7fff9752f8e0) at urecord.c:876<br>
#6 0x00007fcd3dfd34ef in save_restore_req_contacts<br>
(req=0x7fcd444ed840, rpl=0x7fcd454b3c30, mri=0x7fcd44352d78,<br>
_a=0x7fcd44352e10) at save.c:1664<br>
#7 0x00007fcd3dfd4d01 in mid_reg_resp_in (_=<optimized out>,<br>
__=<optimized out>, params=<optimized out>) at save.c:1846<br>
#8 0x00007fcd404290b8 in run_trans_callbacks (type=type@entry=2,<br>
trans=trans@entry=0x7fcd43b498e0, req=<optimized out>,<br>
rpl=rpl@entry=0x7fcd454b3c30, code=<optimized out>) at t_hooks.c:209<br>
#9 0x00007fcd403f73ac in reply_received (p_msg=0x7fcd454b3c30) at<br>
t_reply.c:1577<br>
#10 0x000055a538587897 in forward_reply (msg=msg@entry=0x7fcd454b3c30)<br>
at forward.c:499<br>
#11 0x000055a5385684df in receive_msg (buf=0x55a5388d7780 <buf><br>
"SIP/2.0 200 OK\r\nv: SIP/2.0/UDP<br>
<a href="http://hvpd.realworld.net.au:5060" target="_blank">hvpd.realworld.net.au:5060</a>;rport=5060;received=114.141.98.59;branch=z9hG4bKd0f6.429855a2.0;i=4b070475\r\nv:<br>
SIP/2.0/TLS 10.10.10.29:11968;rport=21056;received=114.141.104."...,<br>
len=<optimized out>, rcv_info=rcv_info@entry=0x7fff9752ffc0,<br>
existing_context=existing_context@entry=0x0,<br>
msg_flags=msg_flags@entry=0) at receive.c:266<br>
#12 0x000055a5386d1d28 in udp_read_req (si=<optimized out>,<br>
bytes_read=<optimized out>) at net/proto_udp/proto_udp.c:186<br>
#13 0x000055a5386aaec0 in handle_io (idx=<optimized out>,<br>
event_type=<optimized out>, fm=<optimized out>) at net/net_udp.c:272<br>
#14 io_wait_loop_epoll (repeat=0, t=1, h=<optimized out>) at<br>
net/../io_wait_loop.h:308<br>
#15 0x000055a5386b0255 in udp_start_processes (chd_rank=<optimized<br>
out>, startup_done=<optimized out>) at net/net_udp.c:497<br>
#16 0x000055a538539553 in main_loop () at main.c:227<br>
#17 main (argc=<optimized out>, argv=<optimized out>) at main.c:916<br>
<br>
Andrew<br>
</blockquote></div></div>