TCP4Clients statistic is inaccurate

Summary

Empirically in BIND 9.18.27, the value reported in TCP4Clients is wildly inaccurate, significantly exceeding both the current tcp clients value from rndc status and the TCPConnHighWater value.

BIND version affected

BIND 9.18.27 (Extended Support Version) <id:663e6d9>
running on Linux x86_64 5.14.0-427.13.1.el9_4.x86_64 #1 SMP PREEMPT_DYNAMIC Wed Apr 10 10:29:16 EDT 2024
built by make with  '--build=x86_64-redhat-linux-gnu' '--host=x86_64-redhat-linux-gnu' '--program-prefix=' '--disable-dependency-tracking' '--prefix=/opt/isc/isc-bind/root/usr' '--exec-prefix=/opt/isc/isc-bind/root/usr' '--bindir=/opt/isc/isc-bind/root/usr/bin' '--sbindir=/opt/isc/isc-bind/root/usr/sbin' '--sysconfdir=/etc/opt/isc/scls/isc-bind' '--datadir=/opt/isc/isc-bind/root/usr/share' '--includedir=/opt/isc/isc-bind/root/usr/include' '--libdir=/opt/isc/isc-bind/root/usr/lib64' '--libexecdir=/opt/isc/isc-bind/root/usr/libexec' '--localstatedir=/var/opt/isc/scls/isc-bind' '--sharedstatedir=/var/opt/isc/scls/isc-bind/lib' '--mandir=/opt/isc/isc-bind/root/usr/share/man' '--infodir=/opt/isc/isc-bind/root/usr/share/info' '--enable-warn-error' '--disable-static' '--enable-dnstap' '--with-pic' '--with-gssapi' '--with-json-c' '--with-libxml2' '--without-lmdb' 'build_alias=x86_64-redhat-linux-gnu' 'host_alias=x86_64-redhat-linux-gnu' 'CC=gcc' 'CFLAGS=-O2 -flto=auto -ffat-lto-objects -fexceptions -g -grecord-gcc-switches -pipe -Wall -Werror=format-security -Wp,-D_FORTIFY_SOURCE=2 -Wp,-D_GLIBCXX_ASSERTIONS -specs=/usr/lib/rpm/redhat/redhat-hardened-cc1 -fstack-protector-strong -specs=/usr/lib/rpm/redhat/redhat-annobin-cc1  -m64 -march=x86-64-v2 -mtune=generic -fasynchronous-unwind-tables -fstack-clash-protection -fcf-protection -fno-omit-frame-pointer' 'LDFLAGS=-Wl,-z,relro -Wl,--as-needed  -Wl,-z,now -specs=/usr/lib/rpm/redhat/redhat-hardened-ld -specs=/usr/lib/rpm/redhat/redhat-annobin-cc1  -L/opt/isc/isc-bind/root/usr/lib64' 'CPPFLAGS= -I/opt/isc/isc-bind/root/usr/include' 'LT_SYS_LIBRARY_PATH=/usr/lib64' 'PKG_CONFIG_PATH=:/opt/isc/isc-bind/root/usr/lib64/pkgconfig:/opt/isc/isc-bind/root/usr/share/pkgconfig' 'SPHINX_BUILD=/builddir/build/BUILD/bind-9.18.27/sphinx/bin/sphinx-build'
compiled by GCC 11.4.1 20231218 (Red Hat 11.4.1-3)
compiled with OpenSSL version: OpenSSL 3.0.7 1 Nov 2022
linked to OpenSSL version: OpenSSL 3.0.7 1 Nov 2022
compiled with libuv version: 1.44.2
linked to libuv version: 1.44.2
compiled with libnghttp2 version: 1.43.0
linked to libnghttp2 version: 1.43.0
compiled with libxml2 version: 2.9.13
linked to libxml2 version: 20913
compiled with json-c version: 0.14
linked to json-c version: 0.14
compiled with zlib version: 1.2.11
linked to zlib version: 1.2.11
compiled with protobuf-c version: 1.4.1
linked to protobuf-c version: 1.4.1
threads support is enabled
DNSSEC algorithms: RSASHA256 RSASHA512 ECDSAP256SHA256 ECDSAP384SHA384 ED25519 ED448
DS algorithms: SHA-1 SHA-256 SHA-384
HMAC algorithms: HMAC-MD5 HMAC-SHA1 HMAC-SHA224 HMAC-SHA256 HMAC-SHA384 HMAC-SHA512
TKEY mode 2 support (Diffie-Hellman): yes
TKEY mode 3 support (GSS-API): yes

