[OpenSIPS-Users] Segfault in 3.2.2 (inc nightly) but not 3.2 in mid_registrar

Tue Sep 28 09:04:05 EST 2021

Hi,

Since testing 3.2.2 we've noticed a segfault affecting registrations
pretty regularly through mid_registrar.

The issue occurs intermittently, but seemingly when the contact
doesn't exist and needs to be created. We are currently using
in-memory mid_registrar without DB backing to test; although we have
previously had DB backing.

We can "more commonly" trigger this with Zoiper as the client; but we
can't see any specific reason. Have checked the github issues and
can't see any particular reason why this would be happening in 3.2.2
but not 3.2.0.

Host OS is Ubuntu 20.04.

We're seeing the following trace from the info log.

Sep 28 18:50:55 hvprxy-dev osips[1134252]: DBG:core:parse_headers:
flags=ffffffffffffffff
Sep 28 18:50:55 hvprxy-dev osips[1134252]: DBG:core:parse_params:
Parsing params for:[expires=3599]
Sep 28 18:50:55 hvprxy-dev osips[1134252]:
DBG:mid_registrar:save_restore_req_contacts: saving + restoring all
contact URIs ...
Sep 28 18:50:55 hvprxy-dev osips[1134252]:
DBG:mid_registrar:calc_contact_expires: expires: 3599
Sep 28 18:50:55 hvprxy-dev osips[1134252]: DBG:core:evi_param_set: set
str domain='location'
Sep 28 18:50:55 hvprxy-dev osips[1134252]: DBG:core:evi_param_set: set
str aor='1000'
Sep 28 18:50:55 hvprxy-dev osips[1134252]: DBG:core:get_dummy_sip_msg:
reusing the static sip msg 0x7f343336a7c8
Sep 28 18:50:55 hvprxy-dev osips[1134252]:
DBG:core:release_dummy_sip_msg: cleaning the static sip msg
0x7f343336a7c8
Sep 28 18:50:55 hvprxy-dev osips[1134252]: DBG:core:destroy_avp_list:
destroying list (nil)
Sep 28 18:50:55 hvprxy-dev osips[1134252]:
DBG:usrloc:run_ul_callbacks: contact=0x7f3431eb4598, callback type
16/208, id 1 entered
Sep 28 18:50:55 hvprxy-dev osips[1134252]:
DBG:mid_registrar:mid_reg_aor_event: AOR callback (16): contact='1000'
Sep 28 18:50:55 hvprxy-dev osips[1134252]:
DBG:mid_registrar:save_restore_req_contacts: INSERTING contact with
expires 1632819655
Sep 28 18:50:55 hvprxy-dev osips[1134252]: DBG:core:evi_param_set: set
str domain='location'
Sep 28 18:50:55 hvprxy-dev osips[1134252]: DBG:core:evi_param_set: set
str aor='1000'
Sep 28 18:50:55 hvprxy-dev osips[1134252]: DBG:core:evi_param_set: set
str uri='sip:1000 at 1.1.1.1:53149;rinstance=718be353c21105be;transport=tls'
Sep 28 18:50:55 hvprxy-dev osips[1134252]: DBG:core:evi_param_set: set
str received=''
Sep 28 18:50:55 hvprxy-dev osips[1134252]: DBG:core:evi_param_set: set
str path=''
Sep 28 18:50:55 hvprxy-dev osips[1134252]: DBG:core:evi_param_set: set
int qval=-1
Sep 28 18:50:55 hvprxy-dev osips[1134252]: DBG:core:evi_param_set: set
str user_agent='Z 5.5.5 v2.10.15.2'
Sep 28 18:50:55 hvprxy-dev osips[1134252]: DBG:core:evi_param_set: set
str socket='tls:2.2.2.2:5061'
Sep 28 18:50:55 hvprxy-dev osips[1134252]: DBG:core:evi_param_set: set
int bflags=14
Sep 28 18:50:55 hvprxy-dev osips[1134252]: DBG:core:evi_param_set: set
int expires=1632819655
Sep 28 18:50:55 hvprxy-dev osips[1134252]: DBG:core:evi_param_set: set
str callid='c77MPaFAE7pAVYD5R-s1-w..'
Sep 28 18:50:55 hvprxy-dev osips[1134252]: DBG:core:evi_param_set: set
int cseq=2
Sep 28 18:50:55 hvprxy-dev osips[1134252]: DBG:core:evi_param_set: set
str attr=''
Sep 28 18:50:55 hvprxy-dev osips[1134252]: DBG:core:evi_param_set: set
int latency=0
Sep 28 18:50:55 hvprxy-dev osips[1134252]: DBG:core:evi_param_set: set
str shtag=''
Sep 28 18:50:55 hvprxy-dev osips[1134252]: DBG:core:get_dummy_sip_msg:
reusing the static sip msg 0x7f343336a7c8
Sep 28 18:50:55 hvprxy-dev osips[1134252]:
DBG:core:release_dummy_sip_msg: cleaning the static sip msg
0x7f343336a7c8
Sep 28 18:50:55 hvprxy-dev osips[1134252]: DBG:core:destroy_avp_list:
destroying list (nil)
Sep 28 18:50:55 hvprxy-dev osips[1134252]: CRITICAL:core:sig_usr:
segfault in process pid: 1134252, id: 4
Sep 28 18:50:55 hvprxy-dev osips[1134252]:
DBG:core:restore_segv_handler: restoring SIGSEGV handler...

