Description of problem: When I run Bind DNS on my blackbird, it unpredictably crashes after 24 hours. It's simplisticly setup with 2 subnets. The DNS service is un-useable until the systemd service is manually restarted. Version-Release number of selected component (if applicable): bind-9.11.8-1.fc30.ppc64le How reproducible: Every day as long as the system stays up for at least 24 hours. (Don't restart the computer or the service in between.) Steps to Reproduce: 1.Install Bind DNS 2.Let it sit for 24 hours 3.Check the service status Expected results: Bind DNS should still be running. Actual results: It has died with this stack trace: Jul 22 00:51:58 Blackbird named[1860]: ../../../lib/dns/rbtdb.c:10337: INSIST((rbtdb->rdatasets[header->node->locknum]).head == (header)) failed, back trace Jul 22 00:51:58 Blackbird audit[1860]: ANOM_ABEND auid=4294967295 uid=25 gid=25 ses=4294967295 pid=1860 comm="isc-worker0006" exe="/usr/sbin/named" sig=6 res=1 Jul 22 00:51:58 Blackbird named[1860]: #0 0x12f650508 in ?? Jul 22 00:51:58 Blackbird named[1860]: #1 0x7fffa8f5d978 in ?? Jul 22 00:51:58 Blackbird named[1860]: #2 0x7fffa91b2714 in ?? Jul 22 00:51:58 Blackbird named[1860]: #3 0x7fffa91b9738 in ?? Jul 22 00:51:58 Blackbird named[1860]: #4 0x7fffa91c3834 in ?? Jul 22 00:51:58 Blackbird named[1860]: #5 0x7fffa913bb90 in ?? Jul 22 00:51:58 Blackbird named[1860]: #6 0x12f6630e0 in ?? Jul 22 00:51:58 Blackbird named[1860]: #7 0x12f66c258 in ?? Jul 22 00:51:58 Blackbird named[1860]: #8 0x7fffa8f91c28 in ?? Jul 22 00:51:58 Blackbird named[1860]: #9 0x7fffa8ab8c10 in ?? Jul 22 00:51:58 Blackbird named[1860]: #10 0x7fffa86ed8a8 in ?? Jul 22 00:51:58 Blackbird named[1860]: exiting (due to assertion failure) Jul 22 00:51:59 Blackbird systemd[1]: named.service: Main process exited, code=killed, status=6/ABRT Jul 22 00:51:59 Blackbird systemd[1]: named.service: Failed with result 'signal'. Additional info: I've only tried it for 1 day but recompiling with --disable-atomic seems to work. export LIBDIR_SUFFIX %configure \ --with-python=%{__python3} \ --disable-atomic \ --with-libtool \ --localstatedir=/var \ --enable-threads \ --enable-ipv6 \ --enable-filter-aaaa \ --with-pic \ etc... and ## minimal subset of options to make clients aka dhcp working %{configure} \ --with-libtool \ --disable-atomic \ --disable-static \ --disable-epoll \ --disable-kqueue \ --libdir=%{_libdir}%{_export_dir} \ --includedir=%{_includedir}%{_export_dir}/ \ --disable-threads \ etc... Credit: https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=778720
Any chance there would be more details captured in journal and available via "coredumpctl gdb" command?
I'll reinstall the stock fedora 30 bind and see if I get a crash tomorrow night. Then I'll try running coredumpctl gdb. Here's a full copy and paste of the journalctl the last time it happened (before I recompiled). Note, it also includes the restart of bind after the crash. Jul 22 00:51:30 Blackbird named[1860]: network unreachable resolving './NS/IN': 2001:500:200::b#53 Jul 22 00:51:30 Blackbird named[1860]: network unreachable resolving './NS/IN': 2001:500:2::c#53 Jul 22 00:51:30 Blackbird named[1860]: network unreachable resolving './NS/IN': 2001:500:12::d0d#53 Jul 22 00:51:30 Blackbird named[1860]: network unreachable resolving './NS/IN': 2001:7fe::53#53 Jul 22 00:51:30 Blackbird named[1860]: network unreachable resolving './NS/IN': 2001:dc3::35#53 Jul 22 00:51:30 Blackbird named[1860]: network unreachable resolving './NS/IN': 2001:500:9f::42#53 Jul 22 00:51:30 Blackbird named[1860]: network unreachable resolving './NS/IN': 2001:500:2d::d#53 Jul 22 00:51:30 Blackbird named[1860]: network unreachable resolving './NS/IN': 2001:500:2f::f#53 Jul 22 00:51:30 Blackbird named[1860]: network unreachable resolving './NS/IN': 2001:503:c27::2:30#53 Jul 22 00:51:30 Blackbird named[1860]: network unreachable resolving './NS/IN': 2001:500:a8::e#53 Jul 22 00:51:30 Blackbird named[1860]: network unreachable resolving './NS/IN': 2001:503:ba3e::2:30#53 Jul 22 00:51:30 Blackbird named[1860]: network unreachable resolving './NS/IN': 2001:500:1::53#53 Jul 22 00:51:30 Blackbird named[1860]: network unreachable resolving './NS/IN': 2001:7fd::1#53 Jul 22 00:51:30 Blackbird named[1860]: trust-anchor-telemetry '_ta-4f66/IN' from 192.168.1.1 Jul 22 00:51:30 Blackbird named[1860]: trust-anchor-telemetry '_ta-4f66/IN' from 192.168.1.1 Jul 22 00:51:30 Blackbird named[1860]: resolver priming query complete Jul 22 00:51:33 Blackbird systemd[1]: systemd-hostnamed.service: Succeeded. Jul 22 00:51:33 Blackbird audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-hostnamed comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Jul 22 00:51:56 Blackbird dbus-broker-launch[2313]: Service file '/usr/share/dbus-1/services/org.mate.freedesktop.FileManager1.service' is not named after the D-Bus name 'org.freedesktop.FileManager1'. Jul 22 00:51:56 Blackbird dbus-broker-launch[2313]: Service file '/usr/share/dbus-1/services/org.mate.panel.applet.SoftupdApplet.service' is not named after the D-Bus name 'org.mate.panel.applet.SoftupdAppletFactory'. Jul 22 00:51:56 Blackbird dbus-broker-launch[2313]: Service file '/usr/share/dbus-1/services/imsettings-daemon.service' is not named after the D-Bus name 'com.redhat.imsettings'. Jul 22 00:51:56 Blackbird dbus-broker-launch[2313]: Service file '/usr/share/dbus-1/services/org.freedesktop.mate.Notifications.service' is not named after the D-Bus name 'org.freedesktop.Notifications'. Jul 22 00:51:58 Blackbird audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-hostnamed comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Jul 22 00:51:58 Blackbird named[1860]: ../../../lib/dns/rbtdb.c:10337: INSIST((rbtdb->rdatasets[header->node->locknum]).head == (header)) failed, back trace Jul 22 00:51:58 Blackbird audit[1860]: ANOM_ABEND auid=4294967295 uid=25 gid=25 ses=4294967295 pid=1860 comm="isc-worker0006" exe="/usr/sbin/named" sig=6 res=1 Jul 22 00:51:58 Blackbird named[1860]: #0 0x12f650508 in ?? Jul 22 00:51:58 Blackbird named[1860]: #1 0x7fffa8f5d978 in ?? Jul 22 00:51:58 Blackbird named[1860]: #2 0x7fffa91b2714 in ?? Jul 22 00:51:58 Blackbird named[1860]: #3 0x7fffa91b9738 in ?? Jul 22 00:51:58 Blackbird named[1860]: #4 0x7fffa91c3834 in ?? Jul 22 00:51:58 Blackbird named[1860]: #5 0x7fffa913bb90 in ?? Jul 22 00:51:58 Blackbird named[1860]: #6 0x12f6630e0 in ?? Jul 22 00:51:58 Blackbird named[1860]: #7 0x12f66c258 in ?? Jul 22 00:51:58 Blackbird named[1860]: #8 0x7fffa8f91c28 in ?? Jul 22 00:51:58 Blackbird named[1860]: #9 0x7fffa8ab8c10 in ?? Jul 22 00:51:58 Blackbird named[1860]: #10 0x7fffa86ed8a8 in ?? Jul 22 00:51:58 Blackbird named[1860]: exiting (due to assertion failure) Jul 22 00:51:59 Blackbird systemd[1]: named.service: Main process exited, code=killed, status=6/ABRT Jul 22 00:51:59 Blackbird systemd[1]: named.service: Failed with result 'signal'. Jul 22 00:51:59 Blackbird audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=named comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=failed' Jul 22 00:51:59 Blackbird systemd-coredump[2917]: Process 1860 (named) of user 25 dumped core. Jul 22 00:52:28 Blackbird systemd[1]: systemd-hostnamed.service: Succeeded. Jul 22 00:52:28 Blackbird audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-hostnamed comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Jul 22 00:53:41 Blackbird systemd[1]: named-setup-rndc.service: Succeeded. Jul 22 00:53:41 Blackbird audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=named-setup-rndc comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Jul 22 00:53:41 Blackbird audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=named-setup-rndc comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Jul 22 00:53:41 Blackbird named[3450]: starting BIND 9.11.6-P1-RedHat-9.11.6-5.P1.fc30 (Extended Support Version) <id:520073a> Jul 22 00:53:41 Blackbird named[3450]: running on Linux ppc64le 5.1.16-300.fc30.ppc64le #1 SMP Wed Jul 3 14:44:03 UTC 2019 Jul 22 00:53:41 Blackbird named[3450]: built with '--build=ppc64le-redhat-linux-gnu' '--host=ppc64le-redhat-linux-gnu' '--program-prefix=' '--disable-dependency-tracking' '--prefix=/usr' '--exec-prefix=/usr' '--bindir=/usr/bin' '--sbindir=/usr/sbin' '--sysconfdir=/etc' '--datadir=/usr/share' '--includedir=/usr/include' '--libdir=/usr/lib64' '--libexecdir=/usr/libexec' '--sharedstatedir=/var/lib' '--mandir=/usr/share/man' '--infodir=/usr/share/info' '--with-python=/usr/bin/python3' '--with-libtool' '--localstatedir=/var' '--enable-threads' '--enable-ipv6' '--enable-filter-aaaa' '--with-pic' '--disable-static' '--includedir=/usr/include/bind9' '--with-tuning=large' '--with-geoip' '--with-libidn2' '--enable-openssl-hash' '--enable-native-pkcs11' '--with-pkcs11=/usr/lib64/pkcs11/libsofthsm2.so' '--with-dlopen=yes' '--with-dlz-ldap=yes' '--with-dlz-postgres=yes' '--with-dlz-mysql=yes' '--with-dlz-filesystem=yes' '--with-dlz-bdb=yes' '--with-gssapi=yes' '--disable-isc-spnego' '--with-lmdb=yes' '--with-libjson' '--enable-dnstap' '--with-cmocka' '--enable-fixed-rrset' '--with-docbook-xsl=/usr/share/sgml/docbook/xsl-stylesheets' '--enable-full-report' 'build_alias=ppc64le-redhat-linux-gnu' 'host_alias=ppc64le-redhat-linux-gnu' 'CFLAGS= -O2 -g -pipe -Wall -Werror=format-security -Wp,-D_FORTIFY_SOURCE=2 -Wp,-D_GLIBCXX_ASSERTIONS -fexceptions -fstack-protector-strong -grecord-gcc-switches -specs=/usr/lib/rpm/redhat/redhat-hardened-cc1 -specs=/usr/lib/rpm/redhat/redhat-annobin-cc1 -m64 -mcpu=power8 -mtune=power8 -fasynchronous-unwind-tables -fstack-clash-protection' 'LDFLAGS=-Wl,-z,relro -Wl,--as-needed -Wl,-z,now -specs=/usr/lib/rpm/redhat/redhat-hardened-ld' 'CPPFLAGS= -DDIG_SIGCHASE' 'PKG_CONFIG_PATH=:/usr/lib64/pkgconfig:/usr/share/pkgconfig' Jul 22 00:53:41 Blackbird named[3450]: running as: named -u named -c /etc/named.conf Jul 22 00:53:41 Blackbird named[3450]: compiled by GCC 9.0.1 20190312 (Red Hat 9.0.1-0.10) Jul 22 00:53:41 Blackbird named[3450]: compiled with OpenSSL version: OpenSSL 1.1.1b FIPS 26 Feb 2019 Jul 22 00:53:41 Blackbird named[3450]: linked to OpenSSL version: OpenSSL 1.1.1c FIPS 28 May 2019 Jul 22 00:53:41 Blackbird named[3450]: compiled with libxml2 version: 2.9.9 Jul 22 00:53:41 Blackbird named[3450]: linked to libxml2 version: 20909 Jul 22 00:53:41 Blackbird named[3450]: compiled with libjson-c version: 0.13.1 Jul 22 00:53:41 Blackbird named[3450]: linked to libjson-c version: 0.13.1 Jul 22 00:53:41 Blackbird named[3450]: compiled with zlib version: 1.2.11 Jul 22 00:53:41 Blackbird named[3450]: linked to zlib version: 1.2.11 Jul 22 00:53:41 Blackbird named[3450]: threads support is enabled Jul 22 00:53:41 Blackbird named[3450]: ---------------------------------------------------- Jul 22 00:53:41 Blackbird named[3450]: BIND 9 is maintained by Internet Systems Consortium, Jul 22 00:53:41 Blackbird named[3450]: Inc. (ISC), a non-profit 501(c)(3) public-benefit Jul 22 00:53:41 Blackbird named[3450]: corporation. Support and training for BIND 9 are Jul 22 00:53:41 Blackbird named[3450]: available at https://www.isc.org/support Jul 22 00:53:41 Blackbird named[3450]: ---------------------------------------------------- Jul 22 00:53:41 Blackbird named[3450]: adjusted limit on open files from 524288 to 1048576 Jul 22 00:53:41 Blackbird named[3450]: found 16 CPUs, using 16 worker threads Jul 22 00:53:41 Blackbird named[3450]: using 15 UDP listeners per interface Jul 22 00:53:41 Blackbird named[3450]: using up to 21000 sockets Jul 22 00:53:41 Blackbird named[3450]: loading configuration from '/etc/named.conf' Jul 22 00:53:41 Blackbird named[3450]: unable to open '/etc/named.iscdlv.key'; using built-in keys instead Jul 22 00:53:41 Blackbird named[3450]: initializing GeoIP Country (IPv4) (type 1) DB Jul 22 00:53:41 Blackbird named[3450]: GEO-106FREE 20180327 Build 1 Copyright (c) 2018 MaxMind Inc All Rights Reserved Jul 22 00:53:41 Blackbird named[3450]: GeoIP Country (IPv6) (type 12) DB not available Jul 22 00:53:41 Blackbird named[3450]: GeoIP City (IPv4) (type 2) DB not available Jul 22 00:53:41 Blackbird named[3450]: GeoIP City (IPv4) (type 6) DB not available Jul 22 00:53:41 Blackbird named[3450]: GeoIP City (IPv6) (type 30) DB not available Jul 22 00:53:41 Blackbird named[3450]: GeoIP City (IPv6) (type 31) DB not available Jul 22 00:53:41 Blackbird named[3450]: GeoIP Region (type 3) DB not available Jul 22 00:53:41 Blackbird named[3450]: GeoIP Region (type 7) DB not available Jul 22 00:53:41 Blackbird named[3450]: GeoIP ISP (type 4) DB not available Jul 22 00:53:41 Blackbird named[3450]: GeoIP Org (type 5) DB not available Jul 22 00:53:41 Blackbird named[3450]: GeoIP AS (type 9) DB not available Jul 22 00:53:41 Blackbird named[3450]: GeoIP Domain (type 11) DB not available Jul 22 00:53:41 Blackbird named[3450]: GeoIP NetSpeed (type 10) DB not available Jul 22 00:53:41 Blackbird named[3450]: using default UDP/IPv4 port range: [32768, 60999] Jul 22 00:53:41 Blackbird named[3450]: using default UDP/IPv6 port range: [32768, 60999] Jul 22 00:53:41 Blackbird named[3450]: listening on IPv4 interface lo, 127.0.0.1#53 Jul 22 00:53:41 Blackbird named[3450]: listening on IPv4 interface ethguest, 192.168.2.1#53 Jul 22 00:53:41 Blackbird named[3450]: listening on IPv4 interface ethmain, 192.168.1.1#53 Jul 22 00:53:41 Blackbird named[3450]: generating session key for dynamic DNS Jul 22 00:53:41 Blackbird named[3450]: sizing zone task pool based on 10 zones Jul 22 00:53:41 Blackbird named[3450]: none:106: 'max-cache-size 90%' - setting to 29338MB (out of 32598MB) Jul 22 00:53:41 Blackbird named[3450]: set up managed keys zone for view _default, file '/var/named/dynamic/managed-keys.bind' Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: 10.IN-ADDR.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: 16.172.IN-ADDR.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: 17.172.IN-ADDR.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: 18.172.IN-ADDR.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: 19.172.IN-ADDR.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: 20.172.IN-ADDR.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: 21.172.IN-ADDR.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: 22.172.IN-ADDR.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: 23.172.IN-ADDR.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: 24.172.IN-ADDR.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: 25.172.IN-ADDR.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: 26.172.IN-ADDR.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: 27.172.IN-ADDR.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: 28.172.IN-ADDR.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: 29.172.IN-ADDR.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: 30.172.IN-ADDR.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: 31.172.IN-ADDR.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: 168.192.IN-ADDR.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: 64.100.IN-ADDR.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: 65.100.IN-ADDR.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: 66.100.IN-ADDR.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: 67.100.IN-ADDR.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: 68.100.IN-ADDR.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: 69.100.IN-ADDR.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: 70.100.IN-ADDR.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: 71.100.IN-ADDR.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: 72.100.IN-ADDR.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: 73.100.IN-ADDR.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: 74.100.IN-ADDR.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: 75.100.IN-ADDR.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: 76.100.IN-ADDR.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: 77.100.IN-ADDR.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: 78.100.IN-ADDR.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: 79.100.IN-ADDR.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: 80.100.IN-ADDR.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: 81.100.IN-ADDR.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: 82.100.IN-ADDR.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: 83.100.IN-ADDR.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: 84.100.IN-ADDR.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: 85.100.IN-ADDR.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: 86.100.IN-ADDR.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: 87.100.IN-ADDR.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: 88.100.IN-ADDR.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: 89.100.IN-ADDR.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: 90.100.IN-ADDR.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: 91.100.IN-ADDR.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: 92.100.IN-ADDR.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: 93.100.IN-ADDR.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: 94.100.IN-ADDR.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: 95.100.IN-ADDR.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: 96.100.IN-ADDR.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: 97.100.IN-ADDR.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: 98.100.IN-ADDR.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: 99.100.IN-ADDR.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: 100.100.IN-ADDR.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: 101.100.IN-ADDR.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: 102.100.IN-ADDR.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: 103.100.IN-ADDR.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: 104.100.IN-ADDR.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: 105.100.IN-ADDR.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: 106.100.IN-ADDR.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: 107.100.IN-ADDR.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: 108.100.IN-ADDR.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: 109.100.IN-ADDR.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: 110.100.IN-ADDR.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: 111.100.IN-ADDR.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: 112.100.IN-ADDR.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: 113.100.IN-ADDR.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: 114.100.IN-ADDR.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: 115.100.IN-ADDR.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: 116.100.IN-ADDR.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: 117.100.IN-ADDR.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: 118.100.IN-ADDR.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: 119.100.IN-ADDR.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: 120.100.IN-ADDR.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: 121.100.IN-ADDR.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: 122.100.IN-ADDR.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: 123.100.IN-ADDR.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: 124.100.IN-ADDR.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: 125.100.IN-ADDR.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: 126.100.IN-ADDR.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: 127.100.IN-ADDR.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: 127.IN-ADDR.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: 254.169.IN-ADDR.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: 2.0.192.IN-ADDR.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: 100.51.198.IN-ADDR.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: 113.0.203.IN-ADDR.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: 255.255.255.255.IN-ADDR.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: 0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.IP6.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: D.F.IP6.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: 8.E.F.IP6.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: 9.E.F.IP6.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: A.E.F.IP6.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: B.E.F.IP6.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: 8.B.D.0.1.0.0.2.IP6.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: EMPTY.AS112.ARPA Jul 22 00:53:41 Blackbird named[3450]: automatic empty zone: HOME.ARPA Jul 22 00:53:41 Blackbird named[3450]: none:106: 'max-cache-size 90%' - setting to 29338MB (out of 32598MB) Jul 22 00:53:41 Blackbird named[3450]: configuring command channel from '/etc/rndc.key' Jul 22 00:53:41 Blackbird named[3450]: command channel listening on 127.0.0.1#953 Jul 22 00:53:41 Blackbird named[3450]: configuring command channel from '/etc/rndc.key' Jul 22 00:53:41 Blackbird named[3450]: command channel listening on ::1#953 Jul 22 00:53:41 Blackbird named[3450]: managed-keys-zone: loaded serial 17 Jul 22 00:53:41 Blackbird named[3450]: zone 0.in-addr.arpa/IN: loaded serial 0 Jul 22 00:53:41 Blackbird named[3450]: zone 2.168.192.in-addr.arpa/IN: loaded serial 20171025 Jul 22 00:53:41 Blackbird named[3450]: zone localhost/IN: loaded serial 0 Jul 22 00:53:41 Blackbird named[3450]: zone 1.168.192.in-addr.arpa/IN: loaded serial 20171025 Jul 22 00:53:41 Blackbird named[3450]: zone main.hq/IN: loaded serial 20171025 Jul 22 00:53:41 Blackbird named[3450]: zone localhost.localdomain/IN: loaded serial 0 Jul 22 00:53:41 Blackbird named[3450]: zone guest.hq/IN: loaded serial 20171025 Jul 22 00:53:41 Blackbird named[3450]: zone 1.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.ip6.arpa/IN: loaded serial 0 Jul 22 00:53:41 Blackbird named[3450]: zone 1.0.0.127.in-addr.arpa/IN: loaded serial 0 Jul 22 00:53:41 Blackbird named[3450]: all zones loaded Jul 22 00:53:41 Blackbird named[3450]: running Jul 22 00:53:41 Blackbird audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=named comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Jul 22 00:53:41 Blackbird named[3450]: network unreachable resolving './NS/IN': 2001:503:ba3e::2:30#53 Jul 22 00:53:41 Blackbird named[3450]: network unreachable resolving './NS/IN': 2001:7fe::53#53 Jul 22 00:53:41 Blackbird named[3450]: network unreachable resolving './NS/IN': 2001:500:9f::42#53 Jul 22 00:53:41 Blackbird named[3450]: network unreachable resolving './NS/IN': 2001:500:1::53#53 Jul 22 00:53:41 Blackbird named[3450]: network unreachable resolving './NS/IN': 2001:500:a8::e#53 Jul 22 00:53:41 Blackbird named[3450]: network unreachable resolving './NS/IN': 2001:503:c27::2:30#53 Jul 22 00:53:41 Blackbird named[3450]: network unreachable resolving './NS/IN': 2001:500:2d::d#53 Jul 22 00:53:41 Blackbird named[3450]: network unreachable resolving './NS/IN': 2001:7fd::1#53 Jul 22 00:53:41 Blackbird named[3450]: network unreachable resolving './NS/IN': 2001:500:2::c#53 Jul 22 00:53:41 Blackbird named[3450]: network unreachable resolving './NS/IN': 2001:500:12::d0d#53 Jul 22 00:53:41 Blackbird named[3450]: network unreachable resolving './NS/IN': 2001:500:2f::f#53 Jul 22 00:53:41 Blackbird named[3450]: network unreachable resolving './NS/IN': 2001:dc3::35#53 Jul 22 00:53:41 Blackbird named[3450]: network unreachable resolving './NS/IN': 2001:500:200::b#53 Jul 22 00:53:41 Blackbird named[3450]: managed-keys-zone: Key 20326 for zone . acceptance timer complete: key now trusted Jul 22 00:53:41 Blackbird named[3450]: resolver priming query complete Jul 22 00:58:33 Blackbird dbus-broker-launch[2313]: Service file '/usr/share/dbus-1/services/org.mate.freedesktop.FileManager1.service' is not named after the D-Bus name 'org.freedesktop.FileManager1'. Jul 22 00:58:33 Blackbird dbus-broker-launch[2313]: Service file '/usr/share/dbus-1/services/org.mate.panel.applet.SoftupdApplet.service' is not named after the D-Bus name 'org.mate.panel.applet.SoftupdAppletFactory'. Jul 22 00:58:33 Blackbird dbus-broker-launch[2313]: Service file '/usr/share/dbus-1/services/imsettings-daemon.service' is not named after the D-Bus name 'com.redhat.imsettings'. Jul 22 00:58:33 Blackbird dbus-broker-launch[2313]: Service file '/usr/share/dbus-1/services/org.freedesktop.mate.Notifications.service' is not named after the D-Bus name 'org.freedesktop.Notifications'. Jul 22 00:59:31 Blackbird dbus-broker-launch[2313]: Service file '/usr/share/dbus-1/services/org.mate.freedesktop.FileManager1.service' is not named after the D-Bus name 'org.freedesktop.FileManager1'. Jul 22 00:59:31 Blackbird dbus-broker-launch[2313]: Service file '/usr/share/dbus-1/services/org.mate.panel.applet.SoftupdApplet.service' is not named after the D-Bus name 'org.mate.panel.applet.SoftupdAppletFactory'. Jul 22 00:59:31 Blackbird dbus-broker-launch[2313]: Service file '/usr/share/dbus-1/services/imsettings-daemon.service' is not named after the D-Bus name 'com.redhat.imsettings'. Jul 22 00:59:31 Blackbird dbus-broker-launch[2313]: Service file '/usr/share/dbus-1/services/org.freedesktop.mate.Notifications.service' is not named after the D-Bus name 'org.freedesktop.Notifications'. Jul 22 00:59:31 Blackbird dbus-broker-launch[2313]: Service file '/usr/share/dbus-1/services/org.mate.freedesktop.FileManager1.service' is not named after the D-Bus name 'org.freedesktop.FileManager1'. Jul 22 00:59:31 Blackbird dbus-broker-launch[2313]: Service file '/usr/share/dbus-1/services/org.mate.panel.applet.SoftupdApplet.service' is not named after the D-Bus name 'org.mate.panel.applet.SoftupdAppletFactory'. Jul 22 00:59:31 Blackbird dbus-broker-launch[2313]: Service file '/usr/share/dbus-1/services/imsettings-daemon.service' is not named after the D-Bus name 'com.redhat.imsettings'. Jul 22 00:59:31 Blackbird dbus-broker-launch[2313]: Service file '/usr/share/dbus-1/services/org.freedesktop.mate.Notifications.service' is not named after the D-Bus name 'org.freedesktop.Notifications'. Jul 22 00:59:31 Blackbird dbus-broker-launch[2313]: Service file '/usr/share/dbus-1/services/org.mate.freedesktop.FileManager1.service' is not named after the D-Bus name 'org.freedesktop.FileManager1'. Jul 22 00:59:31 Blackbird dbus-broker-launch[2313]: Service file '/usr/share/dbus-1/services/org.mate.panel.applet.SoftupdApplet.service' is not named after the D-Bus name 'org.mate.panel.applet.SoftupdAppletFactory'. Jul 22 00:59:31 Blackbird dbus-broker-launch[2313]: Service file '/usr/share/dbus-1/services/imsettings-daemon.service' is not named after the D-Bus name 'com.redhat.imsettings'. Jul 22 00:59:31 Blackbird dbus-broker-launch[2313]: Service file '/usr/share/dbus-1/services/org.freedesktop.mate.Notifications.service' is not named after the D-Bus name 'org.freedesktop.Notifications'. Jul 22 01:00:16 Blackbird named[3450]: received control channel command 'stop' Jul 22 01:00:16 Blackbird named[3450]: shutting down: flushing changes Jul 22 01:00:16 Blackbird named[3450]: stopping command channel on 127.0.0.1#953 Jul 22 01:00:16 Blackbird named[3450]: stopping command channel on ::1#953 Jul 22 01:00:16 Blackbird named[3450]: no longer listening on 127.0.0.1#53 Jul 22 01:00:16 Blackbird named[3450]: no longer listening on 192.168.2.1#53 Jul 22 01:00:16 Blackbird named[3450]: no longer listening on 192.168.1.1#53 Jul 22 01:00:16 Blackbird named[3450]: exiting Jul 22 01:00:16 Blackbird systemd[1]: named.service: Succeeded. Jul 22 01:00:16 Blackbird audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=named comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Jul 22 01:00:16 Blackbird systemd[1]: named-setup-rndc.service: Succeeded. Jul 22 01:00:16 Blackbird audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=named-setup-rndc comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Jul 22 01:00:16 Blackbird audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=named-setup-rndc comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Jul 22 01:00:16 Blackbird named[18917]: starting BIND 9.11.8-RedHat-9.11.8-1.fc30 (Extended Support Version) <id:8d5d82d> Jul 22 01:00:16 Blackbird named[18917]: running on Linux ppc64le 5.1.16-300.fc30.ppc64le #1 SMP Wed Jul 3 14:44:03 UTC 2019 Jul 22 01:00:16 Blackbird named[18917]: built with '--build=ppc64le-redhat-linux-gnu' '--host=ppc64le-redhat-linux-gnu' '--program-prefix=' '--disable-dependency-tracking' '--prefix=/usr' '--exec-prefix=/usr' '--bindir=/usr/bin' '--sbindir=/usr/sbin' '--sysconfdir=/etc' '--datadir=/usr/share' '--includedir=/usr/include' '--libdir=/usr/lib64' '--libexecdir=/usr/libexec' '--sharedstatedir=/var/lib' '--mandir=/usr/share/man' '--infodir=/usr/share/info' '--with-python=/usr/bin/python3' '--with-libtool' '--localstatedir=/var' '--enable-threads' '--enable-ipv6' '--enable-filter-aaaa' '--with-pic' '--disable-static' '--includedir=/usr/include/bind9' '--with-tuning=large' '--with-geoip' '--with-libidn2' '--enable-openssl-hash' '--enable-native-pkcs11' '--with-pkcs11=/usr/lib64/pkcs11/libsofthsm2.so' '--with-dlopen=yes' '--with-dlz-ldap=yes' '--with-dlz-postgres=yes' '--with-dlz-mysql=yes' '--with-dlz-filesystem=yes' '--with-dlz-bdb=yes' '--with-gssapi=yes' '--disable-isc-spnego' '--with-lmdb=yes' '--with-libjson' '--enable-dnstap' '--with-cmocka' '--enable-fixed-rrset' '--with-docbook-xsl=/usr/share/sgml/docbook/xsl-stylesheets' '--enable-full-report' 'build_alias=ppc64le-redhat-linux-gnu' 'host_alias=ppc64le-redhat-linux-gnu' 'CFLAGS= -O2 -g -pipe -Wall -Werror=format-security -Wp,-D_FORTIFY_SOURCE=2 -Wp,-D_GLIBCXX_ASSERTIONS -fexceptions -fstack-protector-strong -grecord-gcc-switches -specs=/usr/lib/rpm/redhat/redhat-hardened-cc1 -specs=/usr/lib/rpm/redhat/redhat-annobin-cc1 -m64 -mcpu=power8 -mtune=power8 -fasynchronous-unwind-tables -fstack-clash-protection' 'LDFLAGS=-Wl,-z,relro -Wl,--as-needed -Wl,-z,now -specs=/usr/lib/rpm/redhat/redhat-hardened-ld' 'CPPFLAGS= -DDIG_SIGCHASE' 'PKG_CONFIG_PATH=:/usr/lib64/pkgconfig:/usr/share/pkgconfig' Jul 22 01:00:16 Blackbird named[18917]: running as: named -u named -c /etc/named.conf Jul 22 01:00:16 Blackbird named[18917]: compiled by GCC 9.1.1 20190503 (Red Hat 9.1.1-1) Jul 22 01:00:16 Blackbird named[18917]: compiled with OpenSSL version: OpenSSL 1.1.1c FIPS 28 May 2019 Jul 22 01:00:16 Blackbird named[18917]: linked to OpenSSL version: OpenSSL 1.1.1c FIPS 28 May 2019 Jul 22 01:00:16 Blackbird named[18917]: compiled with libxml2 version: 2.9.9 Jul 22 01:00:16 Blackbird named[18917]: linked to libxml2 version: 20909 Jul 22 01:00:16 Blackbird named[18917]: compiled with libjson-c version: 0.13.1 Jul 22 01:00:16 Blackbird named[18917]: linked to libjson-c version: 0.13.1 Jul 22 01:00:16 Blackbird named[18917]: compiled with zlib version: 1.2.11 Jul 22 01:00:16 Blackbird named[18917]: linked to zlib version: 1.2.11 Jul 22 01:00:16 Blackbird named[18917]: threads support is enabled Jul 22 01:00:16 Blackbird named[18917]: ---------------------------------------------------- Jul 22 01:00:16 Blackbird named[18917]: BIND 9 is maintained by Internet Systems Consortium, Jul 22 01:00:16 Blackbird named[18917]: Inc. (ISC), a non-profit 501(c)(3) public-benefit Jul 22 01:00:16 Blackbird named[18917]: corporation. Support and training for BIND 9 are Jul 22 01:00:16 Blackbird named[18917]: available at https://www.isc.org/support Jul 22 01:00:16 Blackbird named[18917]: ---------------------------------------------------- Jul 22 01:00:16 Blackbird named[18917]: adjusted limit on open files from 524288 to 1048576 Jul 22 01:00:16 Blackbird named[18917]: found 16 CPUs, using 16 worker threads Jul 22 01:00:16 Blackbird named[18917]: using 15 UDP listeners per interface Jul 22 01:00:16 Blackbird named[18917]: using up to 21000 sockets Jul 22 01:00:16 Blackbird named[18917]: loading configuration from '/etc/named.conf' Jul 22 01:00:16 Blackbird named[18917]: reading built-in trust anchors from file '/etc/named.root.key' Jul 22 01:00:16 Blackbird named[18917]: initializing GeoIP Country (IPv4) (type 1) DB Jul 22 01:00:16 Blackbird named[18917]: GEO-106FREE 20180327 Build 1 Copyright (c) 2018 MaxMind Inc All Rights Reserved Jul 22 01:00:16 Blackbird named[18917]: GeoIP Country (IPv6) (type 12) DB not available Jul 22 01:00:16 Blackbird named[18917]: GeoIP City (IPv4) (type 2) DB not available Jul 22 01:00:16 Blackbird named[18917]: GeoIP City (IPv4) (type 6) DB not available Jul 22 01:00:16 Blackbird named[18917]: GeoIP City (IPv6) (type 30) DB not available Jul 22 01:00:16 Blackbird named[18917]: GeoIP City (IPv6) (type 31) DB not available Jul 22 01:00:16 Blackbird named[18917]: GeoIP Region (type 3) DB not available Jul 22 01:00:16 Blackbird named[18917]: GeoIP Region (type 7) DB not available Jul 22 01:00:16 Blackbird named[18917]: GeoIP ISP (type 4) DB not available Jul 22 01:00:16 Blackbird named[18917]: GeoIP Org (type 5) DB not available Jul 22 01:00:16 Blackbird named[18917]: GeoIP AS (type 9) DB not available Jul 22 01:00:16 Blackbird named[18917]: GeoIP Domain (type 11) DB not available Jul 22 01:00:16 Blackbird named[18917]: GeoIP NetSpeed (type 10) DB not available Jul 22 01:00:16 Blackbird named[18917]: using default UDP/IPv4 port range: [32768, 60999] Jul 22 01:00:16 Blackbird named[18917]: using default UDP/IPv6 port range: [32768, 60999] Jul 22 01:00:16 Blackbird named[18917]: listening on IPv4 interface lo, 127.0.0.1#53 Jul 22 01:00:16 Blackbird named[18917]: listening on IPv4 interface ethguest, 192.168.2.1#53 Jul 22 01:00:16 Blackbird named[18917]: listening on IPv4 interface ethmain, 192.168.1.1#53 Jul 22 01:00:16 Blackbird named[18917]: generating session key for dynamic DNS Jul 22 01:00:16 Blackbird named[18917]: sizing zone task pool based on 10 zones Jul 22 01:00:16 Blackbird named[18917]: none:106: 'max-cache-size 90%' - setting to 29338MB (out of 32598MB) Jul 22 01:00:16 Blackbird named[18917]: set up managed keys zone for view _default, file '/var/named/dynamic/managed-keys.bind' Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: 10.IN-ADDR.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: 16.172.IN-ADDR.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: 17.172.IN-ADDR.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: 18.172.IN-ADDR.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: 19.172.IN-ADDR.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: 20.172.IN-ADDR.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: 21.172.IN-ADDR.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: 22.172.IN-ADDR.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: 23.172.IN-ADDR.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: 24.172.IN-ADDR.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: 25.172.IN-ADDR.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: 26.172.IN-ADDR.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: 27.172.IN-ADDR.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: 28.172.IN-ADDR.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: 29.172.IN-ADDR.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: 30.172.IN-ADDR.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: 31.172.IN-ADDR.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: 168.192.IN-ADDR.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: 64.100.IN-ADDR.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: 65.100.IN-ADDR.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: 66.100.IN-ADDR.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: 67.100.IN-ADDR.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: 68.100.IN-ADDR.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: 69.100.IN-ADDR.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: 70.100.IN-ADDR.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: 71.100.IN-ADDR.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: 72.100.IN-ADDR.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: 73.100.IN-ADDR.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: 74.100.IN-ADDR.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: 75.100.IN-ADDR.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: 76.100.IN-ADDR.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: 77.100.IN-ADDR.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: 78.100.IN-ADDR.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: 79.100.IN-ADDR.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: 80.100.IN-ADDR.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: 81.100.IN-ADDR.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: 82.100.IN-ADDR.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: 83.100.IN-ADDR.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: 84.100.IN-ADDR.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: 85.100.IN-ADDR.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: 86.100.IN-ADDR.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: 87.100.IN-ADDR.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: 88.100.IN-ADDR.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: 89.100.IN-ADDR.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: 90.100.IN-ADDR.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: 91.100.IN-ADDR.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: 92.100.IN-ADDR.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: 93.100.IN-ADDR.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: 94.100.IN-ADDR.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: 95.100.IN-ADDR.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: 96.100.IN-ADDR.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: 97.100.IN-ADDR.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: 98.100.IN-ADDR.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: 99.100.IN-ADDR.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: 100.100.IN-ADDR.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: 101.100.IN-ADDR.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: 102.100.IN-ADDR.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: 103.100.IN-ADDR.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: 104.100.IN-ADDR.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: 105.100.IN-ADDR.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: 106.100.IN-ADDR.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: 107.100.IN-ADDR.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: 108.100.IN-ADDR.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: 109.100.IN-ADDR.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: 110.100.IN-ADDR.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: 111.100.IN-ADDR.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: 112.100.IN-ADDR.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: 113.100.IN-ADDR.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: 114.100.IN-ADDR.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: 115.100.IN-ADDR.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: 116.100.IN-ADDR.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: 117.100.IN-ADDR.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: 118.100.IN-ADDR.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: 119.100.IN-ADDR.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: 120.100.IN-ADDR.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: 121.100.IN-ADDR.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: 122.100.IN-ADDR.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: 123.100.IN-ADDR.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: 124.100.IN-ADDR.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: 125.100.IN-ADDR.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: 126.100.IN-ADDR.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: 127.100.IN-ADDR.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: 127.IN-ADDR.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: 254.169.IN-ADDR.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: 2.0.192.IN-ADDR.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: 100.51.198.IN-ADDR.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: 113.0.203.IN-ADDR.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: 255.255.255.255.IN-ADDR.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: 0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.IP6.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: D.F.IP6.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: 8.E.F.IP6.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: 9.E.F.IP6.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: A.E.F.IP6.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: B.E.F.IP6.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: 8.B.D.0.1.0.0.2.IP6.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: EMPTY.AS112.ARPA Jul 22 01:00:16 Blackbird named[18917]: automatic empty zone: HOME.ARPA Jul 22 01:00:16 Blackbird named[18917]: none:106: 'max-cache-size 90%' - setting to 29338MB (out of 32598MB) Jul 22 01:00:16 Blackbird named[18917]: configuring command channel from '/etc/rndc.key' Jul 22 01:00:16 Blackbird named[18917]: command channel listening on 127.0.0.1#953 Jul 22 01:00:16 Blackbird named[18917]: configuring command channel from '/etc/rndc.key' Jul 22 01:00:16 Blackbird named[18917]: command channel listening on ::1#953 Jul 22 01:00:16 Blackbird named[18917]: managed-keys-zone: journal file is out of date: removing journal file Jul 22 01:00:16 Blackbird named[18917]: managed-keys-zone: loaded serial 18 Jul 22 01:00:16 Blackbird named[18917]: zone 0.in-addr.arpa/IN: loaded serial 0 Jul 22 01:00:16 Blackbird named[18917]: zone 1.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.ip6.arpa/IN: loaded serial 0 Jul 22 01:00:16 Blackbird named[18917]: zone 1.168.192.in-addr.arpa/IN: loaded serial 20171025 Jul 22 01:00:16 Blackbird named[18917]: zone 2.168.192.in-addr.arpa/IN: loaded serial 20171025 Jul 22 01:00:16 Blackbird named[18917]: zone 1.0.0.127.in-addr.arpa/IN: loaded serial 0 Jul 22 01:00:16 Blackbird named[18917]: zone localhost/IN: loaded serial 0 Jul 22 01:00:16 Blackbird named[18917]: zone guest.hq/IN: loaded serial 20171025 Jul 22 01:00:16 Blackbird named[18917]: zone main.hq/IN: loaded serial 20171025 Jul 22 01:00:16 Blackbird named[18917]: zone localhost.localdomain/IN: loaded serial 0 Jul 22 01:00:16 Blackbird named[18917]: all zones loaded Jul 22 01:00:16 Blackbird named[18917]: running Jul 22 01:00:16 Blackbird named[18917]: network unreachable resolving './NS/IN': 2001:500:9f::42#53 Jul 22 01:00:16 Blackbird audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=named comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Jul 22 01:00:16 Blackbird named[18917]: network unreachable resolving './NS/IN': 2001:503:c27::2:30#53 Jul 22 01:00:16 Blackbird named[18917]: network unreachable resolving './NS/IN': 2001:500:2d::d#53 Jul 22 01:00:16 Blackbird named[18917]: network unreachable resolving './NS/IN': 2001:7fe::53#53 Jul 22 01:00:16 Blackbird named[18917]: network unreachable resolving './NS/IN': 2001:500:1::53#53 Jul 22 01:00:16 Blackbird named[18917]: network unreachable resolving './NS/IN': 2001:500:2f::f#53 Jul 22 01:00:16 Blackbird named[18917]: network unreachable resolving './NS/IN': 2001:503:ba3e::2:30#53 Jul 22 01:00:16 Blackbird named[18917]: network unreachable resolving './NS/IN': 2001:dc3::35#53 Jul 22 01:00:16 Blackbird named[18917]: network unreachable resolving './NS/IN': 2001:500:a8::e#53 Jul 22 01:00:16 Blackbird named[18917]: network unreachable resolving './NS/IN': 2001:7fd::1#53 Jul 22 01:00:16 Blackbird named[18917]: network unreachable resolving './NS/IN': 2001:500:12::d0d#53 Jul 22 01:00:16 Blackbird named[18917]: network unreachable resolving './NS/IN': 2001:500:200::b#53 Jul 22 01:00:16 Blackbird named[18917]: network unreachable resolving './NS/IN': 2001:500:2::c#53 Jul 22 01:00:16 Blackbird named[18917]: managed-keys-zone: Key 20326 for zone . acceptance timer complete: key now trusted Jul 22 01:00:16 Blackbird named[18917]: resolver priming query complete Jul 22 01:01:13 Blackbird named[18917]: received control channel command 'stop' Jul 22 01:01:13 Blackbird named[18917]: shutting down: flushing changes Jul 22 01:01:13 Blackbird named[18917]: stopping command channel on 127.0.0.1#953 Jul 22 01:01:13 Blackbird named[18917]: stopping command channel on ::1#953 Jul 22 01:01:13 Blackbird named[18917]: no longer listening on 127.0.0.1#53 Jul 22 01:01:13 Blackbird named[18917]: no longer listening on 192.168.2.1#53 Jul 22 01:01:13 Blackbird named[18917]: no longer listening on 192.168.1.1#53 Jul 22 01:01:13 Blackbird named[18917]: exiting Jul 22 01:01:13 Blackbird systemd[1]: named.service: Succeeded. Jul 22 01:01:13 Blackbird audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=named comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Jul 22 01:03:03 Blackbird named[1917]: network unreachable resolving './NS/IN': 2001:dc3::35#53 Jul 22 01:03:03 Blackbird named[1917]: network unreachable resolving './NS/IN': 2001:503:ba3e::2:30#53 Jul 22 01:03:03 Blackbird named[1917]: network unreachable resolving './NS/IN': 2001:500:a8::e#53 Jul 22 01:03:03 Blackbird named[1917]: network unreachable resolving './NS/IN': 2001:7fe::53#53 Jul 22 01:03:03 Blackbird named[1917]: network unreachable resolving './NS/IN': 2001:7fd::1#53 Jul 22 01:03:03 Blackbird named[1917]: network unreachable resolving './NS/IN': 2001:500:12::d0d#53 Jul 22 01:03:03 Blackbird named[1917]: network unreachable resolving './NS/IN': 2001:503:c27::2:30#53 Jul 22 01:03:03 Blackbird named[1917]: network unreachable resolving './NS/IN': 2001:500:9f::42#53 Jul 22 01:03:03 Blackbird named[1917]: network unreachable resolving './NS/IN': 2001:500:2::c#53 Jul 22 01:03:03 Blackbird named[1917]: network unreachable resolving './NS/IN': 2001:500:200::b#53 Jul 22 01:03:03 Blackbird named[1917]: network unreachable resolving './NS/IN': 2001:500:2f::f#53 Jul 22 01:03:03 Blackbird named[1917]: network unreachable resolving './NS/IN': 2001:500:1::53#53 Jul 22 01:03:03 Blackbird named[1917]: network unreachable resolving './NS/IN': 2001:500:2d::d#53 Jul 22 01:03:03 Blackbird named[1917]: trust-anchor-telemetry '_ta-4f66/IN' from 192.168.1.1 Jul 22 01:03:03 Blackbird named[1917]: trust-anchor-telemetry '_ta-4f66/IN' from 192.168.1.1 Jul 22 01:03:03 Blackbird named[1917]: trust-anchor-telemetry '_ta-4f66/IN' from 192.168.1.1 Jul 22 01:03:03 Blackbird named[1917]: resolver priming query complete Jul 22 01:03:07 Blackbird systemd[1]: systemd-hostnamed.service: Succeeded. Jul 22 01:03:07 Blackbird audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-hostnamed comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Jul 22 01:04:16 Blackbird dbus-broker-launch[2379]: Service file '/usr/share/dbus-1/services/org.mate.freedesktop.FileManager1.service' is not named after the D-Bus name 'org.freedesktop.FileManager1'. Jul 22 01:04:16 Blackbird dbus-broker-launch[2379]: Service file '/usr/share/dbus-1/services/org.mate.panel.applet.SoftupdApplet.service' is not named after the D-Bus name 'org.mate.panel.applet.SoftupdAppletFactory'. Jul 22 01:04:16 Blackbird dbus-broker-launch[2379]: Service file '/usr/share/dbus-1/services/imsettings-daemon.service' is not named after the D-Bus name 'com.redhat.imsettings'. Jul 22 01:04:16 Blackbird dbus-broker-launch[2379]: Service file '/usr/share/dbus-1/services/org.freedesktop.mate.Notifications.service' is not named after the D-Bus name 'org.freedesktop.Notifications'. Jul 22 01:04:17 Blackbird audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-hostnamed comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Jul 22 01:04:47 Blackbird systemd[1]: systemd-hostnamed.service: Succeeded. Jul 22 01:04:47 Blackbird audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-hostnamed comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Unfortunately, for the first time since I've been doing week long trial runs of the blackbird as my new home server, bind didn't crash last night and appears to be going strong. Should I try leaving it on the "crashing" bind for a second night? I'd rather the home server use the recompiled bind, but if it helps...
for the record - https://gitlab.isc.org/isc-projects/bind9/commit/99056063905a9273ec59cf477ae747e0490182b7 is the commit the Debian report talks about for the 9_11 branch
in https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=778720#97
(In reply to Dan Horák from comment #6) > for the record - > https://gitlab.isc.org/isc-projects/bind9/commit/ > 99056063905a9273ec59cf477ae747e0490182b7 is the commit the Debian report > talks about for the 9_11 branch That commit was included in v9_11_3b1 and is already included in all Fedora versions. I think Debian bug mentions it as a fix. We have here different platform and maybe broken stdatomics used. I cannot include it since it already is included. Is it possible GCC's stdatomic is broken? There is minor chance Fedora patch might affect stability, since it does not use exact upstream way to avoid multilib conflicts in devel headers. I will check it. Anyway, it seems this issue has to be only ppc64le related. Hope some unit tests can prove failures quickly. Unfortunately, no recent fixes mentioned atomic. It seems every other architecture but ppc64le works just fine with very same configuration.
Strange, I modified atomic_test to include parts of stdatomic and running it on ppc64le machine. So far no failure at all. ppc64le has no other support, but stdatomics detected by configure (define ISC_PLATFORM_HAVESTDATOMIC).
Created attachment 1608301 [details] atomic_test modification
Mick identified some old Windows crash in rbt in BIND 9.10.4-P1. It seems it might be related to our issue. I have identified it as upstream commit [1]. Nothing directly there. But when looked a bit around, I have noticed older RHEL8 builds of the same version had ISC_PLATFORM_HAVEATOMICSTORE defined in /usr/include/bind9/isc/platform.h on ppc64. The save version has this undefined on ppc64le. It is not clear if it has to be this way, seems more platform detection issue. It is detected only on build time. Even more strange is this is mentioned in the first comment. --disable-atomic forces this option off. It was mentioned it helps. But according to generated platform.h, it should be already turned off! There are more defines related to locking and atomics. Maybe some parts are not in supported combination. On last Fedora rebuild, only ISC_PLATFORM_HAVESTDATOMIC was set. That might be difference, why it more often failed on ppc64le. 1. https://gitlab.isc.org/isc-projects/bind9/commit/027efd2c5be7fd6a6d0e64650b0c0b56cc1c3395
Created attachment 1630395 [details] Core dump of the crash Current version of bind installed. Installed Packages bind.ppc64le 32:9.11.11-1.fc30 @updates bind-dnssec-utils.ppc64le 32:9.11.11-1.fc30 @updates bind-export-libs.ppc64le 32:9.11.11-1.fc30 @updates bind-libs.ppc64le 32:9.11.11-1.fc30 @updates bind-libs-lite.ppc64le 32:9.11.11-1.fc30 @updates bind-license.noarch 32:9.11.11-1.fc30 @updates bind-utils.ppc64le 32:9.11.11-1.fc30 @updates
Finally managed to get a core dump of the crash as it happens naturally.
Thank you! Now just to be find the reason. (gdb) info threads Id Target Id Frame * 1 Thread 0x7fffa381f070 (LWP 29793) 0x00007fffa5d64134 in update_header (header=header@entry=0x7fff9969f010, now=<optimized out>, rbtdb=<optimized out>, rbtdb=<optimized out>) at ../../../lib/dns/rbtdb.c:10321 2 Thread 0x7fffa07bf070 (LWP 29799) 0x00007fffa567144c in pthread_cond_wait@@GLIBC_2.17 () from /lib64/libpthread.so.0 3 Thread 0x7fff9c73f070 (LWP 29807) 0x00007fffa5dd1c38 in dns_rdata_freestruct (source=0x7fff9c73e258) at ../../../lib/dns/rdata.c:1220 4 Thread 0x7fffa27ff070 (LWP 29795) 0x00007fffa567144c in pthread_cond_wait@@GLIBC_2.17 () from /lib64/libpthread.so.0 5 Thread 0x7fffa300f070 (LWP 29794) 0x00007fffa56766a8 in __lll_lock_wait () from /lib64/libpthread.so.0 6 Thread 0x7fff9d75f070 (LWP 29805) 0x00007fffa56766a8 in __lll_lock_wait () from /lib64/libpthread.so.0 7 Thread 0x7fffa17df070 (LWP 29797) 0x00007fffa5676658 in __lll_lock_wait () from /lib64/libpthread.so.0 8 Thread 0x7fff9e77f070 (LWP 29803) 0x00007fffa567144c in pthread_cond_wait@@GLIBC_2.17 () from /lib64/libpthread.so.0 9 Thread 0x7fff9aedf070 (LWP 29810) 0x00007fffa529f968 in epoll_wait () from /lib64/libc.so.6 10 Thread 0x7fffa0fcf070 (LWP 29798) 0x00007fffa567144c in pthread_cond_wait@@GLIBC_2.17 () from /lib64/libpthread.so.0 11 Thread 0x7fff9f79f070 (LWP 29801) 0x00007fffa567144c in pthread_cond_wait@@GLIBC_2.17 () from /lib64/libpthread.so.0 12 Thread 0x7fff9df6f070 (LWP 29804) 0x00007fffa567144c in pthread_cond_wait@@GLIBC_2.17 () from /lib64/libpthread.so.0 13 Thread 0x7fff9cf4f070 (LWP 29806) 0x00007fffa5676658 in __lll_lock_wait () from /lib64/libpthread.so.0 14 Thread 0x7fff9ef8f070 (LWP 29802) 0x00007fffa5676658 in __lll_lock_wait () from /lib64/libpthread.so.0 15 Thread 0x7fff9bf2f070 (LWP 29808) 0x00007fffa5676658 in __lll_lock_wait () from /lib64/libpthread.so.0 16 Thread 0x7fff9b71f070 (LWP 29809) 0x00007fffa5671b14 in pthread_cond_timedwait@@GLIBC_2.17 () from /lib64/libpthread.so.0 17 Thread 0x7fffa1fef070 (LWP 29796) 0x00007fffa5676658 in __lll_lock_wait () from /lib64/libpthread.so.0 18 Thread 0x7fff9ffaf070 (LWP 29800) 0x00007fffa5676658 in __lll_lock_wait () from /lib64/libpthread.so.0 19 Thread 0x7fffa603dd60 (LWP 29792) 0x00007fffa51b2b8c in sigsuspend () from /lib64/libc.so.6 (gdb) bt #0 0x00007fffa51b2668 in raise () from /lib64/libc.so.6 #1 0x00007fffa519468c in abort () from /lib64/libc.so.6 #2 0x0000000105810cf4 in assertion_failed (file=<optimized out>, line=<optimized out>, type=<optimized out>, cond=<optimized out>) at ../../../bin/named/main.c:234 #3 0x00007fffa5b0db68 in isc_assertion_failed (file=<optimized out>, line=<optimized out>, type=<optimized out>, cond=<optimized out>) at ../../../lib/isc/assertions.c:51 #4 0x00007fffa5d64134 in update_header (header=header@entry=0x7fff9969f010, now=<optimized out>, rbtdb=<optimized out>, rbtdb=<optimized out>) at ../../../lib/dns/rbtdb.c:10321 #5 0x00007fffa5d6b178 in find_deepest_zonecut (search=0x7fffa381bbd8, node=0x7fff9969a010, nodep=0x7fffa381c940, foundname=0x7fff99c38150, rdataset=0x7fff99c3c5c0, sigrdataset=0x0) at ../../../lib/dns/rbtdb.c:4878 #6 0x00007fffa5d752a4 in cache_find (db=<optimized out>, name=<optimized out>, version=<optimized out>, type=<optimized out>, options=<optimized out>, now=<optimized out>, nodep=0x7fffa381c940, foundname=0x7fff99c38150, rdataset=<optimized out>, sigrdataset=<optimized out>) at ../../../lib/dns/rbtdb.c:5087 #7 0x00007fffa5cebb40 in dns_db_findext (db=0x7fff99694010, name=0x7fff99c381f0, version=0x0, type=<optimized out>, options=<optimized out>, now=<optimized out>, nodep=0x7fffa381c940, foundname=<optimized out>, methods=0x7fffa381ca58, clientinfo=0x7fffa381ca88, rdataset=0x7fff99c3c5c0, sigrdataset=0x0) at ../../../lib/dns/db.c:594 #8 0x00000001058238b0 in query_find (client=<optimized out>, event=<optimized out>, event@entry=0x0, qtype=qtype@entry=1) at ../../../bin/named/query.c:7274 #9 0x000000010582dfb4 in ns_query_start (client=0x7fff9425fc70) at ../../../bin/named/query.c:9672 #10 0x00000001058022c0 in client_request (task=<optimized out>, event=<optimized out>) at ../../../bin/named/client.c:3093 #11 0x00007fffa5b42068 in dispatch (manager=0x7fffa3825010) at ../../../lib/isc/task.c:1143 #12 run (uap=0x7fffa3825010) at ../../../lib/isc/task.c:1315 #13 0x00007fffa56688c8 in start_thread () from /lib64/libpthread.so.0 #14 0x00007fffa529f498 in clone () from /lib64/libc.so.6 (gdb) frame 4 #4 0x00007fffa5d64134 in update_header (header=header@entry=0x7fff9969f010, now=<optimized out>, rbtdb=<optimized out>, rbtdb=<optimized out>) at ../../../lib/dns/rbtdb.c:10321 10321 ISC_LIST_PREPEND(rbtdb->rdatasets[header->node->locknum], header, link); (gdb) p *header $5 = { serial = 1, rdh_ttl = 1572743778, type = 2, attributes = 576, trust = 7, noqname = 0x0, closest = 0x0, is_mmapped = 0, next_is_relative = 0, node_is_relative = 0, resign_lsb = 0, next = 0x0, down = 0x0, count = 35628, additional_auth = 0x0, additional_glue = 0x0, node = 0x7fff9969a010, last_used = 1572401902, link = { prev = 0x7fff9969d380, next = 0x7fff996b4bb0 }, heap_index = 8, resign = 0, upper = '\000' <repeats 31 times> }
Ok, there must be something wrong with locks in place. update_header unlinks header and reinserts it into beginning of the structure. But in frame 4, header->link appears to be linked already, which it should not be. (gdb) p header->link $21 = { prev = 0x7fff9969d380, next = 0x7fff996b4bb0 } but according to node lock in frame 5, it should be locked. (gdb) ptype lock type = struct isc_rwlock { unsigned int magic; isc_mutex_t lock; int32_t spins; atomic_int_fast32_t write_requests; atomic_int_fast32_t write_completions; atomic_int_fast32_t cnt_and_flag; isc_condition_t readable; isc_condition_t writeable; unsigned int readers_waiting; unsigned int write_granted; unsigned int write_quota; } * (gdb) p *lock $28 = { magic = 1381452907, lock = { __data = { __lock = 0, __count = 0, __owner = 0, __nusers = 3, __kind = 3, __spins = 9, __elision = 0, __list = { __prev = 0x0, __next = 0x0 } }, __size = '\000' <repeats 12 times>, "\003\000\000\000\003\000\000\000\t", '\000' <repeats 18 times>, __align = 0 }, spins = 8, write_requests = 99, write_completions = 98, cnt_and_flag = 1, readable = { __data = { { __wseq = 30, __wseq32 = { __low = 30, __high = 0 } }, { __g1_start = 22, __g1_start32 = { __low = 22, __high = 0 } }, __g_refs = {6, 0}, __g_size = {0, 0}, __g1_orig_size = 4, __wrefs = 24, __g_signals = {0, 0} }, __size = "\036\000\000\000\000\000\000\000\026\000\000\000\000\000\000\000\006", '\000' <repeats 15 times>, "\004\000\000--Type <RET> for more, q to quit, c to continue without paging-- \000\030\000\000\000\000\000\000\000\000\000\000", __align = 30 }, writeable = { __data = { { __wseq = 97, __wseq32 = { __low = 97, __high = 0 } }, { __g1_start = 95, __g1_start32 = { __low = 95, __high = 0 } }, __g_refs = {0, 0}, __g_size = {0, 0}, __g1_orig_size = 4, __wrefs = 0, __g_signals = {0, 0} }, __size = "a\000\000\000\000\000\000\000_", '\000' <repeats 23 times>, "\004", '\000' <repeats 14 times>, __align = 97 }, readers_waiting = 3, write_granted = 7228, write_quota = 4 } (gdb) info locals i = <optimized out> level_node = <optimized out> header = <optimized out> header_prev = 0x7fff9969d380 header_next = <optimized out> found = 0x7fff9969f010 foundsig = 0x7fff9969d380 result = 65565 name = { magic = 1145983854, ndata = 0x7fff9969a078 "", length = 1, labels = 1, attributes = 3, offsets = 0x7fff9969a07a "", buffer = 0x0, link = { prev = 0xffffffffffffffff, next = 0xffffffffffffffff }, list = { head = 0x0, tail = 0x0 } } rbtdb = 0x7fff99694010 done = false lock = 0x7fff94362bb0 locktype = isc_rwlocktype_write It seems to me quite supspicious part of relocking record on rbtdb.c:4871 line, where it changes from read lock to write lock. But found and foundsig are still pointing on original objects, which are not protected by a lock for a while. Similar line is still on master branch [1]. 1. https://gitlab.isc.org/isc-projects/bind9/blob/master/lib/dns/rbtdb.c#L4558
There are two upstream issues detected by upstream. Some might be related. 1. https://gitlab.isc.org/isc-projects/bind9/issues/1419 2. https://gitlab.isc.org/isc-projects/bind9/issues/1417
Created attachment 1640436 [details] possible patch to the issue Not yet properly tested patch. Should help prevent race condition in update_header, dns/rbtdb.c.
Filled upstream issue https://gitlab.isc.org/isc-projects/bind9/issues/1428
FEDORA-2019-9046ee81cd has been submitted as an update to Fedora 31. https://bodhi.fedoraproject.org/updates/FEDORA-2019-9046ee81cd
Imported few fixed thread related issues from upstream branch. It seems to me my fix should be used, but maybe upstream is right. Built also F30 build [1], but new Bodhi interface does not allow me to modify pending update. Would prepare new update after rebase makes it into stable. 1. https://koji.fedoraproject.org/koji/buildinfo?buildID=1418981
bind-9.11.13-3.fc31 has been pushed to the Fedora 31 testing repository. If problems still persist, please make note of it in this bug report. See https://fedoraproject.org/wiki/QA:Updates_Testing for instructions on how to install test updates. You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2019-9046ee81cd
Oh, Thread sanitizer is quite useful tool. Tried it myself just randomly on autosign test. And it produced on my 4 core machine some warnings on ns4 server. Some of them look like quite familiar. This is with upstream patches applied. ================== WARNING: ThreadSanitizer: data race (pid=19443) Read of size 2 at 0x7fe633711640 by thread T4: #0 find_deepest_zonecut ../../../lib/dns/rbtdb.c:4913 (libdns.so.1107+0x11bc7a) #1 cache_findzonecut ../../../lib/dns/rbtdb.c:5500 (libdns.so.1107+0x121fc8) #2 dns_db_findzonecut ../../../lib/dns/db.c:617 (libdns.so.1107+0x7ace3) #3 query_addbestns ../../../bin/named/query.c:3435 (lt-named+0x73f21) #4 query_find ../../../bin/named/query.c:9276 (lt-named+0x73f21) #5 query_resume ../../../bin/named/query.c:4174 (lt-named+0x766f9) #6 dispatch ../../../lib/isc/task.c:1143 (libisc.so.1104+0x59abd) #7 run ../../../lib/isc/task.c:1315 (libisc.so.1104+0x59abd) #8 <null> <null> (libtsan.so.0+0x2b556) Previous write of size 2 at 0x7fe633711640 by thread T1: #0 clean_cache_node ../../../lib/dns/rbtdb.c:1865 (libdns.so.1107+0x118d75) #1 decrement_reference ../../../lib/dns/rbtdb.c:2360 (libdns.so.1107+0x118d75) #2 detachnode ../../../lib/dns/rbtdb.c:5630 (libdns.so.1107+0x139e4d) #3 rdataset_disassociate ../../../lib/dns/rbtdb.c:8939 (libdns.so.1107+0x13a08a) #4 dns_rdataset_disassociate ../../../lib/dns/rdataset.c:117 (libdns.so.1107+0x1bd32c) #5 fctx_destroy ../../../lib/dns/resolver.c:3946 (libdns.so.1107+0x1d17f4) #6 fctx_doshutdown ../../../lib/dns/resolver.c:4114 (libdns.so.1107+0x1dd598) #7 dispatch ../../../lib/isc/task.c:1143 (libisc.so.1104+0x59abd) #8 run ../../../lib/isc/task.c:1315 (libisc.so.1104+0x59abd) #9 <null> <null> (libtsan.so.0+0x2b556) Location is heap block of size 262144 at 0x7fe633707000 allocated by thread T1: #0 malloc <null> (libtsan.so.0+0x2cd76) #1 internal_memalloc ../../../lib/isc/mem.c:884 (libisc.so.1104+0x3e6d7) #2 more_basic_blocks ../../../lib/isc/mem.c:557 (libisc.so.1104+0x3cb45) #3 more_frags ../../../lib/isc/mem.c:601 (libisc.so.1104+0x3cb45) #4 mem_getunlocked ../../../lib/isc/mem.c:686 (libisc.so.1104+0x3cb45) #5 mem_allocateunlocked ../../../lib/isc/mem.c:1534 (libisc.so.1104+0x3e7fa) #6 isc___mem_allocate ../../../lib/isc/mem.c:1557 (libisc.so.1104+0x3e7fa) #7 isc__mem_allocate ../../../lib/isc/mem.c:3004 (libisc.so.1104+0x427b3) #8 isc___mem_get ../../../lib/isc/mem.c:1301 (libisc.so.1104+0x428a1) #9 isc__mem_get ../../../lib/isc/mem.c:2968 (libisc.so.1104+0x431ba) #10 dns_cache_create3 ../../../lib/dns/cache.c:218 (libdns.so.1107+0x6afbd) #11 configure_view ../../../bin/named/server.c:3855 (lt-named+0x8d338) #12 load_configuration ../../../bin/named/server.c:8167 (lt-named+0xa61df) #13 run_server ../../../bin/named/server.c:8929 (lt-named+0xa9c04) #14 dispatch ../../../lib/isc/task.c:1143 (libisc.so.1104+0x59abd) #15 run ../../../lib/isc/task.c:1315 (libisc.so.1104+0x59abd) #16 <null> <null> (libtsan.so.0+0x2b556) Thread T4 'isc-worker0003' (tid=19461, running) created by main thread at: #0 pthread_create <null> (libtsan.so.0+0x2de12) #1 isc_thread_create ../../../../lib/isc/pthreads/thread.c:60 (libisc.so.1104+0x8a129) #2 isc__taskmgr_create ../../../lib/isc/task.c:1452 (libisc.so.1104+0x5af27) #3 isc_taskmgr_create ../../../lib/isc/task.c:2091 (libisc.so.1104+0x5dea3) #4 create_managers ../../../bin/named/main.c:872 (lt-named+0x48df4) #5 setup ../../../bin/named/main.c:1291 (lt-named+0x48df4) #6 main ../../../bin/named/main.c:1538 (lt-named+0x48df4) Thread T1 'isc-worker0000' (tid=19458, running) created by main thread at: #0 pthread_create <null> (libtsan.so.0+0x2de12) #1 isc_thread_create ../../../../lib/isc/pthreads/thread.c:60 (libisc.so.1104+0x8a129) #2 isc__taskmgr_create ../../../lib/isc/task.c:1452 (libisc.so.1104+0x5af27) #3 isc_taskmgr_create ../../../lib/isc/task.c:2091 (libisc.so.1104+0x5dea3) #4 create_managers ../../../bin/named/main.c:872 (lt-named+0x48df4) #5 setup ../../../bin/named/main.c:1291 (lt-named+0x48df4) #6 main ../../../bin/named/main.c:1538 (lt-named+0x48df4) SUMMARY: ThreadSanitizer: data race ../../../lib/dns/rbtdb.c:4913 in find_deepest_zonecut ================== ================== WARNING: ThreadSanitizer: data race (pid=19443) Read of size 4 at 0x7b7c00002344 by thread T4: #0 isc_rwlock_trylock ../../../lib/isc/rwlock.c:495 (libisc.so.1104+0x4fda1) #1 isc_rwlock_lock ../../../lib/isc/rwlock.c:412 (libisc.so.1104+0x504c7) #2 find_deepest_zonecut ../../../lib/dns/rbtdb.c:4993 (libdns.so.1107+0x11baf7) #3 cache_findzonecut ../../../lib/dns/rbtdb.c:5500 (libdns.so.1107+0x121fc8) #4 dns_db_findzonecut ../../../lib/dns/db.c:617 (libdns.so.1107+0x7ace3) #5 query_addbestns ../../../bin/named/query.c:3435 (lt-named+0x73f21) #6 query_find ../../../bin/named/query.c:9276 (lt-named+0x73f21) #7 query_resume ../../../bin/named/query.c:4174 (lt-named+0x766f9) #8 dispatch ../../../lib/isc/task.c:1143 (libisc.so.1104+0x59abd) #9 run ../../../lib/isc/task.c:1315 (libisc.so.1104+0x59abd) #10 <null> <null> (libtsan.so.0+0x2b556) Previous write of size 4 at 0x7b7c00002344 by thread T1: #0 isc_rwlock_trylock ../../../lib/isc/rwlock.c:495 (libisc.so.1104+0x4fdb2) #1 isc_rwlock_lock ../../../lib/isc/rwlock.c:412 (libisc.so.1104+0x504c7) #2 decrement_reference ../../../lib/dns/rbtdb.c:2346 (libdns.so.1107+0x118b67) #3 detachnode ../../../lib/dns/rbtdb.c:5630 (libdns.so.1107+0x139e4d) #4 rdataset_disassociate ../../../lib/dns/rbtdb.c:8939 (libdns.so.1107+0x13a08a) #5 dns_rdataset_disassociate ../../../lib/dns/rdataset.c:117 (libdns.so.1107+0x1bd32c) #6 fctx_destroy ../../../lib/dns/resolver.c:3946 (libdns.so.1107+0x1d17f4) #7 fctx_doshutdown ../../../lib/dns/resolver.c:4114 (libdns.so.1107+0x1dd598) #8 dispatch ../../../lib/isc/task.c:1143 (libisc.so.1104+0x59abd) #9 run ../../../lib/isc/task.c:1315 (libisc.so.1104+0x59abd) #10 <null> <null> (libtsan.so.0+0x2b556) Location is heap block of size 3344 at 0x7b7c00001c00 allocated by thread T1: #0 malloc <null> (libtsan.so.0+0x2cd76) #1 internal_memalloc ../../../lib/isc/mem.c:884 (libisc.so.1104+0x3e6d7) #2 mem_getunlocked ../../../lib/isc/mem.c:664 (libisc.so.1104+0x3c587) #3 mem_allocateunlocked ../../../lib/isc/mem.c:1534 (libisc.so.1104+0x3e7fa) #4 isc___mem_allocate ../../../lib/isc/mem.c:1557 (libisc.so.1104+0x3e7fa) #5 isc__mem_allocate ../../../lib/isc/mem.c:3004 (libisc.so.1104+0x427b3) #6 isc___mem_get ../../../lib/isc/mem.c:1301 (libisc.so.1104+0x428a1) #7 isc__mem_get ../../../lib/isc/mem.c:2968 (libisc.so.1104+0x431ba) #8 dns_rbtdb_create ../../../lib/dns/rbtdb.c:8645 (libdns.so.1107+0x13b0cb) #9 dns_db_create ../../../lib/dns/db.c:129 (libdns.so.1107+0x79268) #10 cache_create_db ../../../lib/dns/cache.c:172 (libdns.so.1107+0x6b59a) #11 dns_cache_create3 ../../../lib/dns/cache.c:297 (libdns.so.1107+0x6b59a) #12 configure_view ../../../bin/named/server.c:3855 (lt-named+0x8d338) #13 load_configuration ../../../bin/named/server.c:8167 (lt-named+0xa61df) #14 run_server ../../../bin/named/server.c:8929 (lt-named+0xa9c04) #15 dispatch ../../../lib/isc/task.c:1143 (libisc.so.1104+0x59abd) #16 run ../../../lib/isc/task.c:1315 (libisc.so.1104+0x59abd) #17 <null> <null> (libtsan.so.0+0x2b556) Thread T4 'isc-worker0003' (tid=19461, running) created by main thread at: #0 pthread_create <null> (libtsan.so.0+0x2de12) #1 isc_thread_create ../../../../lib/isc/pthreads/thread.c:60 (libisc.so.1104+0x8a129) #2 isc__taskmgr_create ../../../lib/isc/task.c:1452 (libisc.so.1104+0x5af27) #3 isc_taskmgr_create ../../../lib/isc/task.c:2091 (libisc.so.1104+0x5dea3) #4 create_managers ../../../bin/named/main.c:872 (lt-named+0x48df4) #5 setup ../../../bin/named/main.c:1291 (lt-named+0x48df4) #6 main ../../../bin/named/main.c:1538 (lt-named+0x48df4) Thread T1 'isc-worker0000' (tid=19458, running) created by main thread at: #0 pthread_create <null> (libtsan.so.0+0x2de12) #1 isc_thread_create ../../../../lib/isc/pthreads/thread.c:60 (libisc.so.1104+0x8a129) #2 isc__taskmgr_create ../../../lib/isc/task.c:1452 (libisc.so.1104+0x5af27) #3 isc_taskmgr_create ../../../lib/isc/task.c:2091 (libisc.so.1104+0x5dea3) #4 create_managers ../../../bin/named/main.c:872 (lt-named+0x48df4) #5 setup ../../../bin/named/main.c:1291 (lt-named+0x48df4) #6 main ../../../bin/named/main.c:1538 (lt-named+0x48df4) SUMMARY: ThreadSanitizer: data race ../../../lib/isc/rwlock.c:495 in isc_rwlock_trylock ================== ================== WARNING: ThreadSanitizer: data race (pid=19443) Write of size 8 at 0x7fe63370e090 by thread T4: #0 update_header ../../../lib/dns/rbtdb.c:10515 (libdns.so.1107+0x10f0b2) #1 find_deepest_zonecut ../../../lib/dns/rbtdb.c:4998 (libdns.so.1107+0x11bd4b) #2 cache_findzonecut ../../../lib/dns/rbtdb.c:5500 (libdns.so.1107+0x121fc8) #3 dns_db_findzonecut ../../../lib/dns/db.c:617 (libdns.so.1107+0x7ace3) #4 query_addbestns ../../../bin/named/query.c:3435 (lt-named+0x73f21) #5 query_find ../../../bin/named/query.c:9276 (lt-named+0x73f21) #6 query_resume ../../../bin/named/query.c:4174 (lt-named+0x766f9) #7 dispatch ../../../lib/isc/task.c:1143 (libisc.so.1104+0x59abd) #8 run ../../../lib/isc/task.c:1315 (libisc.so.1104+0x59abd) #9 <null> <null> (libtsan.so.0+0x2b556) Previous read of size 8 at 0x7fe63370e090 by thread T1: #0 free_rdataset ../../../lib/dns/rbtdb.c:1746 (libdns.so.1107+0x1183e3) #1 clean_stale_headers ../../../lib/dns/rbtdb.c:1834 (libdns.so.1107+0x118c81) #2 clean_cache_node ../../../lib/dns/rbtdb.c:1851 (libdns.so.1107+0x118c81) #3 decrement_reference ../../../lib/dns/rbtdb.c:2360 (libdns.so.1107+0x118c81) #4 detachnode ../../../lib/dns/rbtdb.c:5630 (libdns.so.1107+0x139e4d) #5 rdataset_disassociate ../../../lib/dns/rbtdb.c:8939 (libdns.so.1107+0x13a08a) #6 dns_rdataset_disassociate ../../../lib/dns/rdataset.c:117 (libdns.so.1107+0x1bd32c) #7 fctx_destroy ../../../lib/dns/resolver.c:3946 (libdns.so.1107+0x1d17f4) #8 fctx_doshutdown ../../../lib/dns/resolver.c:4114 (libdns.so.1107+0x1dd598) #9 dispatch ../../../lib/isc/task.c:1143 (libisc.so.1104+0x59abd) #10 run ../../../lib/isc/task.c:1315 (libisc.so.1104+0x59abd) #11 <null> <null> (libtsan.so.0+0x2b556) Location is heap block of size 262144 at 0x7fe633707000 allocated by thread T1: #0 malloc <null> (libtsan.so.0+0x2cd76) #1 internal_memalloc ../../../lib/isc/mem.c:884 (libisc.so.1104+0x3e6d7) #2 more_basic_blocks ../../../lib/isc/mem.c:557 (libisc.so.1104+0x3cb45) #3 more_frags ../../../lib/isc/mem.c:601 (libisc.so.1104+0x3cb45) #4 mem_getunlocked ../../../lib/isc/mem.c:686 (libisc.so.1104+0x3cb45) #5 mem_allocateunlocked ../../../lib/isc/mem.c:1534 (libisc.so.1104+0x3e7fa) #6 isc___mem_allocate ../../../lib/isc/mem.c:1557 (libisc.so.1104+0x3e7fa) #7 isc__mem_allocate ../../../lib/isc/mem.c:3004 (libisc.so.1104+0x427b3) #8 isc___mem_get ../../../lib/isc/mem.c:1301 (libisc.so.1104+0x428a1) #9 isc__mem_get ../../../lib/isc/mem.c:2968 (libisc.so.1104+0x431ba) #10 dns_cache_create3 ../../../lib/dns/cache.c:218 (libdns.so.1107+0x6afbd) #11 configure_view ../../../bin/named/server.c:3855 (lt-named+0x8d338) #12 load_configuration ../../../bin/named/server.c:8167 (lt-named+0xa61df) #13 run_server ../../../bin/named/server.c:8929 (lt-named+0xa9c04) #14 dispatch ../../../lib/isc/task.c:1143 (libisc.so.1104+0x59abd) #15 run ../../../lib/isc/task.c:1315 (libisc.so.1104+0x59abd) #16 <null> <null> (libtsan.so.0+0x2b556) Thread T4 'isc-worker0003' (tid=19461, running) created by main thread at: #0 pthread_create <null> (libtsan.so.0+0x2de12) #1 isc_thread_create ../../../../lib/isc/pthreads/thread.c:60 (libisc.so.1104+0x8a129) #2 isc__taskmgr_create ../../../lib/isc/task.c:1452 (libisc.so.1104+0x5af27) #3 isc_taskmgr_create ../../../lib/isc/task.c:2091 (libisc.so.1104+0x5dea3) #4 create_managers ../../../bin/named/main.c:872 (lt-named+0x48df4) #5 setup ../../../bin/named/main.c:1291 (lt-named+0x48df4) #6 main ../../../bin/named/main.c:1538 (lt-named+0x48df4) Thread T1 'isc-worker0000' (tid=19458, running) created by main thread at: #0 pthread_create <null> (libtsan.so.0+0x2de12) #1 isc_thread_create ../../../../lib/isc/pthreads/thread.c:60 (libisc.so.1104+0x8a129) #2 isc__taskmgr_create ../../../lib/isc/task.c:1452 (libisc.so.1104+0x5af27) #3 isc_taskmgr_create ../../../lib/isc/task.c:2091 (libisc.so.1104+0x5dea3) #4 create_managers ../../../bin/named/main.c:872 (lt-named+0x48df4) #5 setup ../../../bin/named/main.c:1291 (lt-named+0x48df4) #6 main ../../../bin/named/main.c:1538 (lt-named+0x48df4) SUMMARY: ThreadSanitizer: data race ../../../lib/dns/rbtdb.c:10515 in update_header ================== It generates lot of noise, because some warnings are present even in dig, rndc and other tools. It makes test fail, I think it might be because output to stderr is often corrupted by warnings. Anyway, it does not seems upstream changes fix this issue properly.
Good heavens, ThreadSanitizer [1] is so cool tool for BIND problems troubleshooting. It reports many issues we are hitting in various places, including this one. Pushed to master very basic compilation support. I am using it like: fedpkg local --with TSAN --with SYSTEMTEST Found out ThreadSanitizer overrides return codes on found issues. But that would prevent normal run, so configured it back. Anyway, it seems this issue is quite generic and is detected also on my 4 core x86_64 laptop. Trying to find correct fix on master upstream branch. Using simple script: $ cat check-update-header.sh #!/bin/sh make -j4 cd bin/tests/system export TSAN_OPTIONS="log_exe_name=true log_path=tsan exitcode=0" TEST=resolver find $TEST -name 'tsan.*' -delete sh run.sh $TEST && ! grep update_header $TEST/ns*/tsan.lt-named.* Still, similar issue is detected and reported, even on latest master branch, commit 96475e7eb411db2298121d9cd560fc5b5a57a2f1. My proposed fix does not resolve those issues. 1. https://github.com/google/sanitizers/wiki/ThreadSanitizerFlags
Upstream issue 1443 [1] seems related to some detected backtraces, not yet merged. 1. https://gitlab.isc.org/isc-projects/bind9/issues/1443
It would match well this issue on master, when we have crashes on T3, corrupted maybe in T5 in this case. WARNING: ThreadSanitizer: data race (pid=27503) Write of size 8 at 0x7fa8844860c0 by thread T3: #0 update_header /home/pemensik/git/bind9/lib/dns/rbtdb.c:10163 (libdns.so.1505+0x118121) #1 cache_find /home/pemensik/git/bind9/lib/dns/rbtdb.c:5027 (libdns.so.1505+0x13aca8) #2 dns_db_findext /home/pemensik/git/bind9/lib/dns/db.c:551 (libdns.so.1505+0x747a5) #3 query_lookup /home/pemensik/git/bind9/lib/ns/query.c:5515 (libns.so.1502+0x3e692) #4 ns__query_start /home/pemensik/git/bind9/lib/ns/query.c:5441 (libns.so.1502+0x3f645) #5 query_setup /home/pemensik/git/bind9/lib/ns/query.c:5162 (libns.so.1502+0x48864) #6 ns_query_start /home/pemensik/git/bind9/lib/ns/query.c:11239 (libns.so.1502+0x49054) #7 ns__client_request /home/pemensik/git/bind9/lib/ns/client.c:2157 (libns.so.1502+0x17fe4) #8 udp_recv_cb /home/pemensik/git/bind9/lib/isc/netmgr/udp.c:318 (libisc.so.1504+0x49af6) #9 uv__udp_recvmsg src/unix/udp.c:200 (libuv.so.1+0x208ee) #10 uv__udp_io src/unix/udp.c:143 (libuv.so.1+0x208ee) #11 <null> <null> (libtsan.so.0+0x2b556) Previous read of size 8 at 0x7fa8844860c0 by thread T5: #0 free_rdataset /home/pemensik/git/bind9/lib/dns/rbtdb.c:1460 (libdns.so.1505+0x126a30) #1 clean_stale_headers /home/pemensik/git/bind9/lib/dns/rbtdb.c:1569 (libdns.so.1505+0x126a30) #2 clean_cache_node /home/pemensik/git/bind9/lib/dns/rbtdb.c:1586 (libdns.so.1505+0x126a30) #3 decrement_reference /home/pemensik/git/bind9/lib/dns/rbtdb.c:1989 (libdns.so.1505+0x126a30) #4 detachnode /home/pemensik/git/bind9/lib/dns/rbtdb.c:5244 (libdns.so.1505+0x12baa0) #5 rdataset_disassociate /home/pemensik/git/bind9/lib/dns/rbtdb.c:8442 (libdns.so.1505+0x12bdbc) #6 dns_rdataset_disassociate /home/pemensik/git/bind9/lib/dns/rdataset.c:118 (libdns.so.1505+0x18e3e8) #7 fctx_destroy /home/pemensik/git/bind9/lib/dns/resolver.c:4399 (libdns.so.1505+0x1a076e) #8 fctx_doshutdown /home/pemensik/git/bind9/lib/dns/resolver.c:4574 (libdns.so.1505+0x1aed47) #9 dispatch /home/pemensik/git/bind9/lib/isc/task.c:1134 (libisc.so.1504+0x5b447) #10 run /home/pemensik/git/bind9/lib/isc/task.c:1319 (libisc.so.1504+0x5b447) #11 <null> <null> (libtsan.so.0+0x2b556) Location is heap block of size 262144 at 0x7fa88447f000 allocated by thread T5: #0 malloc <null> (libtsan.so.0+0x2cd76) #1 default_memalloc /home/pemensik/git/bind9/lib/isc/mem.c:685 (libisc.so.1504+0x3a258) #2 more_basic_blocks /home/pemensik/git/bind9/lib/isc/mem.c:382 (libisc.so.1504+0x38fb7) #3 more_frags /home/pemensik/git/bind9/lib/isc/mem.c:427 (libisc.so.1504+0x38fb7) #4 mem_getunlocked /home/pemensik/git/bind9/lib/isc/mem.c:498 (libisc.so.1504+0x38fb7) #5 mem_allocateunlocked /home/pemensik/git/bind9/lib/isc/mem.c:1220 (libisc.so.1504+0x3b122) #6 isc___mem_allocate /home/pemensik/git/bind9/lib/isc/mem.c:1242 (libisc.so.1504+0x3b122) #7 isc__mem_allocate /home/pemensik/git/bind9/lib/isc/mem.c:2387 (libisc.so.1504+0x40ddd) #8 isc___mem_get /home/pemensik/git/bind9/lib/isc/mem.c:1007 (libisc.so.1504+0x413d3) #9 isc__mem_get /home/pemensik/git/bind9/lib/isc/mem.c:2365 (libisc.so.1504+0x3fe9b) #10 dns_cache_create /home/pemensik/git/bind9/lib/dns/cache.c:198 (libdns.so.1505+0x65704) #11 configure_view server.c:4486 (lt-named+0x432c5) #12 load_configuration server.c:8922 (lt-named+0x5bcd1) #13 run_server server.c:9644 (lt-named+0x5ebd4) #14 dispatch /home/pemensik/git/bind9/lib/isc/task.c:1134 (libisc.so.1504+0x5b447) #15 run /home/pemensik/git/bind9/lib/isc/task.c:1319 (libisc.so.1504+0x5b447) #16 <null> <null> (libtsan.so.0+0x2b556) Thread T3 'isc-net-0002' (tid=27520, running) created by main thread at: #0 pthread_create <null> (libtsan.so.0+0x2de12) #1 isc_thread_create /home/pemensik/git/bind9/lib/isc/pthreads/thread.c:75 (libisc.so.1504+0x81cc5) #2 isc_nm_start /home/pemensik/git/bind9/lib/isc/netmgr/netmgr.c:152 (libisc.so.1504+0x42f5b) #3 create_managers main.c:895 (lt-named+0x1e80b) #4 setup main.c:1235 (lt-named+0x1e80b) #5 main main.c:1517 (lt-named+0x1e80b) Thread T5 'isc-worker0000' (tid=27522, running) created by main thread at: #0 pthread_create <null> (libtsan.so.0+0x2de12) #1 isc_thread_create /home/pemensik/git/bind9/lib/isc/pthreads/thread.c:75 (libisc.so.1504+0x81cc5) #2 isc_taskmgr_create /home/pemensik/git/bind9/lib/isc/task.c:1410 (libisc.so.1504+0x5e1d7) #3 create_managers main.c:902 (lt-named+0x1e862) #4 setup main.c:1235 (lt-named+0x1e862) #5 main main.c:1517 (lt-named+0x1e862) SUMMARY: ThreadSanitizer: data race /home/pemensik/git/bind9/lib/dns/rbtdb.c:10163 in update_header
bind-9.11.13-3.fc31 has been pushed to the Fedora 31 stable repository. If problems still persist, please make note of it in this bug report.
It seems I missed one important commit [1], which seems the most directly related to these issues from all used. Separates bitfields with locknum and references from common flags used for different things. It might affect references wrong way. Maybe I looked on wrong place all the time. If locknum is not correct, wrong lock would be held. Would match behaviour observed more than other changes. And this would change behaviour when stdatomics are disabled, as it was reported it helped. It might be also related with upstream MR [2], and issue [3]. 1. https://gitlab.isc.org/isc-projects/bind9/commit/6eed12605154b8ce10e9be0f51253e6ec318550e 2. https://gitlab.isc.org/isc-projects/bind9/merge_requests/2703 3. https://gitlab.isc.org/isc-projects/bind9/issues/1443
FEDORA-2020-4eecfe82aa has been submitted as an update to Fedora 31. https://bodhi.fedoraproject.org/updates/FEDORA-2020-4eecfe82aa
bind-9.11.14-2.fc31 has been pushed to the Fedora 31 testing repository. If problems still persist, please make note of it in this bug report. See https://fedoraproject.org/wiki/QA:Updates_Testing for instructions on how to install test updates. You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2020-4eecfe82aa
bind-9.11.14-2.fc31 has been pushed to the Fedora 31 stable repository. If problems still persist, please make note of it in this bug report.