Bug 2231755 - bind keeps repeating success resolving messages in log file
Summary: bind keeps repeating success resolving messages in log file
Keywords:
Status: CLOSED EOL
Alias: None
Product: Fedora
Classification: Fedora
Component: bind
Version: 37
Hardware: x86_64
OS: Linux
unspecified
medium
Target Milestone: ---
Assignee: Petr Menšík
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2023-08-13 23:36 UTC by John Griffiths
Modified: 2024-01-15 12:20 UTC (History)
6 users (show)

Fixed In Version:
Clone Of:
Environment:
Last Closed: 2024-01-15 12:20:43 UTC
Type: ---
Embargoed:


Attachments (Terms of Use)

Description John Griffiths 2023-08-13 23:36:38 UTC
After the latest update to bind-9.18.17-1.fc37.x86_64,  bind  keeps logging entries like these:

success resolving '100.44.159.162.zen.spamhaus.org/A' after disabling qname minimization due to 'ncache nxdomain': 1 Time(s)
    success resolving '100.99.74.204.zen.spamhaus.org/A' after disabling qname minimization due to 'ncache nxdomain': 1 Time(s)
    success resolving '1000073432._domainkey.auth.ccsend.com/A' after disabling qname minimization due to 'ncache nxdomain': 1 Time(s)

The system got 802 of these yesterday.

Reproducible: Always

Steps to Reproduce:
1. Update bind
2. Let is run
3. check logwatch or the log file
Actual Results:  
Lots of success resolving messages.

Expected Results:  
Nothing if it is a success.

Comment 1 Petr Menšík 2023-09-18 09:13:58 UTC
success resolving '100.44.159.162.zen.spamhaus.org/A' after disabling qname minimization due to 'ncache nxdomain'

means the resolution process is broken somewhere and behaves somehow non-standard way. It should not happen normally and that is why it is logged.
Unfortunately it seems qname-minimization can be turned off only for global or view, not per server as it seems that is needed in your case.

Can you gather statistics for responsible zones, where such events occur? Does that happen on low number of parent zones?

Basic statistics should be done by command:
cat /tmp/log | awk '$1 == "success" && $6 == "qname" && $7 == "minimization" {print $3}' | sed -e "s,^'\(.*\)/[[:alpha:]]'$,\1," | while read NAME; do dig -t SOA $NAME | awk '$4 == "SOA" { print $1 }'; done | sort | uniq -c

Of course you can get rid of these by 

qname-minimization off; in options {} block;

It might be possible to disable these logs by sending this severity messages to null target. More in ARM about logging statement:

https://downloads.isc.org/isc/bind9/9.18.17/doc/arm/html/reference.html#namedconf-statement-logging

But I doubt upstream or I would like to hide broken behaviour of servers in default configuration. More likely this should be reported to operators of failing zones to get them fixed their servers. It should not need qname-minimization to relaxed value, which this error suggests were needed for successful resolution.

Comment 2 Petr Menšík 2023-09-18 09:23:44 UTC
do any of zones emitting those messages have own zone record in named configuration? Are forwarders used for them or globally?

Output of named-checkconf -px would greatly help to understand what is the configuration. Or what else might be causing qname minimization algorithm to fail.

Comment 3 John Griffiths 2023-09-18 16:09:56 UTC
The format of the messages I posted was from logwatch. The messages in the /var/log/messages file actually look like this:

Sep 18 12:00:02 XXXXXX named[1387]: success resolving 'prod.ups-ats.us-east-1.aolp-ds-prd.aws.oath.cloud/A' after disabling qname minimization due to 'ncache nxdomain'
Sep 18 12:00:03 XXXXXX named[1387]: success resolving 'ats-eks.us-east-1.dcs-online-targeting-prd.aws.oath.cloud/A' after disabling qname minimization due to 'ncache nxdomain'
Sep 18 12:00:33 XXXXXX named[1387]: success resolving 'naeu.geo.cloudwm-cdn.com/A' after disabling qname minimization due to 'ncache nxdomain'
Sep 18 12:00:33 XXXXXX named[1387]: success resolving 'mb9eo.publishers.tremorhub.com/A' after disabling qname minimization due to 'ncache nxdomain'
Sep 18 12:00:42 XXXXXX named[1387]: success resolving 'match.prod.bidr.io/A' after disabling qname minimization due to 'ncache nxdomain