BT says:

Core was generated by `/usr/sbin/opensips -P
/run/opensips/opensips.pid -f /etc/opensips/opensips.cfg'.
Program terminated with signal SIGSEGV, Segmentation fault.
#0  __memmove_avx_unaligned_erms () at
../sysdeps/x86_64/multiarch/memmove-vec-unaligned-erms.S:287
287 ../sysdeps/x86_64/multiarch/memmove-vec-unaligned-erms.S: No such
file or directory.
(gdb) bt
#0  __memmove_avx_unaligned_erms () at
../sysdeps/x86_64/multiarch/memmove-vec-unaligned-erms.S:287
#1  0x00007fcd40357065 in memcpy (__len=<optimized out>,
__src=<optimized out>, __dest=<optimized out>) at
/usr/include/x86_64-linux-gnu/bits/string_fortified.h:34
#2  kv_put (_store=<optimized out>, _key=<optimized out>,
_val=0x7fff9752f750) at kv_store.c:87
#3  0x00007fcd3dfc11e5 in store_ucontact_data (c=0x7fcd4434f458,
mri=0x7fcd4585fb80 <main_arena>, ct_uri=0x6152d9d6, expires=<optimized
out>, expires_out=21925, last_reg_ts=94, last_cseq=0) at
ul_storage.c:201
#4  0x00007fcd3dfc7349 in mid_reg_store_ct_data (c=<optimized out>,
info=<optimized out>) at save.c:243
#5  0x00007fcd4034adf1 in insert_ucontact (_r=0x7fcd43b2f768,
_contact=0x7fcd44020a48, _ci=0x7fcd3dff4060 <ci>,
match=0x7fcd44352e30, skip_replication=<optimized out>,
_c=0x7fff9752f8e0) at urecord.c:876
#6  0x00007fcd3dfd34ef in save_restore_req_contacts
(req=0x7fcd444ed840, rpl=0x7fcd454b3c30, mri=0x7fcd44352d78,
_a=0x7fcd44352e10) at save.c:1664
#7  0x00007fcd3dfd4d01 in mid_reg_resp_in (_=<optimized out>,
__=<optimized out>, params=<optimized out>) at save.c:1846
#8  0x00007fcd404290b8 in run_trans_callbacks (type=type at entry=2,
trans=trans at entry=0x7fcd43b498e0, req=<optimized out>,
rpl=rpl at entry=0x7fcd454b3c30, code=<optimized out>) at t_hooks.c:209
#9  0x00007fcd403f73ac in reply_received (p_msg=0x7fcd454b3c30) at
t_reply.c:1577
#10 0x000055a538587897 in forward_reply (msg=msg at entry=0x7fcd454b3c30)
at forward.c:499
#11 0x000055a5385684df in receive_msg (buf=0x55a5388d7780 <buf>
"SIP/2.0 200 OK\r\nv: SIP/2.0/UDP
hvpd.realworld.net.au:5060;rport=5060;received=114.141.98.59;branch=z9hG4bKd0f6.429855a2.0;i=4b070475\r\nv:
SIP/2.0/TLS 10.10.10.29:11968;rport=21056;received=114.141.104."...,
len=<optimized out>, rcv_info=rcv_info at entry=0x7fff9752ffc0,
    existing_context=existing_context at entry=0x0,
msg_flags=msg_flags at entry=0) at receive.c:266
#12 0x000055a5386d1d28 in udp_read_req (si=<optimized out>,
bytes_read=<optimized out>) at net/proto_udp/proto_udp.c:186
#13 0x000055a5386aaec0 in handle_io (idx=<optimized out>,
event_type=<optimized out>, fm=<optimized out>) at net/net_udp.c:272
#14 io_wait_loop_epoll (repeat=0, t=1, h=<optimized out>) at
net/../io_wait_loop.h:308
#15 0x000055a5386b0255 in udp_start_processes (chd_rank=<optimized
out>, startup_done=<optimized out>) at net/net_udp.c:497
#16 0x000055a538539553 in main_loop () at main.c:227
#17 main (argc=<optimized out>, argv=<optimized out>) at main.c:916

Andrew