default paths:
  named configuration:  /etc/opt/isc/scls/isc-bind/named.conf
  rndc configuration:   /etc/opt/isc/scls/isc-bind/rndc.conf
  DNSSEC root key:      /etc/opt/isc/scls/isc-bind/bind.keys
  nsupdate session key: /var/opt/isc/scls/isc-bind/run/named/session.key
  named PID file:       /var/opt/isc/scls/isc-bind/run/named/named.pid
  named lock file:      /var/opt/isc/scls/isc-bind/run/named/named.lock

Steps to reproduce

1. Run BIND 9.18.27 as a recursive nameserver in my production environment (configuration shown below with minor annotated omissions).
2. Monitor TCP4Clients as well as rndc status and observe huge discrepancies.

I'm sorry, I do not know specifically what sort of behavior triggers the discrepancies.

What is the current bug behavior?

After running for about 2 days in my production environment, I see TCP4Clients above 100, even though the value reported by rndc status is in the single digits, and the high water mark is 25.

Anecdotally,

[dmrz@resolver2-1 ~]$ echo; rndc status | grep -i ^tcp; curl -s http://localhost:8053/xml/v3/net  | xmllint --xpath "/statistics/server/counters[@type='sockstat']/counter[@name='TCP4Clients']" -; date

tcp clients: 3/150
TCP high-water: 25
<counter name="TCP4Clients">106</counter>
Thu May 23 10:17:58 AM CDT 2024

[dmrz@resolver2-1 ~]$ echo; rndc status | grep -i ^tcp; curl -s http://localhost:8053/xml/v3/net  | xmllint --xpath "/statistics/server/counters[@type='sockstat']/counter[@name='TCP4Clients']" -; date

tcp clients: 0/150
TCP high-water: 25
<counter name="TCP4Clients">103</counter>
Thu May 23 10:18:19 AM CDT 2024

[dmrz@resolver2-1 ~]$ echo; rndc status | grep -i ^tcp; curl -s http://localhost:8053/xml/v3/net  | xmllint --xpath "/statistics/server/counters[@type='sockstat']/counter[@
name='TCP4Clients']" -; date

tcp clients: 3/150
TCP high-water: 25
<counter name="TCP4Clients">108</counter>
Thu May 23 10:37:03 AM CDT 2024

[dmrz@resolver2-1 ~]$ echo; rndc status | grep -i ^tcp; curl -s http://localhost:8053/xml/v3/net  | xmllint --xpath "/statistics/server/counters[@type='sockstat']/counter[@
name='TCP4Clients']" -; date

tcp clients: 0/150
TCP high-water: 25
<counter name="TCP4Clients">109</counter>
Thu May 23 10:38:23 AM CDT 2024

Trend over time (harvested by collectd and stuffed into Splunk) since launching named:

