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

Tue Sep 28 11:00:28 EST 2021

Just further to this, I'm pretty sure this is a regression introduced in
https://github.com/OpenSIPS/opensips/commit/c11f92698c6f345d8921d645177f71aa36c9791d
.

On Tue, 28 Sept 2021 at 19:04, Andrew Yager <andrew at rwts.com.au> wrote:

> 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
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.opensips.org/pipermail/users/attachments/20210928/2400ec42/attachment-0001.html>