The command I had to use is:
cat messages | awk '$6 == "success" && $11 {print $8}'  | sed -e "s,^'\(.*\)/[[:alpha:]]'$,\1," | while read NAME; do dig -t SOA $NAME | awk '$4 == "SOA" { print $1 }'; done | sort | uniq -c

The output is:
    211 .
     14 a.akamaiedge.net.
      1 adobe.io.
      3 airtelbroadband.in.
      4 amazontrust.com.
      1 angsrvr.com.
      9 api10.akamai.net.
     14 bidr.io.
     21 bl.score.senderscore.com.
      4 bluecava.com.
      1 byteigtm.com.
      1 ccc.net.il.
     16 c.footprint.net.
      1 claro.net.do.
      2 cloudflare.net.
      3 cloudwm-cdn.com.
      1 content-signature-chains.prod.webservices.mozgcp.net.
      5 d25xi40x97liuc.cloudfront.net.
      1 d2ljcaegf12t2d.cloudfront.net.
    116 dbl.spamhaus.org.
     36 dcs-online-targeting-prd.aws.oath.cloud.
     25 dn.apigee.net.
     73 dnsbl.sorbs.net.
     56 dob.sibl.support-intelligence.net.
      1 e.allegiant.com.
    100 elb.us-east-1.amazonaws.com.
      3 e-planning.net.
      4 fastly.net.
      1 feromedia.eu.
      6 fna.fbcdn.net.
     34 fresh.fmb.la.
      2 future.net.uk.
      6 gateway.devices.a2z.com.
     22 hwcdn.net.
     25 iadb.isipp.com.
      7 ie.internal.unity3d.com.
      5 kube.t-mobile.com.
     22 list.dnswl.org.
      1 live.eks.hotjar.com.
      3 llnwd.net.
      6 llnwi.net.
     28 lookup.dkimwl.org.
      2 loris.llnwd.net.
      1 m1.com.sg.
      1 mlsmatrix.com.
      2 mobile.crashtracking.prod.ring.com.
    122 multi.surbl.org.
    122 multi.uribl.com.
      2 mx.
      8 nflxso.net.
      2 omni03.prd-aws-us-east-1.k8s.jwp.io.
      2 parsely.com.
      1 playback.live-video.net.
      2 prod-1.us-east-1.mdcs.mshop.amazon.dev.
     33 prod.lkt.is.
      1 prod.us-east-1.cxm-bcn.publisher-services.amazon.dev.
      8 prod.us-east-1.forester.a2z.com.
     34 psbl.surriel.com.
      1 pubnative.net.
      1 redeglobaltelecom.net.br.
     27 row.aiv-cdn.net.
      2 rtb.quantserve.net.
      1 ru4.com.
      1 s001.iad.prod.t200.ter.int.amazonvideo.com.
      1 s002.iad.prod.t100.ter.int.amazonvideo.com.
     10 samsungcloud.com.
      1 sc-gw.com.
      2 spearad.video.
      4 _spf.sparkpostmail.com.
      8 ss-domain.com.
      2 supersonicads.com.
      3 tmus.io.
      1 unified-prod.sharethis.net.
      5 us-east-1-2.telemetry.insights.video.a2z.com.
     36 us-east-1.elb.amazonaws.com.
     47 us-east-1.prod.service.minerva.devices.a2z.com.
      2 us-east-2.elb.amazonaws.com.
      3 us-west-2.compute.amazonaws.com.
      3 us-west-2.elb.amazonaws.com.
      1 visioncritical.com.
      3 wtxcdn.com.
    966 zen.spamhaus.org.

