Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

[CRASH] Crash from double free in private memory #1974

Closed
danpascu opened this issue Feb 17, 2020 · 1 comment
Closed

[CRASH] Crash from double free in private memory #1974

danpascu opened this issue Feb 17, 2020 · 1 comment
Assignees
@danpascu
Labels
bug

Comments

@danpascu
Copy link
Member

OpenSIPS version you are running

version: opensips 3.1.0-dev (x86_64/linux)
flags: STATS: On, DISABLE_NAGLE, USE_MCAST, SHM_MMAP, Q_MALLOC, F_MALLOC, HP_MALLOC, DBG_MALLOC, CC_O0, FAST_LOCK-ADAPTIVE_WAIT, DBG_LOCK
ADAPTIVE_WAIT_LOOPS=1024, MAX_RECV_BUFFER_SIZE 262144, MAX_LISTEN 16, MAX_URI_SIZE 1024, BUF_SIZE 65535
poll method support: poll, epoll, sigio_rt, select.
git revision: 98cfd9243
main.c compiled on  with gcc 9

Crash Core Dump

Core was generated by `./opensips -f o.cfg -w /run/opensips -P opensips.pid -a Q_MALLOC_DBG -m 512 -u'.
Program terminated with signal SIGABRT, Aborted.
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
#1  0x00007f5546dfd535 in __GI_abort () at abort.c:79
#2  0x00007f5546e53ca8 in __libc_message (action=action@entry=do_abort, fmt=fmt@entry=0x7f5546f5ea79 "%s\n") at ../sysdeps/posix/libc_fatal.c:181
#3  0x00007f5546e5a20a in malloc_printerr (str=str@entry=0x7f5546f607c8 "double free or corruption (out)") at malloc.c:5366
#4  0x00007f5546e5bf90 in _int_free (av=0x7f5546f91c40 <main_arena>, p=0x7f55287528a0, have_lock=<optimized out>) at malloc.c:4326
#5  0x000055cf33089e3a in sys_free (p=0x7f55287528b0, file=0x7f5526295314 "t_msgbuilder.h", function=0x7f5526296ce8 <__FUNCTION__.11545> "free_faked_req", line=355) at mem/mem.c:365
#6  0x00007f552624c9b1 in free_faked_req (faked_req=0x7f55262b4380 <faked_req>, t=0x7f55288b2cb0) at t_msgbuilder.h:355
#7  0x00007f552624efae in do_dns_failover (t=0x7f55288b2cb0) at t_reply.c:718
#8  0x00007f552624f9dd in t_should_relay_response (Trans=0x7f55288b2cb0, new_code=408, branch=0, should_store=0x7fffdc6f43cc, should_relay=0x7fffdc6f43d0, cancel_bitmap=0x7fffdc6f4430, reply=0xffffffffffffffff) at t_reply.c:972
#9  0x00007f55262512ba in local_reply (t=0x7f55288b2cb0, p_msg=0xffffffffffffffff, branch=0, msg_status=408, cancel_bitmap=0x7fffdc6f4430) at t_reply.c:1427
#10 0x00007f552628af41 in fake_reply (t=0x7f55288b2cb0, branch=0, code=408) at timer.c:251
#11 0x00007f552628b65e in final_response_handler (fr_tl=0x7f55288b2f00) at timer.c:404
#12 0x00007f552628d50d in timer_routine (ticks=56579, set=0x0) at timer.c:1088
#13 0x000055cf33046156 in handle_timer_job () at timer.c:868
#14 0x000055cf3312619d in handle_io (fm=0x7f55239bf090, idx=3, event_type=1) at net/net_udp.c:276
#15 0x000055cf3312490d in io_wait_loop_epoll (h=0x55cf3333ec60 <_worker_io>, t=1, repeat=0) at net/../io_wait_loop.h:305
#16 0x000055cf33127377 in udp_start_processes (chd_rank=0x55cf33307b5c <chd_rank>, startup_done=0x0) at net/net_udp.c:497
#17 0x000055cf33068c07 in main_loop () at main.c:798
#18 0x000055cf3306bfd7 in main (argc=15, argv=0x7fffdc6f4838) at main.c:1483

Here is the full backtrace: bt-full.txt

Describe the traffic that generated the bug

It was processing some auto-generated SUBSCRIBE from RLS. It tried to send it to the destination (remote server) and it had a failure to send, which triggered a DNS based failover and then it crashed with a double free for a faked_req.

To Reproduce

Don't know. I was running opensips version 0e2e434 for more than a month without any issues, then I upgraded to 9a7a2f6 late last week and got 3 different crashes (one I pushed a fix for in 98cfd92, one is described here #1973 and this one) within 24 hours.

Relevant System Logs

Feb 15 09:13:33 node15 ./opensips[3654]: INFO:core:probe_max_sock_buff: using snd buffer of 416 kb
Feb 15 09:13:33 node15 ./opensips[3654]: INFO:core:init_sock_keepalive: TCP keepalive enabled on socket 245
Feb 15 09:13:33 node15 ./opensips[3654]: ERROR:core:tcp_connect_blocking_timeout: connect timed out, 199249 us elapsed out of 200000 us
Feb 15 09:13:33 node15 ./opensips[3654]: ERROR:proto_tls:tls_sync_connect: tcp_blocking_connect failed
Feb 15 09:13:33 node15 ./opensips[3654]: ERROR:proto_tls:proto_tls_send: connect failed
Feb 15 09:13:33 node15 ./opensips[3654]: ERROR:tm:msg_send: send() to 85.17.186.7:443 for proto tls/3 failed
Feb 15 09:13:33 node15 ./opensips[3654]: ERROR:tm:t_forward_nonack: sending request failed
Feb 15 09:13:33 node15 ./opensips[3649]: WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 100 ms ago (now 56579940 ms), delaying execution
Feb 15 09:13:33 node15 ./opensips[3649]: WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 240 ms ago (now 56580080 ms), delaying execution
Feb 15 09:13:33 node15 ./opensips[3649]: WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 300 ms ago (now 56580140 ms), delaying execution
Feb 15 09:13:33 node15 ./opensips[3649]: WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 390 ms ago (now 56580230 ms), delaying execution
Feb 15 09:13:34 node15 ./opensips[3649]: WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 490 ms ago (now 56580330 ms), delaying execution
Feb 15 09:13:34 node15 ./opensips[3649]: WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 590 ms ago (now 56580430 ms), delaying execution
Feb 15 09:13:34 node15 ./opensips[3649]: WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 690 ms ago (now 56580530 ms), delaying execution
Feb 15 09:13:34 node15 ./opensips[3649]: WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 790 ms ago (now 56580630 ms), delaying execution
Feb 15 09:13:34 node15 ./opensips[3649]: WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 890 ms ago (now 56580730 ms), delaying execution
Feb 15 09:13:34 node15 ./opensips[3649]: WARNING:core:timer_ticker: timer task <tm-timer> already scheduled 990 ms ago (now 56580730 ms), delaying execution
Feb 15 09:13:34 node15 ./opensips[3649]: WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 990 ms ago (now 56580830 ms), delaying execution
Feb 15 09:13:34 node15 ./opensips[3649]: WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 1090 ms ago (now 56580930 ms), delaying execution
Feb 15 09:13:34 node15 ./opensips[3649]: WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 1190 ms ago (now 56581030 ms), delaying execution
Feb 15 09:13:34 node15 ./opensips[3649]: WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 1290 ms ago (now 56581130 ms), delaying execution
Feb 15 09:13:34 node15 ./opensips[3649]: WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 1390 ms ago (now 56581230 ms), delaying execution
Feb 15 09:13:35 node15 ./opensips[3649]: WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 1490 ms ago (now 56581330 ms), delaying execution
Feb 15 09:13:35 node15 ./opensips[3649]: WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 1590 ms ago (now 56581430 ms), delaying execution
Feb 15 09:13:35 node15 ./opensips[3649]: WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 1690 ms ago (now 56581530 ms), delaying execution
Feb 15 09:13:35 node15 ./opensips[3649]: WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 1790 ms ago (now 56581630 ms), delaying execution
Feb 15 09:13:35 node15 ./opensips[3649]: WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 1890 ms ago (now 56581730 ms), delaying execution
Feb 15 09:13:35 node15 ./opensips[3649]: WARNING:core:timer_ticker: timer task <tm-timer> already scheduled 1990 ms ago (now 56581730 ms), delaying execution
Feb 15 09:13:35 node15 ./opensips[3649]: WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 1990 ms ago (now 56581830 ms), delaying execution
Feb 15 09:13:35 node15 ./opensips[3643]: INFO:core:handle_sigs: child process 3654 exited by a signal 6
Feb 15 09:13:35 node15 ./opensips[3643]: INFO:core:handle_sigs: core was generated
Feb 15 09:13:35 node15 ./opensips[3643]: INFO:core:handle_sigs: terminating due to SIGCHLD

OS/environment information

  • Operating System: debian sid
  • OpenSIPS installation: git
  • other relevant information:

Additional context

After I upgraded last week, there were some connectivity issues between this server and the one where it failed to send, which explain why the DNS based failover was triggered.

Also, between 0e2e434 (working stable) and 98cfd92 (crashing) I noticed there are these commits that are related to DNS based failover and faked requests, that may have something to do with this: 4d8d9ca, 09473b3, 0390ec9, f73abff, ee19a4f. The crash is because of a double free for a faked_req and I have a suspicion the other free happened in a timer.
@danpascu danpascu added the bug label Feb 19, 2020
@danpascu danpascu self-assigned this Feb 19, 2020
@bogdan-iancu
Copy link
Member

@danpascu , thanks for catching this !

razvancrainea pushed a commit that referenced this issue Feb 19, 2020
@danpascu @razvancrainea
Fixed crash caused by invalid memory free (fixes #1974)
acd20ae 
(cherry picked from commit 4432711)
razvancrainea pushed a commit that referenced this issue Feb 19, 2020
@danpascu @razvancrainea
Fixed crash caused by invalid memory free (fixes #1974)
4b8bc3b 
(cherry picked from commit 4432711)
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@danpascu danpascu

Labels
bug
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@bogdan-iancu @danpascu