Bug 1736762 - [ppc64le] Bind DNS Spontaneously Crashes After 24 Hours
Summary: [ppc64le] Bind DNS Spontaneously Crashes After 24 Hours
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Fedora
Classification: Fedora
Component: bind
Version: 30
Hardware: ppc64le
OS: Linux
unspecified
medium
Target Milestone: ---
Assignee: Petr Menšík
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On: 1666178
Blocks: PPCTracker rhel7_ppc64_crashes
TreeView+ depends on / blocked
 
Reported: 2019-08-01 22:14 UTC by Daniel
Modified: 2020-04-15 17:37 UTC (History)
17 users (show)

Fixed In Version: bind-9.11.13-3.fc31 bind-9.11.14-2.fc31
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
: 1740511 rhel7_ppc64_crashes (view as bug list)
Environment:
Last Closed: 2020-01-13 02:19:41 UTC
Type: Bug


Attachments (Terms of Use)
atomic_test modification (4.35 KB, patch)
2019-08-26 20:43 UTC, Petr Menšík
no flags Details | Diff
Core dump of the crash (9.13 MB, application/octet-stream)
2019-10-30 02:25 UTC, Daniel
no flags Details
possible patch to the issue (2.10 KB, patch)
2019-11-28 17:07 UTC, Petr Menšík
no flags Details | Diff


Links
System ID Private Priority Status Summary Last Updated
IBM Linux Technology Center 181694 0 None None None 2019-09-29 08:54:19 UTC
Red Hat Knowledge Base (Solution) 4788601 0 None None None 2020-04-15 17:37:21 UTC

Description Daniel 2019-08-01 22:14:08 UTC
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

Comment 1 Dan Horák 2019-08-02 07:19:54 UTC
Any chance there would be more details captured in journal and available via "coredumpctl gdb" command?

Comment 2 Daniel 2019-08-06 05:50:01 UTC
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'

Comment 3 Daniel 2019-08-07 04:35:18 UTC
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...

Comment 6 Dan Horák 2019-08-13 08:13:26 UTC
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

Comment 8 Petr Menšík 2019-08-26 15:46:35 UTC
(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.

Comment 9 Petr Menšík 2019-08-26 20:42:33 UTC
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).

Comment 10 Petr Menšík 2019-08-26 20:43:35 UTC
Created attachment 1608301 [details]
atomic_test modification

Comment 12 Petr Menšík 2019-10-02 17:07:00 UTC
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

Comment 13 Daniel 2019-10-30 02:25:57 UTC
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

Comment 14 Daniel 2019-10-30 02:27:31 UTC
Finally managed to get a core dump of the crash as it happens naturally.

Comment 15 Petr Menšík 2019-11-28 12:18:36 UTC
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>
}

Comment 16 Petr Menšík 2019-11-28 13:21:46 UTC
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

Comment 17 Petr Menšík 2019-11-28 17:02:21 UTC
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

Comment 18 Petr Menšík 2019-11-28 17:07:19 UTC
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.

Comment 19 Petr Menšík 2019-11-28 17:13:07 UTC
Filled upstream issue https://gitlab.isc.org/isc-projects/bind9/issues/1428

Comment 20 Fedora Update System 2019-12-03 13:37:54 UTC
FEDORA-2019-9046ee81cd has been submitted as an update to Fedora 31. https://bodhi.fedoraproject.org/updates/FEDORA-2019-9046ee81cd

Comment 21 Petr Menšík 2019-12-03 18:56:48 UTC
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

Comment 22 Fedora Update System 2019-12-04 02:20:17 UTC
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

Comment 25 Petr Menšík 2019-12-04 16:02:01 UTC
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.

Comment 26 Petr Menšík 2019-12-04 17:52:59 UTC
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

Comment 27 Petr Menšík 2019-12-04 21:00:39 UTC
Upstream issue 1443 [1] seems related to some detected backtraces, not yet merged.

1. https://gitlab.isc.org/isc-projects/bind9/issues/1443

Comment 28 Petr Menšík 2019-12-04 21:13:33 UTC
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

Comment 29 Fedora Update System 2019-12-05 01:40:52 UTC
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.

Comment 30 Petr Menšík 2019-12-09 20:24:12 UTC
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

Comment 31 Fedora Update System 2020-01-06 15:25:41 UTC
FEDORA-2020-4eecfe82aa has been submitted as an update to Fedora 31. https://bodhi.fedoraproject.org/updates/FEDORA-2020-4eecfe82aa

Comment 32 Fedora Update System 2020-01-07 01:07:31 UTC
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

Comment 33 Fedora Update System 2020-01-13 02:19:41 UTC
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.


Note You need to log in before you can comment on or make changes to this bug.