Any DNS queries that are not for hosts local to our network are forwarded.
Here is the output of named-checkconf -px:

controls {
        inet 127.0.0.1 allow {
                "localhost";
        } keys {
                "rndc-key";
        };
};
options {
        directory "/var/named";
        dump-file "/var/named/data/cache_dump.db";
        geoip-directory "/usr/share/GeoIP";
        listen-on-v6 port 53 {
                "any";
        };
        managed-keys-directory "/var/named/dynamic";
        memstatistics-file "/var/named/data/named_mem_stats.txt";
        pid-file "/run/named/named.pid";
        session-keyfile "/run/named/session.key";
        statistics-file "/var/named/data/named_stats.txt";
        dnssec-validation auto;
        allow-query {
                "any";
        };
        notify no;
};
key "rndc-key" {
        algorithm "hmac-sha256";
        secret "????????????????????????????????????????????";
};
trust-anchors {
        "." initial-ds 20326 8 2 "E06D44B80B8F1D39A95C0B0D7C65D08458E880409BBC683457104237C7F8EC8D";
};
zone "." IN {
        type hint;
        file "named.ca";
};
zone "localhost.localdomain" IN {
        type primary;
        file "named.localhost";
        allow-update {
                "none";
        };
};
zone "localhost" IN {
        type primary;
        file "named.localhost";
        allow-update {
                "none";
        };
};
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 {
        type primary;
        file "named.loopback";
        allow-update {
                "none";
        };
};
zone "1.0.0.127.in-addr.arpa" IN {
        type primary;
        file "named.loopback";
        allow-update {
                "none";
        };
};
zone "0.in-addr.arpa" IN {
        type primary;
        file "named.empty";
        allow-update {
                "none";
        };
};
zone "internal.grifent.com" {
        type master;
        file "master/db.internal.grifent.com";
        allow-update {
                "none";
        };
};
zone "1.168.192.in-addr.arpa" {
        type master;
        file "master/db.192.168.1";
        allow-update {
                "none";
        };
};
zone "15.168.192.in-addr.arpa" {
        type master;
        file "master/db.192.168.15";
        allow-update {
                "none";
        };
};
zone "0.0.0.0.0.0.0.0.0.0.0.0.0.8.E.F.IP6.ARPA" {
        type master;
        file "master/db.fe80::";
        allow-update {
                "none";
        };
};

Comment 4 John Griffiths 2023-09-18 16:15:36 UTC
Sorry. Realized I left the test for "qname" out of the awk command. Command should have been:

cat messages | awk '$6 == "success" && $11  == "qname" {print $8}'  | sed -e "s,^'\(.*\)/[[:alpha:]]'$,\1," | while read NAME; do dig -t SOA $NAME | awk '$4 == "SOA" { print $1 }'; done | sort | uniq -c

