null pointer in services/outside_network.c:160 reuse_cmp / rbtree_find_less_equal in Unbound 1.13.0 release

Using my amd64 linux on centos7 build from #393 (comment) with these commits added to 1.13.0:

I am still getting rare crashes. I've caught one here, in reuse_cmp having a nullptr for key2, coming from node->key:

unbound/util/rbtree.c

Lines 525 to 528 in ca49781

    
           /* While there are children... */ 
        
           while (node != RBTREE_NULL) { 
        
           	r = rbtree->cmp(key, node->key); 
        
           	if (r == 0) {

The backtrace is:

(gdb) bt
#0  reuse_cmp_addrportssl (key1=0x7fde2e2737e8, key2=0x0) at services/outside_network.c:144
#1  0x000055e21f6ba7c1 in   (key1=0x7fde2e2737e8, key2=0x0) at services/outside_network.c:160
#2  0x000055e21f6759ce in rbtree_find_less_equal (rbtree=rbtree@entry=0x7fdd7a428198, key=key@entry=0x7fde2e2737e8, result=result@entry=0x7fde2e2737c8) at util/rbtree.c:527
#3  0x000055e21f6baf0c in reuse_tcp_find (outnet=outnet@entry=0x7fdd7a428090, addr=addr@entry=0x7fdd6718d6f0, addrlen=16, use_ssl=<optimized out>) at services/outside_network.c:480
#4  0x000055e21f6bbf5f in use_free_buffer (outnet=outnet@entry=0x7fdd7a428090) at services/outside_network.c:723
#5  0x000055e21f6bc4fb in outnet_tcp_cb (c=0x7fdd61fd0ce0, arg=0x7fdd61fd0bb0, error=<optimized out>, reply_info=0x7fdd61fd0d18) at services/outside_network.c:1095
#6  0x000055e21f6b4087 in tcp_callback_reader (c=0x7fdd61fd0ce0) at util/netevent.c:1144
#7  0x000055e21f6b5548 in comm_point_tcp_handle_read (fd=217, c=0x7fdd61fd0ce0, short_ok=0) at util/netevent.c:1668
#8  0x000055e21f6b584b in comm_point_tcp_handle_callback (fd=217, event=<optimized out>, arg=0x7fdd61fd0ce0) at util/netevent.c:2062
#9  0x00007fde30723a14 in event_base_loop () from /lib64/libevent-2.0.so.5
#10 0x000055e21f6b1fac in comm_base_dispatch (b=<optimized out>) at util/netevent.c:246
#11 0x000055e21f62e499 in worker_work (worker=worker@entry=0x55e2216803b0) at daemon/worker.c:1941
#12 0x000055e21f6222bf in thread_start (arg=0x55e2216803b0) at daemon/daemon.c:540
#13 0x00007fde3009bea5 in start_thread () from /lib64/libpthread.so.0
#14 0x00007fde2fdc496d in clone () from /lib64/libc.so.6

At the null pointer, *node is normal except for the null:

(gdb) up
#1  0x000055e21f6ba7c1 in reuse_cmp (key1=0x7fde2e2737e8, key2=0x0) at services/outside_network.c:160
160		r = reuse_cmp_addrportssl(key1, key2);
(gdb) up
#2  0x000055e21f6759ce in rbtree_find_less_equal (rbtree=rbtree@entry=0x7fdd7a428198, key=key@entry=0x7fde2e2737e8, result=result@entry=0x7fde2e2737c8) at util/rbtree.c:527
527			r = rbtree->cmp(key, node->key);
(gdb) p *node
$2 = {parent = 0x7fdd61a09468, left = 0x55e21f922460 <rbtree_null_node>, right = 0x55e21f922460 <rbtree_null_node>, key = 0x0, color = 1 '\001'}

The core file is 6.36 GB; I can certainly share it and the centos7 rpm files out-of-band if you'd like to investigate directly, or I am happy to dig around in the core file in response to your questions. Thanks again!

Could you provide the configuration in use?

Sure: https://gist.github.com/jcjones/2f7a19b8d0c5b3c4072b5f265f88a4bf

Thanks! At least this excludes a path I was looking at: forwarders and tls configuration.
Having a NULL on the key and the node somehow still being part of the tree is the fault here; still looking into it.
If you notice a way to reliably reproduce it that would be a big plus.

I'm afraid a reproducer is not going to be likely given the nature of the input data to these instances; sorry. Still, if something comes up, I'll let you know.

- Attempt to fix NULL keys in the reuse_tcp tree; relates to #411.

@jcjones

Hi @jcjones, I wasn't able to reproduce this. We have an attempt on a fix that is included in the ongoing release candidate for unbound 1.13.1. We have a branch for that, if you would like to try it out that would be great.
Other than that, an extra question: do you use unbound-control to alter the configuration on the fly?

No, we're not using unbound-control. I'll give the tag a try ASAP, though it may be a few days before I have results. Thanks!

Just an update that we've had 24 hours of 1.13.1rc1 so far with only a stuck process (100% CPU, unfortunately didn't get a core on the restart), no segfaults yet.

We've seen a segfault on 1.13.1rc1; I have a core dump I'll analyze tonight.

Log output would also be nice if available. We added a couple extra print error cases ("internal error: ...") when trying to fix this.

Will do, I saw many of those.

On Tue, Feb 9, 2021 at 12:19 PM gthess ***@***.***> wrote: Log output would also be nice if available. We added a couple extra print error cases ("internal error: ...") when trying to fix this. — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#411 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AAD6TDRPPINTXIKQSE6NLVLS6GDDTANCNFSM4WUTKYBA> .

-- -- James ‘J.C.’ Jones Blog <https://insufficient.coffee/>

Merge remote-tracking branch 'nlnet/master'

Stack trace:

(gdb) bt
#0  reuse_cmp_addrportssl (key1=0x7fb22db8f858, key2=0x0) at services/outside_network.c:148
#1  0x0000564e82da01c1 in reuse_cmp (key1=0x7fb22db8f858, key2=0x0) at services/outside_network.c:164
#2  0x0000564e82d5b3be in rbtree_find_less_equal (rbtree=rbtree@entry=0x7fb17a428198, key=key@entry=0x7fb22db8f858, result=result@entry=0x7fb22db8f838) at util/rbtree.c:527
#3  0x0000564e82da090c in reuse_tcp_find (outnet=outnet@entry=0x7fb17a428090, addr=addr@entry=0x7fb15a124b10, addrlen=28, use_ssl=<optimized out>) at services/outside_network.c:487
#4  0x0000564e82da19d5 in use_free_buffer (outnet=outnet@entry=0x7fb17a428090) at services/outside_network.c:740
#5  0x0000564e82da1f6b in outnet_tcp_cb (c=0x7fb161c93a80, arg=0x7fb161c93950, error=<optimized out>, reply_info=0x0) at services/outside_network.c:1112
#6  0x00007fb23003fa14 in event_base_loop () from /lib64/libevent-2.0.so.5
#7  0x0000564e82d9793c in comm_base_dispatch (b=<optimized out>) at util/netevent.c:246
#8  0x0000564e82d14779 in worker_work (worker=worker@entry=0x564e846bfe30) at daemon/worker.c:1949
#9  0x0000564e82d084cf in thread_start (arg=0x564e846bfe30) at daemon/daemon.c:540
#10 0x00007fb22f9b7ea5 in start_thread () from /lib64/libpthread.so.0
#11 0x00007fb22f6e098d in ?? () from /lib64/libc.so.6
#12 0x0000000000000000 in ?? ()

I swear I saw internal errors somewhere recently, but perhaps it wasn't unbound. None of my unbound instances have logged "internal error" in accessible logs, nor the specific messages from a8485d5.

Here's the log around the segfault, though it's pretty bare:

"2021-02-09T07:57:12.300438+00:00 unbound: [30742:0] info: generate keytag query _ta-4f66. NULL IN"
"2021-02-09T07:56:07.801150+00:00 unbound: [30742:0] info: generate keytag query _ta-4f66. NULL IN"
"2021-02-09T07:56:07.673111+00:00 unbound: [30742:1] info: generate keytag query _ta-4f66. NULL IN"
"2021-02-09T07:55:06.567384+00:00 unbound: [30742:1] info: generate keytag query _ta-4f66. NULL IN"
"2021-02-09T07:55:06.129952+00:00 unbound: [30742:0] info: generate keytag query _ta-4f66. NULL IN"
"2021-02-09T07:54:02.351378+00:00 unbound: [30742:1] info: generate keytag query _ta-4f66. NULL IN"
"2021-02-09T07:54:02.331246+00:00 unbound: [30742:0] info: generate keytag query _ta-4f66. NULL IN"
"2021-02-09T07:54:02.247063+00:00 unbound: [30742:0] info: start of service (unbound 1.13.1rc1)."
"2021-02-09T07:54:01.651197+00:00 unbound: [30742:0] notice: init module 2: iterator"
"2021-02-09T07:54:01.650961+00:00 unbound: [30742:0] notice: init module 1: validator"
"2021-02-09T07:54:01.650680+00:00 unbound: [30742:0] notice: init module 0: subnet"
"2021-02-09T07:54:01.639870+00:00 unbound: [30742:0] warning: did not exit gracefully last time (6459)"
"2021-02-09T07:54:01.626723+00:00 systemd: Started Unbound recursive Domain Name Server."
"2021-02-09T07:54:01.566999+00:00 unbound-checkconf: unbound-checkconf: no errors in /etc/unbound/unbound.conf"
"2021-02-09T07:54:01.535324+00:00 systemd: Starting Unbound recursive Domain Name Server..."
"2021-02-09T07:54:01.533312+00:00 systemd: Stopped Unbound recursive Domain Name Server."
"2021-02-09T07:54:01.533003+00:00 systemd: unbound.service holdoff time over, scheduling restart."
"2021-02-09T07:54:01.370294+00:00 systemd: unbound.service failed."
"2021-02-09T07:54:01.370028+00:00 systemd: Unit unbound.service entered failed state."
"2021-02-09T07:54:01.369677+00:00 systemd: unbound.service: main process exited, code=killed, status=11/SEGV"
"2021-02-09T07:53:13.530533+00:00 kernel: unbound[6461]: segfault at a8 ip 0000564e82da0154 sp 00007fb22db8f7c0 error 4 in unbound[564e82cf4000+112000]"
"2021-02-09T07:52:20.096442+00:00 unbound: [6459:1] info: generate keytag query _ta-4f66. NULL IN"
"2021-02-09T07:51:15.445427+00:00 unbound: [6459:0] info: generate keytag query _ta-4f66. NULL IN"
"2021-02-09T07:51:15.373748+00:00 unbound: [6459:1] info: generate keytag query _ta-4f66. NULL IN"
"2021-02-09T07:50:14.272442+00:00 unbound: [6459:0] info: generate keytag query _ta-4f66. NULL IN"
"2021-02-09T07:50:14.243744+00:00 unbound: [6459:1] info: generate keytag query _ta-4f66. NULL IN"
"2021-02-09T07:49:13.625484+00:00 unbound: [6459:1] info: generate keytag query _ta-4f66. NULL IN"

I'm still seeing these spuriously with 1.13.1 release, they look the same. E.g.:

Core was generated by `/usr/sbin/unbound -d'.
Program terminated with signal 11, Segmentation fault.
#0  reuse_cmp_addrportssl (key1=0x7f3c049a6588, key2=0x0) at services/outside_network.c:148
148		r = sockaddr_cmp(&r1->addr, r1->addrlen, &r2->addr, r2->addrlen);
Missing separate debuginfos, use: debuginfo-install glibc-2.17-323.el7_9.x86_64 keyutils-libs-1.5.8-3.el7.x86_64 krb5-libs-1.15.1-50.el7.x86_64 libcom_err-1.42.9-19.el7.x86_64 libevent-2.0.21-4.el7.x86_64 libselinux-2.5-15.el7.x86_64 openssl-libs-1.0.2k-21.el7_9.x86_64 pcre-8.32-17.el7.x86_64 protobuf-c-1.0.2-3.el7.x86_64 zlib-1.2.7-19.el7_9.x86_64
(gdb) bt
#0  reuse_cmp_addrportssl (key1=0x7f3c049a6588, key2=0x0) at services/outside_network.c:148
#1  0x000055aefd4df251 in reuse_cmp (key1=0x7f3c049a6588, key2=0x0) at services/outside_network.c:164
#2  0x000055aefd49a45e in rbtree_find_less_equal (rbtree=rbtree@entry=0x7f3b52428198, key=key@entry=0x7f3c049a6588, 
    result=result@entry=0x7f3c049a6568) at util/rbtree.c:527
#3  0x000055aefd4df99c in reuse_tcp_find (outnet=0x7f3b52428090, addr=addr@entry=0x7f3b3c856808, addrlen=28, use_ssl=<optimized out>)
    at services/outside_network.c:487
#4  0x000055aefd4e322d in pending_tcp_query (sq=sq@entry=0x7f3b3c8567b0, packet=packet@entry=0x7f3b52428350, 
    timeout=timeout@entry=3000, callback=callback@entry=0x55aefd4e37d0 <serviced_tcp_callback>, 
    callback_arg=callback_arg@entry=0x7f3b3c8567b0) at services/outside_network.c:2120
#5  0x000055aefd4e3789 in serviced_tcp_initiate (sq=0x7f3b3c8567b0, buff=0x7f3b52428350) at services/outside_network.c:2807
#6  0x000055aefd4e3d51 in serviced_udp_callback (c=0x7f3b3c287800, arg=0x7f3b3c8567b0, error=<optimized out>, rep=0x7f3c049a6c30)
    at services/outside_network.c:3010
#7  0x000055aefd4e198a in outnet_udp_cb (c=0x7f3b3c287800, arg=0x7f3b52428090, error=<optimized out>, reply_info=0x7f3c049a6c30)
    at services/outside_network.c:1243
#8  0x000055aefd4d6d58 in comm_point_udp_callback (fd=159, event=<optimized out>, arg=<optimized out>) at util/netevent.c:769
#9  0x00007f3c06e56a14 in event_base_loop () from /lib64/libevent-2.0.so.5
#10 0x000055aefd4d69cc in comm_base_dispatch (b=<optimized out>) at util/netevent.c:246
#11 0x000055aefd453779 in worker_work (worker=worker@entry=0x55aefdd24e60) at daemon/worker.c:1949
#12 0x000055aefd4474cf in thread_start (arg=0x55aefdd24e60) at daemon/daemon.c:540
#13 0x00007f3c067ceea5 in start_thread () from /lib64/libpthread.so.0
#14 0x00007f3c064f79fd in clone () from /lib64/libc.so.6

No instances of "internal error" in the logs at all. No output from unbound in the logs anytime close to the segfault.

Most interesting to me is that I have two of these same segfaults occurring within 10 minutes of each other, whereas before they always seemed to need substantial time to reproduce:

$ sudo coredumpctl list
TIME                            PID   UID   GID SIG PRESENT EXE
Sat 2021-02-20 12:32:09 UTC   20030   997   993  11   /usr/sbin/unbound
Sun 2021-02-21 06:49:44 UTC   26011   997   993  11   /usr/sbin/unbound
Tue 2021-02-23 04:41:03 UTC    8149   997   993  11   /usr/sbin/unbound
Thu 2021-02-25 08:25:12 UTC   26630   997   993  11   /usr/sbin/unbound
Thu 2021-02-25 11:43:34 UTC   10285   997   993  11   /usr/sbin/unbound
Mon 2021-03-01 19:41:24 UTC   24626   997   993  11 * /usr/sbin/unbound
Mon 2021-03-01 20:43:46 UTC   20576   997   993  11 * /usr/sbin/unbound
Mon 2021-03-01 23:27:30 UTC   25400   997   993  11 * /usr/sbin/unbound
Mon 2021-03-01 23:37:13 UTC    4760   997   993  11 * /usr/sbin/unbound

- Changelog entry for #513: Stream reuse, attempt to fix #411, #439,

Auto-closed by commit message, reopening.

@jcjones

Hi @jcjones, @Mityai, @internationils,
Further fixes have been merged (PR #513) to the master branch.
Our own testing does not yield the issue anymore but it would be great if you could test and provide feedback!

@jcjones

Hi @jcjones, @Mityai, @internationils,
Further fixes have been merged (PR #513) to the master branch.
Our own testing does not yield the issue anymore but it would be great if you could test and provide feedback!

I would love to add this patch on pfSense development branches so more people can test but it's not applying on 1.13.1 cleanly. I'm going to work on fixing conflicts and see if it works

@rbgarga

Hi @rbgarga,
that would be great!
From a quick look, the conflicts don't appear complicated to me, glad to help if you get stuck. (Make sure to ignore doc/Changelog as this can give a lot of conflicts).

Btw you would also need the following commits (in order, before the PR diff) that solve parts of the issue before the PR was created:

@rbgarga

t

Hi @rbgarga,
that would be great!
From a quick look, the conflicts don't appear complicated to me, glad to help if you get stuck. (Make sure to ignore doc/Changelog as this can give a lot of conflicts).

Btw you would also need the following commits (in order, before the PR diff) that solve parts of the issue before the PR was created:

1bdae42

7396eff

ff6b527

I already have these 3 commits applied and removed test changes for #513 ending up with a patch that only touches services/outside_network.[ch].

2 hunks fail to apply creating this reject file https://idaho.arrakis.com.br/files/outside_network.c.rej

@rbgarga

t

Hi @rbgarga,
that would be great!
From a quick look, the conflicts don't appear complicated to me, glad to help if you get stuck. (Make sure to ignore doc/Changelog as this can give a lot of conflicts).
Btw you would also need the following commits (in order, before the PR diff) that solve parts of the issue before the PR was created:

1bdae42

7396eff

ff6b527

I already have these 3 commits applied and removed test changes for #513 ending up with a patch that only touches services/outside_network.[ch].

2 hunks fail to apply creating this reject file https://idaho.arrakis.com.br/files/outside_network.c.rej

I sorted out first hunk but second seems to depend of any other change:

@@ -801,11 +907,15 @@
 #ifdef USE_DNSTAP
                        pend_tcp = pend;
 #endif
+               } else {
+                       /* no reuse and no free buffer, put back at the start */
+                       outnet_add_tcp_waiting_first(outnet, w, 0);
+                       break;
                }
 #ifdef USE_DNSTAP
                if(outnet->dtenv && pend_tcp && w && w->sq &&
-                  (outnet->dtenv->log_resolver_query_messages ||
-                   outnet->dtenv->log_forwarder_query_messages)) {
+                       (outnet->dtenv->log_resolver_query_messages ||
+                       outnet->dtenv->log_forwarder_query_messages)) {
                        sldns_buffer tmp;
                        sldns_buffer_init_frm_data(&tmp, w->pkt, w->pkt_len);
                        dt_msg_send_outside_query(outnet->dtenv, &w->sq->addr,```

I don't see any place that this change would fit

You need the first part for sure; the else including outnet_add_tcp_waiting_first and break.
This becomes the else to the if(reuse) above. The previous else has now become else if(outnet->tcp_free).

I believe there are no ifdefs in your current version and you can ignore the second part.

Hope this is clear.

You need the first part for sure; the else including outnet_add_tcp_waiting_first and break.
This becomes the else to the if(reuse) above. The previous else has now become else if(outnet->tcp_free).

I believe there are no ifdefs in your current version and you can ignore the second part.

Hope this is clear.

Awesome! Thanks!

Merge remote-tracking branch 'nlnet/master'

@rbgarga

@rbgarga, 1.13.2 is now released which includes the aforementioned patches. I believe it solves the occasional crash while reloading that I've been reading on the pfsense forum.

@jcjones, @Mityai, we believe 1.13.2 solves this issue. I leave the issue open and feel free to close/update based on your experience.

Closing as inactive; the observed issues seem resolved.

Merge pull request NLnetLabs#513 from NLnetLabs/tcp_reuse_fix

Navigation Menu

Repository navigation

null pointer in services/outside_network.c:160 reuse_cmp / rbtree_find_less_equal in Unbound 1.13.0 release #411

23 remaining items

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

	/* While there are children... */
	while (node != RBTREE_NULL) {
	r = rbtree->cmp(key, node->key);
	if (r == 0) {

null pointer in services/outside_network.c:160 reuse_cmp / rbtree_find_less_equal in Unbound 1.13.0 release #411

Description

Activity

gthess commented on Jan 27, 2021

jcjones commented on Jan 27, 2021

gthess commented on Jan 27, 2021

jcjones commented on Jan 27, 2021

gthess commented on Feb 2, 2021

jcjones commented on Feb 2, 2021

jcjones commented on Feb 9, 2021

jcjones commented on Feb 9, 2021

gthess commented on Feb 9, 2021

jcjones commented on Feb 9, 2021

jcjones commented on Feb 10, 2021

jcjones commented on Mar 4, 2021

23 remaining items

gthess commented on Jul 26, 2021

gthess commented on Jul 26, 2021

rbgarga commented on Jul 26, 2021

gthess commented on Jul 26, 2021

rbgarga commented on Jul 26, 2021

rbgarga commented on Jul 26, 2021

gthess commented on Jul 26, 2021

rbgarga commented on Jul 26, 2021

gthess commented on Aug 12, 2021

gthess commented on Mar 17, 2023

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions