The "main" memory context may not be clean upon exit, causing crashes
I saw the shutdown
test fail three times (50 % of times) on FreeBSD 11 & 12 on main
(9dcf2296):
S:shutdown:2020-07-21T08:24:29+0000
T:shutdown:1:A
A:shutdown:System test shutdown
I:shutdown:PORTS:25125,25126,25127,25128,25129,25130,25131,25132,25133,25134
I:shutdown:starting servers
D:shutdown:============================= test session starts ==============================
D:shutdown:platform freebsd11 -- Python 3.7.7, pytest-4.5.0, py-1.8.1, pluggy-0.12.0 -- /usr/local/bin/python3.7
D:shutdown:cachedir: .pytest_cache
D:shutdown:rootdir: /builds/isc-projects/bind9/bin/tests/system/shutdown
D:shutdown:collecting ... collected 1 item
D:shutdown:
D:shutdown:tests-shutdown.py::test_named_shutdown FAILED [100%]
D:shutdown:
D:shutdown:=================================== FAILURES ===================================
D:shutdown:_____________________________ test_named_shutdown ______________________________
D:shutdown:
D:shutdown:named_port = 25125, control_port = 25134
D:shutdown:
D:shutdown:@pytest.mark.dnspython
D:shutdown:def test_named_shutdown(named_port, control_port):
D:shutdown:# pylint: disable-msg=too-many-locals
D:shutdown:cfg_dir = os.path.join(os.getcwd(), "resolver")
D:shutdown:assert os.path.isdir(cfg_dir)
D:shutdown:
D:shutdown:cfg_file = os.path.join(cfg_dir, "named.conf")
D:shutdown:assert os.path.isfile(cfg_file)
D:shutdown:
D:shutdown:named = os.getenv("NAMED")
D:shutdown:assert named is not None
D:shutdown:
D:shutdown:rndc = os.getenv("RNDC")
D:shutdown:assert rndc is not None
D:shutdown:
D:shutdown:systest_dir = os.getenv("SYSTEMTESTTOP")
D:shutdown:assert systest_dir is not None
D:shutdown:
D:shutdown:# rndc configuration resides in $SYSTEMTESTTOP/common/rndc.conf
D:shutdown:rndc_cfg = os.path.join(systest_dir, "common", "rndc.conf")
D:shutdown:assert os.path.isfile(rndc_cfg)
D:shutdown:
D:shutdown:# rndc command with default arguments.
D:shutdown:rndc_cmd = [rndc, "-c", rndc_cfg, "-p", str(control_port),
D:shutdown:"-s", "10.53.0.3"]
D:shutdown:
D:shutdown:# Helper function, launch named without blocking.
D:shutdown:def launch_named():
D:shutdown:proc = subprocess.Popen([named, "-c", cfg_file, "-f"], cwd=cfg_dir)
D:shutdown:# Ensure named is running
D:shutdown:assert proc.poll() is None
D:shutdown:
D:shutdown:return proc
D:shutdown:
D:shutdown:# We create a resolver instance that will be used to send queries.
D:shutdown:resolver = dns.resolver.Resolver()
D:shutdown:resolver.nameservers = ['10.53.0.3']
D:shutdown:resolver.port = named_port
D:shutdown:
D:shutdown:# We test named shutting down using two methods:
D:shutdown:# Method 1: using rndc ctop
D:shutdown:# Method 2: killing with SIGTERM
D:shutdown:# In both methods named should exit gracefully.
D:shutdown:for kill_method in ("rndc", "sigterm"):
D:shutdown:named_proc = launch_named()
D:shutdown:time.sleep(2)
D:shutdown:
D:shutdown:do_work(named_proc, resolver, rndc_cmd,
D:shutdown:kill_method, n_workers=12, n_queries=16)
D:shutdown:
D:shutdown:# Wait named to exit for a maximum of MAX_TIMEOUT seconds.
D:shutdown:MAX_TIMEOUT = 10
D:shutdown:is_dead = False
D:shutdown:for _ in range(MAX_TIMEOUT):
D:shutdown:if named_proc.poll() is not None:
D:shutdown:is_dead = True
D:shutdown:break
D:shutdown:time.sleep(1)
D:shutdown:
D:shutdown:if not is_dead:
D:shutdown:named_proc.kill()
D:shutdown:
D:shutdown:assert is_dead
D:shutdown:# Ensures that named exited gracefully.
D:shutdown:# If it crashed (abort()) exitcode will be non zero.
D:shutdown:> assert named_proc.returncode == 0
D:shutdown:E assert -6 == 0
D:shutdown:E --6
D:shutdown:E +0
D:shutdown:
D:shutdown:tests-shutdown.py:193: AssertionError
D:shutdown:----------------------------- Captured stdout call -----------------------------
D:shutdown:version: BIND 9.17.3 (Development Release) <id:b59e691>
D:shutdown:running on freebsd: FreeBSD amd64 11.4-RELEASE FreeBSD 11.4-RELEASE #0 r362094: Fri Jun 12 18:27:15 UTC 2020 root@releng2.nyi.freebsd.org:/usr/obj/usr/src/sys/GENERIC
D:shutdown:boot time: Tue, 21 Jul 2020 08:24:34 GMT
D:shutdown:last configured: Tue, 21 Jul 2020 08:24:34 GMT
D:shutdown:configuration file: /builds/isc-projects/bind9/bin/tests/system/shutdown/resolver/named.conf
D:shutdown:CPUs found: 4
D:shutdown:worker threads: 4
D:shutdown:UDP listeners per interface: 4
D:shutdown:number of zones: 100 (99 automatic)
D:shutdown:debug level: 0
D:shutdown:xfers running: 0
D:shutdown:xfers deferred: 0
D:shutdown:soa queries in progress: 0
D:shutdown:query logging is OFF
D:shutdown:recursive clients: 0/900/1000
D:shutdown:tcp clients: 0/150
D:shutdown:TCP high-water: 0
D:shutdown:server is up and running
D:shutdown:version: BIND 9.17.3 (Development Release) <id:b59e691>
D:shutdown:running on freebsd: FreeBSD amd64 11.4-RELEASE FreeBSD 11.4-RELEASE #0 r362094: Fri Jun 12 18:27:15 UTC 2020 root@releng2.nyi.freebsd.org:/usr/obj/usr/src/sys/GENERIC
D:shutdown:boot time: Tue, 21 Jul 2020 08:24:34 GMT
D:shutdown:last configured: Tue, 21 Jul 2020 08:24:34 GMT
D:shutdown:configuration file: /builds/isc-projects/bind9/bin/tests/system/shutdown/resolver/named.conf
D:shutdown:CPUs found: 4
D:shutdown:worker threads: 4
D:shutdown:UDP listeners per interface: 4
D:shutdown:number of zones: 100 (99 automatic)
D:shutdown:debug level: 0
D:shutdown:xfers running: 0
D:shutdown:xfers deferred: 0
D:shutdown:soa queries in progress: 0
D:shutdown:query logging is OFF
D:shutdown:recursive clients: 0/900/1000
D:shutdown:tcp clients: 0/150
D:shutdown:TCP high-water: 0
D:shutdown:server is up and running
D:shutdown:version: BIND 9.17.3 (Development Release) <id:b59e691>
D:shutdown:running on freebsd: FreeBSD amd64 11.4-RELEASE FreeBSD 11.4-RELEASE #0 r362094: Fri Jun 12 18:27:15 UTC 2020 root@releng2.nyi.freebsd.org:/usr/obj/usr/src/sys/GENERIC
D:shutdown:boot time: Tue, 21 Jul 2020 08:24:34 GMT
D:shutdown:last configured: Tue, 21 Jul 2020 08:24:34 GMT
D:shutdown:configuration file: /builds/isc-projects/bind9/bin/tests/system/shutdown/resolver/named.conf
D:shutdown:CPUs found: 4
D:shutdown:worker threads: 4
D:shutdown:UDP listeners per interface: 4
D:shutdown:number of zones: 100 (99 automatic)
D:shutdown:debug level: 0
D:shutdown:xfers running: 0
D:shutdown:xfers deferred: 0
D:shutdown:soa queries in progress: 0
D:shutdown:query logging is OFF
D:shutdown:recursive clients: 0/900/1000
D:shutdown:tcp clients: 0/150
D:shutdown:TCP high-water: 0
D:shutdown:server is up and running
D:shutdown:----------------------------- Captured stderr call -----------------------------
D:shutdown:rndc: connection to remote host closed.
D:shutdown:* This may indicate that the
D:shutdown:* remote server is using an older
D:shutdown:* version of the command protocol,
D:shutdown:* this host is not authorized to connect,
D:shutdown:* the clocks are not synchronized,
D:shutdown:* the key signing algorithm is incorrect,
D:shutdown:* or the key is invalid.
D:shutdown:rndc: connection to remote host closed.
D:shutdown:* This may indicate that the
D:shutdown:* remote server is using an older
D:shutdown:* version of the command protocol,
D:shutdown:* this host is not authorized to connect,
D:shutdown:* the clocks are not synchronized,
D:shutdown:* the key signing algorithm is incorrect,
D:shutdown:* or the key is invalid.
D:shutdown:rndc: connection to remote host closed.
D:shutdown:* This may indicate that the
D:shutdown:* remote server is using an older
D:shutdown:* version of the command protocol,
D:shutdown:* this host is not authorized to connect,
D:shutdown:* the clocks are not synchronized,
D:shutdown:* the key signing algorithm is incorrect
D:shutdown:* or the key is invalid.
D:shutdown:rndc: connection to remote host closed.
D:shutdown:* This may indicate that the
D:shutdown:* remote server is using an older
D:shutdown:* version of the command protocol,
D:shutdown:* this host is not authorized to connect,
D:shutdown:* the clocks are not synchronized,
D:shutdown:* the key signing algorithm is incorrect,
D:shutdown:* or the key is invalid.
D:shutdown:Failing assertion due to probable leaked memory in context 0x805c23000 ("main") (stats[9].gets == 3).
D:shutdown:mem.c:893: INSIST(ctx->stats[i].gets == 0U) failed
D:shutdown:=========================== 1 failed in 6.57 seconds ===========================
I:system:FAILED
I:shutdown:stopping servers
I:shutdown:Core dump(s) found: shutdown/resolver/core.43405
D:shutdown:backtrace from shutdown/resolver/core.43405:
D:shutdown:--------------------------------------------------------------------------------
D:shutdown:Core was generated by `/builds/isc-projects/bind9/bin/named/.libs/named -c /builds/isc-projects/bind9/b'.
D:shutdown:Program terminated with signal SIGABRT, Aborted.
D:shutdown:#0 0x0000000804b1b0ba in thr_kill () from /lib/libc.so.7
D:shutdown:#0 0x0000000804b1b0ba in thr_kill () from /lib/libc.so.7
D:shutdown:#1 0x0000000804b1b084 in raise () from /lib/libc.so.7
D:shutdown:#2 0x0000000804b1aff9 in abort () from /lib/libc.so.7
D:shutdown:#3 0x000000000041c612 in assertion_failed (file=<optimized out>, line=<optimized out>, type=isc_assertiontype_insist, cond=<optimized out>) at main.c:253
D:shutdown:#4 0x00000008008c144a in isc_assertion_failed (file=0x18b57 <error: Cannot access memory at address 0x18b57>, line=6, type=isc_assertiontype_require, cond=0x804b1b0da <thr_self+10> "\017\202\204\350\b") at assertions.c:46
D:shutdown:#5 0x00000008008ce783 in destroy (ctx=0x805c23000) at mem.c:893
D:shutdown:#6 0x00000008008ceb76 in isc_mem_destroy (ctxp=0x674fc0 <named_g_mctx>) at mem.c:1021
D:shutdown:#7 0x000000000041c55f in main (argc=<optimized out>, argv=<optimized out>) at main.c:1573
D:shutdown:--------------------------------------------------------------------------------
D:shutdown:full backtrace from shutdown/resolver/core.43405 saved in core.43405-backtrace.txt
D:shutdown:core dump shutdown/resolver/core.43405 archived as shutdown/resolver/core.43405.gz
R:shutdown:FAIL
E:shutdown:2020-07-21T08:24:42+0000
FAIL shutdown (exit status: 1)