_time	TCP4Clients	TCP6Clients	TCPConnHighWater
2024-05-21T13:30:00.000-05:00	6	1	19
2024-05-21T14:00:00.000-05:00	9	1	25
2024-05-21T14:30:00.000-05:00	11	3	25
2024-05-21T15:00:00.000-05:00	18	2	25
2024-05-21T15:30:00.000-05:00	17	0	25
2024-05-21T16:00:00.000-05:00	19	1	25
2024-05-21T16:30:00.000-05:00	18	1	25
2024-05-21T17:00:00.000-05:00	21	1	25
2024-05-21T17:30:00.000-05:00	21	0	25
2024-05-21T18:00:00.000-05:00	22	0	25
2024-05-21T18:30:00.000-05:00	23	1	25
2024-05-21T19:00:00.000-05:00	23	0	25
2024-05-21T19:30:00.000-05:00	26	2	25
2024-05-21T20:00:00.000-05:00	23	1	25
2024-05-21T20:30:00.000-05:00	26	2	25
2024-05-21T21:00:00.000-05:00	25	1	25
2024-05-21T21:30:00.000-05:00	25	1	25
2024-05-21T22:00:00.000-05:00	24	1	25
2024-05-21T22:30:00.000-05:00	24	3	25
2024-05-21T23:00:00.000-05:00	25	1	25
2024-05-21T23:30:00.000-05:00	25	1	25
2024-05-22T00:00:00.000-05:00	26	2	25
2024-05-22T00:30:00.000-05:00	25	1	25
2024-05-22T01:00:00.000-05:00	26	2	25
2024-05-22T01:30:00.000-05:00	27	1	25
2024-05-22T02:00:00.000-05:00	26	1	25
2024-05-22T02:30:00.000-05:00	26	1	25
2024-05-22T03:00:00.000-05:00	28	1	25
2024-05-22T03:30:00.000-05:00	27	2	25
2024-05-22T04:00:00.000-05:00	29	1	25
2024-05-22T04:30:00.000-05:00	27	1	25
2024-05-22T05:00:00.000-05:00	28	2	25
2024-05-22T05:30:00.000-05:00	29	2	25
2024-05-22T06:00:00.000-05:00	30	1	25
2024-05-22T06:30:00.000-05:00	28	1	25
2024-05-22T07:00:00.000-05:00	30	1	25
2024-05-22T07:30:00.000-05:00	30	1	25
2024-05-22T08:00:00.000-05:00	34	1	25
2024-05-22T08:30:00.000-05:00	36	2	25
2024-05-22T09:00:00.000-05:00	37	2	25
2024-05-22T09:30:00.000-05:00	39	2	25
2024-05-22T10:00:00.000-05:00	49	3	25
2024-05-22T10:30:00.000-05:00	46	8	25
2024-05-22T11:00:00.000-05:00	53	4	25
2024-05-22T11:30:00.000-05:00	57	3	25
2024-05-22T12:00:00.000-05:00	58	3	25
2024-05-22T12:30:00.000-05:00	60	3	25
2024-05-22T13:00:00.000-05:00	67	3	25
2024-05-22T13:30:00.000-05:00	66	3	25
2024-05-22T14:00:00.000-05:00	69	3	25
2024-05-22T14:30:00.000-05:00	69	2	25
2024-05-22T15:00:00.000-05:00	73	3	25
2024-05-22T15:30:00.000-05:00	80	2	25
2024-05-22T16:00:00.000-05:00	78	4	25
2024-05-22T16:30:00.000-05:00	80	2	25
2024-05-22T17:00:00.000-05:00	80	3	25
2024-05-22T17:30:00.000-05:00	79	3	25
2024-05-22T18:00:00.000-05:00	79	4	25
2024-05-22T18:30:00.000-05:00	78	3	25
2024-05-22T19:00:00.000-05:00	80	3	25
2024-05-22T19:30:00.000-05:00	79	3	25
2024-05-22T20:00:00.000-05:00	82	3	25
2024-05-22T20:30:00.000-05:00	82	3	25
2024-05-22T21:00:00.000-05:00	82	3	25
2024-05-22T21:30:00.000-05:00	85	4	25
2024-05-22T22:00:00.000-05:00	85	4	25
2024-05-22T22:30:00.000-05:00	86	5	25
2024-05-22T23:00:00.000-05:00	85	5	25
2024-05-22T23:30:00.000-05:00	86	4	25
2024-05-23T00:00:00.000-05:00	88	4	25
2024-05-23T00:30:00.000-05:00	85	5	25
2024-05-23T01:00:00.000-05:00	87	5	25
2024-05-23T01:30:00.000-05:00	86	5	25
2024-05-23T02:00:00.000-05:00	88	6	25
2024-05-23T02:30:00.000-05:00	87	5	25
2024-05-23T03:00:00.000-05:00	86	6	25
2024-05-23T03:30:00.000-05:00	86	5	25
2024-05-23T04:00:00.000-05:00	88	6	25
2024-05-23T04:30:00.000-05:00	88	6	25
2024-05-23T05:00:00.000-05:00	90	5	25
2024-05-23T05:30:00.000-05:00	89	5	25
2024-05-23T06:00:00.000-05:00	87	5	25
2024-05-23T06:30:00.000-05:00	88	5	25
2024-05-23T07:00:00.000-05:00	89	5	25
2024-05-23T07:30:00.000-05:00	89	5	25
2024-05-23T08:00:00.000-05:00	91	5	25
2024-05-23T08:30:00.000-05:00	94	5	25
2024-05-23T09:00:00.000-05:00	97	6	25
2024-05-23T09:30:00.000-05:00	107	5	25
2024-05-23T10:00:00.000-05:00	108	5	25
2024-05-23T10:30:00.000-05:00	111	6	25

