local_datas without \4\n reuses last read buffer(?) and produces infinite error output

[nabijaczleweli]

Describe the bug
local_datas without \4\n reuses last read buffer(?) and produces infinite error output

To reproduce

$ { printf '%s\n' 'UBCT1 local_datas' ';; a' 'abc.def. 3600 in txt testupa' ';; b'; } | sudo socat - UNIX-CONNECT:/run/unbound.ctl
error parsing local-data at line 1 position 4 ';; a': Syntax error, could not parse the RR
error parsing local-data at line 3 position 4 ';; b': Syntax error, could not parse the RR
error parsing local-data at line 4 position 0 '': Syntax error, could not parse the RR
error parsing local-data at line 5 position 0 '': Syntax error, could not parse the RR
error parsing local-data at line 6 position 0 '': Syntax error, could not parse the RR
error parsing local-data at line 7 position 0 '': Syntax error, could not parse the RR
error parsing local-data at line 8 position 0 '': Syntax error, could not parse the RR
error parsing local-data at line 9 position 0 '': Syntax error, could not parse the RR
error parsing local-data at line 10 position 0 '': Syntax error, could not parse the RR
error parsing local-data at line 11 position 0 '': Syntax error, could not parse the RR
error parsing local-data at line 12 position 0 '': Syntax error, could not parse the RR
error parsing local-data at line 13 position 0 '': Syntax error, could not parse the RR
error parsing local-data at line 14 position 0 '': Syntax error, could not parse the RR
error parsing local-data at line 15 position 0 '': Syntax error, could not parse the RR
error parsing local-data at line 16 position 0 '': Syntax error, could not parse the RR
error parsing local-data at line 17 position 0 '': Syntax error, could not parse the RR
error parsing local-data at line 18 position 0 '': Syntax error, could not parse the RR
error parsing local-data at line 19 position 0 '': Syntax error, could not parse the RR
error parsing local-data at line 20 position 0 '': Syntax error, could not parse the RR
error parsing local-data at line 21 position 0 '': Syntax error, could not parse the RR
error parsing local-data at line 22 position 0 '': Syntax error, could not parse the RR
error parsing local-data at line 23 position 0 '': Syntax error, could not parse the RR
error parsing local-data at line 24 position 0 '': Syntax error, could not parse the RR
error parsing local-data at line 25 position 0 '': Syntax error, could not parse the RR
error parsing local-data at line 26 position 0 '': Syntax error, could not parse the RR
error parsing local-data at line 27 position 0 '': Syntax error, could not parse the RR
error parsing local-data at line 28 position 0 '': Syntax error, could not parse the RR
...
error parsing local-data at line 56466 position 0 '': Syntax error, could not parse the RR
error parsing local-data at line 56467 position 0 '': Syntax error, could not parse the RR
error parsing local-data at line 56468 position 0 '': Syntax error, could not parse the RR
error parsing local-data at line 56469 position 0 '': Syntax error, could not parse the RR
error parsing local-data at line 56470 position 0 '': Syntax error, could not parse the RR
error parsing local-data at line 56471 position 0 '': Syntax error, could not parse the RR
error parsing local-data at line 56472 position 0 '': Syntax error, could not parse the RR
error parsing local-data at line 56473 position 0 '': Syntax error, could not parse the RR
error parsing local-data at line 56474 position 0 '': Syntax error, could not parse the RR
error parsing local-data at line 56475 position 0 '': Syntax error, could not parse the RR
error parsing local-data at line 56476 position 0 '': Syntax error, could not parse the RR
^C

strace -f of this moment.

Appending printf '\4\n', as stolen from strace unbound-control local_datas, makes it work correctly.

Expected behavior
not that

System:

• Unbound version: 1.17.1-2 off Debian
• Unbound version: 1.18.0-2 off Debian
• OS: Debian
• unbound -V output:

Version 1.17.1

Configure line: --build=x86_64-linux-gnu --prefix=/usr --includedir=${prefix}/include --mandir=${prefix}/share/man --infodir=${prefix}/share/info --sysconfdir=/etc --localstatedir=/var --disable-option-checking --disable-silent-rules --libdir=${prefix}/lib/x86_64-linux-gnu --runstatedir=/run --disable-maintainer-mode --disable-dependency-tracking --with-pythonmodule --with-pyunbound --enable-subnet --enable-dnstap --enable-systemd --with-libnghttp2 --with-chroot-dir= --with-dnstap-socket-path=/run/dnstap.sock --disable-rpath --with-pidfile=/run/unbound.pid --with-libevent --enable-tfo-client --with-rootkey-file=/usr/share/dns/root.key --enable-tfo-server
Linked libs: libevent 2.1.12-stable (it uses epoll), OpenSSL 3.0.11 19 Sep 2023
Linked modules: dns64 python subnetcache respip validator iterator
TCP Fastopen feature available

BSD licensed, see LICENSE in source package for details.
Report bugs to unbound-bugs@nlnetlabs.nl or https://github.com/NLnetLabs/unbound/issues

Version 1.18.0

Configure line: --build=x86_64-linux-gnux32 --prefix=/usr --includedir=${prefix}/include --mandir=${prefix}/share/man --infodir=${prefix}/share/info --sysconfdir=/etc --localstatedir=/var --disable-option-checking --disable-silent-rules --libdir=${prefix}/lib/x86_64-linux-gnux32 --runstatedir=/run --disable-maintainer-mode --disable-dependency-tracking --with-pythonmodule --with-pyunbound --enable-subnet --enable-dnstap --enable-systemd --enable-cachedb --with-libhiredis --with-libnghttp2 --with-chroot-dir= --with-dnstap-socket-path=/run/dnstap.sock --disable-rpath --with-pidfile=/run/unbound.pid --with-libevent --enable-tfo-client --with-rootkey-file=/usr/share/dns/root.key --disable-flto --enable-tfo-server
Linked libs: libevent 2.1.12-stable (it uses epoll), OpenSSL 3.0.11 19 Sep 2023
Linked modules: dns64 python cachedb subnetcache respip validator iterator
TCP Fastopen feature available

BSD licensed, see LICENSE in source package for details.
Report bugs to unbound-bugs@nlnetlabs.nl or https://github.com/NLnetLabs/unbound/issues

Additional information
Downstream bug: https://bugs.debian.org/1051817

[gthess]

Thanks for reporting and the analysis!
This should be addressed now with 516f90a; at least I cannot reproduce it anymore.
Could you verify?

[nabijaczleweli]

Applied 516f90a to 1.18.0-2 and that seems to be worse: on first go it returns an error, but then it just enters an infinite loop, silently:

$ { printf '%s\n' 'UBCT1 local_datas' ';; a' 'abc.def. 3600 in txt testupa' ';; b'; } | sudo socat - UNIX-CONNECT:/run/unbound.ctl
error parsing local-data at line 1 position 4 ';; a': Syntax error, could not parse the RR
error parsing local-data at line 3 position 4 ';; b': Syntax error, could not parse the RR
$ { printf '%s\n' 'UBCT1 local_datas' ';; a' 'abc.def. 3600 in txt testupa' ';; b'; } | sudo socat - UNIX-CONNECT:/run/unbound.ctl
$ { printf '%s\n' 'UBCT1 local_datas' ';; a' 'abc.def. 3600 in txt testupa' ';; b'; } | sudo socat - UNIX-CONNECT:/run/unbound.ctl
$ { printf '%s\n' 'UBCT1 local_datas' ';; a' 'abc.def. 3600 in txt testupa' ';; b'; } | sudo socat - UNIX-CONNECT:/run/unbound.ctl
$ { printf '%s\n' 'UBCT1 local_datas' ';; a' 'abc.def. 3600 in txt testupa' ';; b'; } | sudo socat - UNIX-CONNECT:/run/unbound.ctl
$ sudo unbound-control flush_zone nabijaczleweli.xyz
(u-c slept here, unbound was 100% CPU the whole time w/o output, until I kill -9ed unbound)

[1696949806] unbound-control[2890268:0] fatal error: could not recv: Connection reset by peer

[gthess]

I cannot reproduce it here, neither on 1.18.0 with patch, nor on current master:

$ { printf '%s\n' 'UBCT1 local_datas' ';; a' 'abc.def. 3600 in txt testupa' ';; b'; } | sudo socat - UNIX-CONNECT:./control.ctl
error parsing local-data at line 1 position 4 ';; a': Syntax error, could not parse the RR
error parsing local-data at line 3 position 4 ';; b': Syntax error, could not parse the RR
added 1 datas

$ { printf '%s\n' 'UBCT1 local_datas' ';; a' 'abc.def. 3600 in txt testupa' ';; b'; } | sudo socat - UNIX-CONNECT:./control.ctl
error parsing local-data at line 1 position 4 ';; a': Syntax error, could not parse the RR
error parsing local-data at line 3 position 4 ';; b': Syntax error, could not parse the RR
added 1 datas

$ { printf '%s\n' 'UBCT1 local_datas' ';; a' 'abc.def. 3600 in txt testupa' ';; b'; } | sudo socat - UNIX-CONNECT:./control.ctl
error parsing local-data at line 1 position 4 ';; a': Syntax error, could not parse the RR
error parsing local-data at line 3 position 4 ';; b': Syntax error, could not parse the RR
added 1 datas

$ sudo ./unbound-control flush_zone nabijaczleweli.xyz
ok removed 0 rrsets, 0 messages and 0 key entries

Do you see anything in the Unbound log if you bump verbosity to 4?

[nabijaczleweli]

Okay I thought I couldn't re-reproduce this, but it's just intermittent, and I must've been lucky to hit it on the first try. It also seems timing-dependent because it's impossible to trigger (to me) with verbosity 4.

By doing while :; do { printf '%s\n' 'UBCT1 local_datas' ';; a' 'abc.def. 3600 in txt testupa' ';; b'; } | socat - UNIX-CONNECT:/run/unbound.ctl; date; done, I got a single repeat date a few times, but only a hard hang with verbosity 1 or 0.

And at that level I don't see a correlation. One time I got

2023-10-11T13:51:07+0200 tarta unbound[1914144]: [1914144:0] info: control cmd: local_datas
2023-10-11T13:51:07+0200 tarta unbound[1914144]: [1914144:0] error: could not recv: Address family not supported by protocol
2023-10-11T13:51:07+0200 tarta unbound[1914144]: [1914144:0] info: resolving zdalnenagrywanie.ncplus.pl. A IN
2023-10-11T13:51:07+0200 tarta unbound[1914144]: [1914144:0] info: priming . IN NS
2023-10-11T13:51:07+0200 tarta unbound[1914144]: [1914144:0] info: control cmd: local_datas

but.

Or not intermittent at all because sometimes it works on the first try. Anyway,

(gdb) bt
#0  0x00007fd23b1f7649 in __libc_recv (fd=13, buf=buf@entry=0x7ffe3f0ce6e0, len=len@entry=1, flags=flags@entry=0) at ../sysdeps/unix/sysv/linux/recv.c:28
#1  0x000055a30f877b12 in recv (__flags=0, __n=1, __buf=0x7ffe3f0ce6e0, __fd=<optimized out>) at /usr/include/x86_64-linux-gnu/bits/socket2.h:38
#2  ssl_read_line (res=res@entry=0x7ffe3f0cf390, buf=buf@entry=0x7ffe3f0ce6e0 ";; b", max=max@entry=2048) at daemon/remote.c:590
#3  0x000055a30f877e90 in do_datas_add (ssl=ssl@entry=0x7ffe3f0cf390, zones=0x55a31001b6a0) at daemon/remote.c:1337
#4  0x000055a30f87aa2b in execute_cmd (rc=rc@entry=0x55a30ffd89f0, ssl=ssl@entry=0x7ffe3f0cf390, cmd=cmd@entry=0x7ffe3f0cef50 "local_datas", worker=<optimized out>)
    at daemon/remote.c:3146
#5  0x000055a30f87b38f in handle_req (rc=rc@entry=0x55a30ffd89f0, res=res@entry=0x7ffe3f0cf390, s=0x55a310770b50) at daemon/remote.c:3264
#6  0x000055a30f87b45e in remote_control_callback (c=0x55a310770b90, arg=arg@entry=0x55a310770b50, err=err@entry=0, rep=rep@entry=0x0) at daemon/remote.c:3350
#7  0x000055a30f87b721 in remote_accept_callback (err=0, rep=<optimized out>, arg=0x55a30ffd89f0, c=<optimized out>) at daemon/remote.c:485
#8  remote_accept_callback (c=<optimized out>, arg=0x55a30ffd89f0, err=<optimized out>, rep=<optimized out>) at daemon/remote.c:411
#9  0x00007fd23c029585 in event_persist_closure (ev=<optimized out>, base=0x55a31007a5a0) at ./event.c:1623
#10 event_process_active_single_queue (base=base@entry=0x55a31007a5a0, activeq=0x55a31007a9f0, max_to_process=max_to_process@entry=2147483647, endtime=endtime@entry=0x0)
    at ./event.c:1682
#11 0x00007fd23c029c1f in event_process_active (base=0x55a31007a5a0) at ./event.c:1783
#12 event_base_loop (base=0x55a31007a5a0, flags=flags@entry=0) at ./event.c:2006
#13 0x00007fd23c029ed7 in event_base_dispatch (event_base=<optimized out>) at ./event.c:1817
#14 0x000055a30f94b205 in ub_event_base_dispatch (base=<optimized out>) at util/ub_event.c:280
#15 0x000055a30f93887c in comm_base_dispatch (b=<optimized out>) at util/netevent.c:280
#16 0x000055a30f880d39 in worker_work (worker=<optimized out>) at daemon/worker.c:2326
#17 0x000055a30f871ef4 in daemon_fork (daemon=daemon@entry=0x55a30ff902d0) at daemon/daemon.c:795
#18 0x000055a30f86cdb1 in run_daemon (need_pidfile=0, debug_mode=1, cmdline_verbose=0, cfgfile=0x55a30f95d3d8 "/etc/unbound/unbound.conf") at daemon/unbound.c:637
#19 main (argc=<optimized out>, argv=<optimized out>) at daemon/unbound.c:739

[gthess]

I believe I addressed it properly this time with 07149f5.
Could you try again?

[nabijaczleweli]

Yep, can't repro with 516f90a + 07149f5.

[gthess]

That's good to hear! I suppose the same goes for #947?

[nabijaczleweli]

yep, tried both in a few configurations and and neither repro

[gthess]

Feel free to close them in your own time in case you want to try some more.
Thanks again for the report!