But the output is the same.

    211 .
     14 a.akamaiedge.net.
      1 adobe.io.
      3 airtelbroadband.in.
      4 amazontrust.com.
      1 angsrvr.com.
      9 api10.akamai.net.
     15 bidr.io.
     21 bl.score.senderscore.com.
      4 bluecava.com.
      1 byteigtm.com.
      1 ccc.net.il.
     16 c.footprint.net.
      1 claro.net.do.
      2 cloudflare.net.
      4 cloudwm-cdn.com.
      1 content-signature-chains.prod.webservices.mozgcp.net.
      5 d25xi40x97liuc.cloudfront.net.
      1 d2ljcaegf12t2d.cloudfront.net.
    116 dbl.spamhaus.org.
     40 dcs-online-targeting-prd.aws.oath.cloud.
     25 dn.apigee.net.
     73 dnsbl.sorbs.net.
     56 dob.sibl.support-intelligence.net.
      1 e.allegiant.com.
    100 elb.us-east-1.amazonaws.com.
      4 e-planning.net.
      4 fastly.net.
      1 feromedia.eu.
      6 fna.fbcdn.net.
     34 fresh.fmb.la.
      2 future.net.uk.
      6 gateway.devices.a2z.com.
     22 hwcdn.net.
     25 iadb.isipp.com.
      8 ie.internal.unity3d.com.
      5 kube.t-mobile.com.
     22 list.dnswl.org.
      1 live.eks.hotjar.com.
      3 llnwd.net.
      6 llnwi.net.
     28 lookup.dkimwl.org.
      2 loris.llnwd.net.
      1 m1.com.sg.
      1 mlsmatrix.com.
      2 mobile.crashtracking.prod.ring.com.
    122 multi.surbl.org.
    122 multi.uribl.com.
      2 mx.
      8 nflxso.net.
      2 omni03.prd-aws-us-east-1.k8s.jwp.io.
      3 parsely.com.
      1 playback.live-video.net.
      2 prod-1.us-east-1.mdcs.mshop.amazon.dev.
     33 prod.lkt.is.
      1 prod.us-east-1.cxm-bcn.publisher-services.amazon.dev.
      8 prod.us-east-1.forester.a2z.com.
     34 psbl.surriel.com.
      1 pubnative.net.
      1 redeglobaltelecom.net.br.
     27 row.aiv-cdn.net.
      2 rtb.quantserve.net.
      1 ru4.com.
      1 s002.iad.prod.t200.ter.int.amazonvideo.com.
      1 s004.iad.prod.t100.ter.int.amazonvideo.com.
     10 samsungcloud.com.
      1 sc-gw.com.
      2 spearad.video.
      4 _spf.sparkpostmail.com.
      8 ss-domain.com.
      2 supersonicads.com.
      3 tmus.io.
      1 unified-prod.sharethis.net.
      1 us-east-1-1.telemetry.insights.video.a2z.com.
      4 us-east-1-3.telemetry.insights.video.a2z.com.
     37 us-east-1.elb.amazonaws.com.
     47 us-east-1.prod.service.minerva.devices.a2z.com.
      2 us-east-2.elb.amazonaws.com.
      3 us-west-2.compute.amazonaws.com.
      3 us-west-2.elb.amazonaws.com.
      1 visioncritical.com.
      3 wtxcdn.com.
    966 zen.spamhaus.org.

Comment 5 John Griffiths 2023-09-18 16:18:52 UTC
I was able to get the messages ignored by logwatch by adding

*Remove = "success resolving .* after disabling qname minimization due to .*"

/etc/logwatch/conf/services/named.conf

Comment 6 Aoife Moloney 2023-11-23 01:49:00 UTC
This message is a reminder that Fedora Linux 37 is nearing its end of life.
Fedora will stop maintaining and issuing updates for Fedora Linux 37 on 2023-12-05.
It is Fedora's policy to close all bug reports from releases that are no longer
maintained. At that time this bug will be closed as EOL if it remains open with a
'version' of '37'.

Package Maintainer: If you wish for this bug to remain open because you
plan to fix it in a currently maintained version, change the 'version' 
to a later Fedora Linux version. Note that the version field may be hidden.
Click the "Show advanced fields" button if you do not see it.

Thank you for reporting this issue and we are sorry that we were not 
able to fix it before Fedora Linux 37 is end of life. If you would still like 
to see this bug fixed and are able to reproduce it against a later version 
of Fedora Linux, you are encouraged to change the 'version' to a later version
prior to this bug being closed.

Comment 7 Aoife Moloney 2024-01-15 12:20:43 UTC
Fedora Linux 37 entered end-of-life (EOL) status on 2023-12-05.

Fedora Linux 37 is no longer maintained, which means that it
will not receive any further security or bug fix updates. As a result we
are closing this bug.

If you can reproduce this bug against a currently maintained version of Fedora Linux
please feel free to reopen this bug against that version. Note that the version
field may be hidden. Click the "Show advanced fields" button if you do not see
the version field.

If you are unable to reopen this bug, please file a new report against an
active release.

Thank you for reporting this bug and we are sorry it could not be fixed.


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