What is the expected correct behavior?

I believe the sum of TCP4Clients + TCP6Clients should roughly correspond to the current tcp clients value from rndc status and should not exceed the high watermark value.

AFAICT these values' descriptions are missing from https://bind9.readthedocs.io/en/v9.18.27/reference.html#bind-9-statistics, so my expectation is based on "The statistics channel now includes counters that indicate the number of currently connected TCP IPv4/IPv6 clients." from release notes plus the context in #4425 (closed)

Relevant configuration files

// OMITTED: 7 acl statements
controls {
	inet 127.0.0.1 port 953 allow {
		127.0.0.1/32;
	} keys {
		"rndc-key";
	};
};
logging {
	channel "local_errors_channel" {
		file "/var/opt/isc/scls/isc-bind/log/named/errors.log" versions 5 size 20971520 suffix increment;
		severity error;
		print-time iso8601-utc;
		print-severity yes;
		print-category yes;
	};
	channel "local_warnings_channel" {
		file "/var/opt/isc/scls/isc-bind/log/named/errors.log" versions 5 size 20971520 suffix increment;
		severity warning;
		print-time iso8601-utc;
		print-severity yes;
		print-category yes;
	};
	channel "queries_channel" {
		file "/var/opt/isc/scls/isc-bind/log/named/queries.log" versions 9 size 209715200 suffix increment;
		severity info;
		print-time iso8601-utc;
		print-severity yes;
		print-category yes;
	};
	channel "query-errors_channel" {
		file "/var/opt/isc/scls/isc-bind/log/named/query-errors.log" versions 2 size 52428800 suffix increment;
		severity dynamic;
		print-time iso8601-utc;
		print-severity yes;
		print-category yes;
	};
	channel "network_channel" {
		file "/var/opt/isc/scls/isc-bind/log/named/network.log" versions 2 size 20971520 suffix increment;
		severity info;
		print-time iso8601-utc;
		print-severity yes;
		print-category yes;
	};
	channel "notify_channel" {
		file "/var/opt/isc/scls/isc-bind/log/named/notify.log" versions 2 size 20971520 suffix increment;
		severity info;
		print-time iso8601-utc;
		print-severity yes;
		print-category yes;
	};
	channel "lame-servers_channel" {
		file "/var/opt/isc/scls/isc-bind/log/named/lame-servers.log" versions 2 size 20971520 suffix increment;
		severity info;
		print-time iso8601-utc;
		print-severity yes;
		print-category yes;
	};
	channel "resolver_channel" {
		file "/var/opt/isc/scls/isc-bind/log/named/resolver.log" versions 2 size 20971520 suffix increment;
		severity info;
		print-time iso8601-utc;
		print-severity yes;
		print-category yes;
	};
	channel "rpz_channel" {
		file "/var/opt/isc/scls/isc-bind/log/named/rpz.log" versions 2 size 20971520 suffix increment;
		severity info;
		print-time iso8601-utc;
		print-severity yes;
		print-category yes;
	};
	channel "security_channel" {
		file "/var/opt/isc/scls/isc-bind/log/named/security.log" versions 2 size 20971520 suffix increment;
		severity info;
		print-time iso8601-utc;
		print-severity yes;
		print-category yes;
	};
	channel "default_channel" {
		file "/var/opt/isc/scls/isc-bind/log/named/named.log" versions 5 size 20971520 suffix increment;
		severity info;
		print-time iso8601-utc;
		print-severity yes;
		print-category yes;
	};
	category "queries" {
		"queries_channel";
	};
	category "query-errors" {
		"query-errors_channel";
	};
	category "network" {
		"network_channel";
		"local_errors_channel";
	};
	category "notify" {
		"notify_channel";
		"local_errors_channel";
	};
	category "lame-servers" {
		"lame-servers_channel";
	};
	category "edns-disabled" {
		"null";
	};
	category "resolver" {
		"resolver_channel";
		"local_errors_channel";
	};
	category "serve-stale" {
		"resolver_channel";
		"local_errors_channel";
	};
	category "cname" {
		"resolver_channel";
		"local_errors_channel";
	};
	category "rpz" {
		"rpz_channel";
		"local_warnings_channel";
	};
	category "rpz-passthru" {
		"null";
	};
	category "security" {
		"security_channel";
	};
	category "update-security" {
		"security_channel";
	};
	category "default" {
		"default_channel";
		"local_errors_channel";
	};
};
options {
	cookie-algorithm siphash24;
	cookie-secret "????????????????????????????????";
	directory "/var/opt/isc/scls/isc-bind/named/data";
	interface-interval 0;
	querylog yes;
	recursive-clients 6000;
	server-id hostname;
	tcp-listen-queue 100;
	udp-receive-buffer 20000000;
	version none;
	dnssec-validation no;
	max-cache-size 80%;
	max-cache-ttl 900;
	max-ncache-ttl 900;
	min-cache-ttl 1;
	min-ncache-ttl 1;
	no-case-compress {
		"any";
	};
	recursion yes;
	require-server-cookie no;
	response-policy {
		zone "rpz-hardcoded.local" log no max-policy-ttl 86400;
		zone "rpz-security.local" policy cname "protection.illinois.edu";
	} max-policy-ttl 5;
	stale-answer-enable yes;
	stale-answer-client-timeout 1800;
	stale-answer-ttl 60;
	stale-cache-enable yes;
	// OMITTED: allow-query
	allow-transfer  {
		"none";
	};
	masterfile-format text;
	max-transfer-idle-in 15;
	max-transfer-time-in 15;
	notify explicit;
};
primaries "adns" {
	130.126.2.100 key "resolver-key";
	130.126.2.120 key "resolver-key";
	3.16.92.183 key "resolver-key";
};
statistics-channels {
	inet 127.0.0.1 port 8053 allow {
		127.0.0.1/32;
	};
};
key "defaultviewkey" {
	algorithm "hmac-md5";
	secret "????????????????????????";
};
key "resolver-key" {
	algorithm "hmac-sha256";
	secret "????????????????????????????????????????????";
};
key "rndc-key" {
	algorithm "hmac-sha256";
	secret "????????????????????????????????????????????";
};
server 192.168.0.0/16 {
	bogus yes;
};
zone "rpz-hardcoded.local" {
	type primary;
	file "/etc/opt/isc/scls/isc-bind/rpz-hardcoded.local.zone";
	allow-query {
		"localhost";
	};
	allow-transfer  {
		"localhost";
	};
};
zone "rpz-security.local" {
	type secondary;
	file "rpz-security.local.zone";
	primaries {
		"adns";
	};
	allow-query {
		"localhost";
	};
	allow-transfer  {
		"localhost";
	};
};
zone "illinois.edu" {
	type stub;
	file "var/named/default/illinois.edu";
	masters {
		130.126.2.100;
		130.126.2.120;
		3.16.92.183;
	};
};
// OMITTED: about 500 more stub zones like the one above

Relevant logs