Use helper Python classes for watching log files

Make log file watching in Python-based system tests consistent by
employing the helper Python classes designed for that purpose.  Drop the
custom code currently used.

diff --git a/bin/tests/system/checkds/tests_checkds.py b/bin/tests/system/checkds/tests_checkds.py
index 515f3ff8eb73db80637b122958bafa800abe0373..f68ec8a451a4b7e87b6168ee0b44bb60816ca744 100755 (executable)
--- a/bin/tests/system/checkds/tests_checkds.py
+++ b/bin/tests/system/checkds/tests_checkds.py
@@ -11,7 +11,6 @@
 # See the COPYRIGHT file distributed with this work for additional
 # information regarding copyright ownership.
 
-import mmap
 import os
 import subprocess
 import sys
@@ -261,33 +260,7 @@ def rekey(zone):
     assert controller.returncode == 0
 
 
-def wait_for_log(filename, zone, log):
-    found = False
-
-    for _ in range(10):
-        print("read log file {}".format(filename))
-
-        try:
-            with open(filename, "r", encoding="utf-8") as file:
-                s = mmap.mmap(file.fileno(), 0, access=mmap.ACCESS_READ)
-                if s.find(bytes(log, "ascii")) != -1:
-                    found = True
-        except FileNotFoundError:
-            print("file not found {}".format(filename))
-
-        if found:
-            break
-
-        print("rekey")
-        rekey(zone)
-
-        print("sleep")
-        time.sleep(1)
-
-    assert found
-
-
-def checkds_dspublished(named_port, checkds, addr):
+def checkds_dspublished(named_port, servers, checkds, addr):
     # We create resolver instances that will be used to send queries.
     server = dns.resolver.Resolver()
     server.nameservers = ["10.53.0.9"]
@@ -305,11 +278,9 @@ def checkds_dspublished(named_port, checkds, addr):
     # The simple case.
     zone = "good.{}.dspublish.ns2".format(checkds)
     zone_check(server, zone)
-    wait_for_log(
-        "ns9/named.run",
-        zone,
-        "zone {}/IN (signed): checkds: DS response from {}".format(zone, addr),
-    )
+    with servers["ns9"].watch_log_from_start() as watcher:
+        line = f"zone {zone}/IN (signed): checkds: DS response from {addr}"
+        watcher.wait_for_line(line)
     keystate_check(parent, zone, "DSPublish")
 
     #
@@ -318,11 +289,9 @@ def checkds_dspublished(named_port, checkds, addr):
     #
     zone = "not-yet.{}.dspublish.ns5".format(checkds)
     zone_check(server, zone)
-    wait_for_log(
-        "ns9/named.run",
-        zone,
-        "zone {}/IN (signed): checkds: empty DS response from 10.53.0.5".format(zone),
-    )
+    with servers["ns9"].watch_log_from_start() as watcher:
+        line = f"zone {zone}/IN (signed): checkds: empty DS response from 10.53.0.5"
+        watcher.wait_for_line(line)
     keystate_check(parent, zone, "!DSPublish")
 
     #
@@ -332,19 +301,13 @@ def checkds_dspublished(named_port, checkds, addr):
     zone = "bad.{}.dspublish.ns6".format(checkds)
     zone_check(server, zone)
     if checkds == "explicit":
-        wait_for_log(
-            "ns9/named.run",
-            zone,
-            "zone {}/IN (signed): checkds: bad DS response from 10.53.0.6".format(zone),
-        )
+        with servers["ns9"].watch_log_from_start() as watcher:
+            line = f"zone {zone}/IN (signed): checkds: bad DS response from 10.53.0.6"
+            watcher.wait_for_line(line)
     elif checkds == "yes":
-        wait_for_log(
-            "ns9/named.run",
-            zone,
-            "zone {}/IN (signed): checkds: error during parental-agents processing".format(
-                zone
-            ),
-        )
+        with servers["ns9"].watch_log_from_start() as watcher:
+            line = f"zone {zone}/IN (signed): checkds: error during parental-agents processing"
+            watcher.wait_for_line(line)
     keystate_check(parent, zone, "!DSPublish")
 
     #
@@ -358,16 +321,12 @@ def checkds_dspublished(named_port, checkds, addr):
     #
     zone = "good.{}.dspublish.ns2-4".format(checkds)
     zone_check(server, zone)
-    wait_for_log(
-        "ns9/named.run",
-        zone,
-        "zone {}/IN (signed): checkds: DS response from {}".format(zone, addr),
-    )
-    wait_for_log(
-        "ns9/named.run",
-        zone,
-        "zone {}/IN (signed): checkds: DS response from 10.53.0.4".format(zone),
-    )
+    with servers["ns9"].watch_log_from_start() as watcher:
+        line = f"zone {zone}/IN (signed): checkds: DS response from {addr}"
+        watcher.wait_for_line(line)
+    with servers["ns9"].watch_log_from_start() as watcher:
+        line = f"zone {zone}/IN (signed): checkds: DS response from 10.53.0.4"
+        watcher.wait_for_line(line)
     keystate_check(parent, zone, "DSPublish")
 
     #
@@ -376,21 +335,15 @@ def checkds_dspublished(named_port, checkds, addr):
     #
     zone = "incomplete.{}.dspublish.ns2-4-5".format(checkds)
     zone_check(server, zone)
-    wait_for_log(
-        "ns9/named.run",
-        zone,
-        "zone {}/IN (signed): checkds: DS response from {}".format(zone, addr),
-    )
-    wait_for_log(
-        "ns9/named.run",
-        zone,
-        "zone {}/IN (signed): checkds: DS response from 10.53.0.4".format(zone),
-    )
-    wait_for_log(
-        "ns9/named.run",
-        zone,
-        "zone {}/IN (signed): checkds: empty DS response from 10.53.0.5".format(zone),
-    )
+    with servers["ns9"].watch_log_from_start() as watcher:
+        line = f"zone {zone}/IN (signed): checkds: DS response from {addr}"
+        watcher.wait_for_line(line)
+    with servers["ns9"].watch_log_from_start() as watcher:
+        line = f"zone {zone}/IN (signed): checkds: DS response from 10.53.0.4"
+        watcher.wait_for_line(line)
+    with servers["ns9"].watch_log_from_start() as watcher:
+        line = f"zone {zone}/IN (signed): checkds: empty DS response from 10.53.0.5"
+        watcher.wait_for_line(line)
     keystate_check(parent, zone, "!DSPublish")
 
     #
@@ -399,21 +352,15 @@ def checkds_dspublished(named_port, checkds, addr):
     #
     zone = "bad.{}.dspublish.ns2-4-6".format(checkds)
     zone_check(server, zone)
-    wait_for_log(
-        "ns9/named.run",
-        zone,
-        "zone {}/IN (signed): checkds: DS response from {}".format(zone, addr),
-    )
-    wait_for_log(
-        "ns9/named.run",
-        zone,
-        "zone {}/IN (signed): checkds: DS response from 10.53.0.4".format(zone),
-    )
-    wait_for_log(
-        "ns9/named.run",
-        zone,
-        "zone {}/IN (signed): checkds: bad DS response from 10.53.0.6".format(zone),
-    )
+    with servers["ns9"].watch_log_from_start() as watcher:
+        line = f"zone {zone}/IN (signed): checkds: DS response from {addr}"
+        watcher.wait_for_line(line)
+    with servers["ns9"].watch_log_from_start() as watcher:
+        line = f"zone {zone}/IN (signed): checkds: DS response from 10.53.0.4"
+        watcher.wait_for_line(line)
+    with servers["ns9"].watch_log_from_start() as watcher:
+        line = f"zone {zone}/IN (signed): checkds: bad DS response from 10.53.0.6"
+        watcher.wait_for_line(line)
     keystate_check(parent, zone, "!DSPublish")
 
     #
@@ -425,7 +372,7 @@ def checkds_dspublished(named_port, checkds, addr):
     # TBD: Check with TLS
 
 
-def checkds_dswithdrawn(named_port, checkds, addr):
+def checkds_dswithdrawn(named_port, servers, checkds, addr):
     # We create resolver instances that will be used to send queries.
     server = dns.resolver.Resolver()
     server.nameservers = ["10.53.0.9"]
@@ -443,11 +390,9 @@ def checkds_dswithdrawn(named_port, checkds, addr):
     # The simple case.
     zone = "good.{}.dsremoved.ns5".format(checkds)
     zone_check(server, zone)
-    wait_for_log(
-        "ns9/named.run",
-        zone,
-        "zone {}/IN (signed): checkds: empty DS response from {}".format(zone, addr),
-    )
+    with servers["ns9"].watch_log_from_start() as watcher:
+        line = f"zone {zone}/IN (signed): checkds: empty DS response from {addr}"
+        watcher.wait_for_line(line)
     keystate_check(parent, zone, "DSRemoved")
 
     #
@@ -456,11 +401,9 @@ def checkds_dswithdrawn(named_port, checkds, addr):
     #
     zone = "still-there.{}.dsremoved.ns2".format(checkds)
     zone_check(server, zone)
-    wait_for_log(
-        "ns9/named.run",
-        zone,
-        "zone {}/IN (signed): checkds: DS response from 10.53.0.2".format(zone),
-    )
+    with servers["ns9"].watch_log_from_start() as watcher:
+        line = f"zone {zone}/IN (signed): checkds: DS response from 10.53.0.2"
+        watcher.wait_for_line(line)
     keystate_check(parent, zone, "!DSRemoved")
 
     #
@@ -470,19 +413,13 @@ def checkds_dswithdrawn(named_port, checkds, addr):
     zone = "bad.{}.dsremoved.ns6".format(checkds)
     zone_check(server, zone)
     if checkds == "explicit":
-        wait_for_log(
-            "ns9/named.run",
-            zone,
-            "zone {}/IN (signed): checkds: bad DS response from 10.53.0.6".format(zone),
-        )
+        with servers["ns9"].watch_log_from_start() as watcher:
+            line = f"zone {zone}/IN (signed): checkds: bad DS response from 10.53.0.6"
+            watcher.wait_for_line(line)
     elif checkds == "yes":
-        wait_for_log(
-            "ns9/named.run",
-            zone,
-            "zone {}/IN (signed): checkds: error during parental-agents processing".format(
-                zone
-            ),
-        )
+        with servers["ns9"].watch_log_from_start() as watcher:
+            line = f"zone {zone}/IN (signed): checkds: error during parental-agents processing"
+            watcher.wait_for_line(line)
     keystate_check(parent, zone, "!DSRemoved")
 
     #
@@ -496,16 +433,12 @@ def checkds_dswithdrawn(named_port, checkds, addr):
     #
     zone = "good.{}.dsremoved.ns5-7".format(checkds)
     zone_check(server, zone)
-    wait_for_log(
-        "ns9/named.run",
-        zone,
-        "zone {}/IN (signed): checkds: empty DS response from {}".format(zone, addr),
-    )
-    wait_for_log(
-        "ns9/named.run",
-        zone,
-        "zone {}/IN (signed): checkds: empty DS response from 10.53.0.7".format(zone),
-    )
+    with servers["ns9"].watch_log_from_start() as watcher:
+        line = f"zone {zone}/IN (signed): checkds: empty DS response from {addr}"
+        watcher.wait_for_line(line)
+    with servers["ns9"].watch_log_from_start() as watcher:
+        line = f"zone {zone}/IN (signed): checkds: empty DS response from 10.53.0.7"
+        watcher.wait_for_line(line)
     keystate_check(parent, zone, "DSRemoved")
 
     #
@@ -514,21 +447,15 @@ def checkds_dswithdrawn(named_port, checkds, addr):
     #
     zone = "incomplete.{}.dsremoved.ns2-5-7".format(checkds)
     zone_check(server, zone)
-    wait_for_log(
-        "ns9/named.run",
-        zone,
-        "zone {}/IN (signed): checkds: DS response from 10.53.0.2".format(zone),
-    )
-    wait_for_log(
-        "ns9/named.run",
-        zone,
-        "zone {}/IN (signed): checkds: empty DS response from {}".format(zone, addr),
-    )
-    wait_for_log(
-        "ns9/named.run",
-        zone,
-        "zone {}/IN (signed): checkds: empty DS response from 10.53.0.7".format(zone),
-    )
+    with servers["ns9"].watch_log_from_start() as watcher:
+        line = f"zone {zone}/IN (signed): checkds: DS response from 10.53.0.2"
+        watcher.wait_for_line(line)
+    with servers["ns9"].watch_log_from_start() as watcher:
+        line = f"zone {zone}/IN (signed): checkds: empty DS response from {addr}"
+        watcher.wait_for_line(line)
+    with servers["ns9"].watch_log_from_start() as watcher:
+        line = f"zone {zone}/IN (signed): checkds: empty DS response from 10.53.0.7"
+        watcher.wait_for_line(line)
     keystate_check(parent, zone, "!DSRemoved")
 
     #
@@ -537,21 +464,15 @@ def checkds_dswithdrawn(named_port, checkds, addr):
     #
     zone = "bad.{}.dsremoved.ns5-6-7".format(checkds)
     zone_check(server, zone)
-    wait_for_log(
-        "ns9/named.run",
-        zone,
-        "zone {}/IN (signed): checkds: empty DS response from {}".format(zone, addr),
-    )
-    wait_for_log(
-        "ns9/named.run",
-        zone,
-        "zone {}/IN (signed): checkds: empty DS response from 10.53.0.7".format(zone),
-    )
-    wait_for_log(
-        "ns9/named.run",
-        zone,
-        "zone {}/IN (signed): checkds: bad DS response from 10.53.0.6".format(zone),
-    )
+    with servers["ns9"].watch_log_from_start() as watcher:
+        line = f"zone {zone}/IN (signed): checkds: empty DS response from {addr}"
+        watcher.wait_for_line(line)
+    with servers["ns9"].watch_log_from_start() as watcher:
+        line = f"zone {zone}/IN (signed): checkds: empty DS response from 10.53.0.7"
+        watcher.wait_for_line(line)
+    with servers["ns9"].watch_log_from_start() as watcher:
+        line = f"zone {zone}/IN (signed): checkds: bad DS response from 10.53.0.6"
+        watcher.wait_for_line(line)
     keystate_check(parent, zone, "!DSRemoved")
 
     #
@@ -560,7 +481,7 @@ def checkds_dswithdrawn(named_port, checkds, addr):
     # TBD
 
 
-def test_checkds_reference(named_port):
+def test_checkds_reference(named_port, servers):
     # We create resolver instances that will be used to send queries.
     server = dns.resolver.Resolver()
     server.nameservers = ["10.53.0.9"]
@@ -573,15 +494,13 @@ def test_checkds_reference(named_port):
     # Using a reference to parental-agents.
     zone = "reference.explicit.dspublish.ns2"
     zone_check(server, zone)
-    wait_for_log(
-        "ns9/named.run",
-        zone,
-        "zone {}/IN (signed): checkds: DS response from 10.53.0.8".format(zone),
-    )
+    with servers["ns9"].watch_log_from_start() as watcher:
+        line = f"zone {zone}/IN (signed): checkds: DS response from 10.53.0.8"
+        watcher.wait_for_line(line)
     keystate_check(parent, zone, "DSPublish")
 
 
-def test_checkds_resolver(named_port):
+def test_checkds_resolver(named_port, servers):
     # We create resolver instances that will be used to send queries.
     server = dns.resolver.Resolver()
     server.nameservers = ["10.53.0.9"]
@@ -594,25 +513,21 @@ def test_checkds_resolver(named_port):
     # Using a resolver as parental-agent (ns3).
     zone = "resolver.explicit.dspublish.ns2"
     zone_check(server, zone)
-    wait_for_log(
-        "ns9/named.run",
-        zone,
-        "zone {}/IN (signed): checkds: DS response from 10.53.0.3".format(zone),
-    )
+    with servers["ns9"].watch_log_from_start() as watcher:
+        line = f"zone {zone}/IN (signed): checkds: DS response from 10.53.0.3"
+        watcher.wait_for_line(line)
     keystate_check(parent, zone, "DSPublish")
 
     # Using a resolver as parental-agent (ns3).
     zone = "resolver.explicit.dsremoved.ns5"
     zone_check(server, zone)
-    wait_for_log(
-        "ns9/named.run",
-        zone,
-        "zone {}/IN (signed): checkds: empty DS response from 10.53.0.3".format(zone),
-    )
+    with servers["ns9"].watch_log_from_start() as watcher:
+        line = f"zone {zone}/IN (signed): checkds: empty DS response from 10.53.0.3"
+        watcher.wait_for_line(line)
     keystate_check(parent, zone, "DSRemoved")
 
 
-def test_checkds_no_ent(named_port):
+def test_checkds_no_ent(named_port, servers):
     # We create resolver instances that will be used to send queries.
     server = dns.resolver.Resolver()
     server.nameservers = ["10.53.0.9"]
@@ -624,31 +539,27 @@ def test_checkds_no_ent(named_port):
 
     zone = "no-ent.ns2"
     zone_check(server, zone)
-    wait_for_log(
-        "ns9/named.run",
-        zone,
-        "zone {}/IN (signed): checkds: DS response from 10.53.0.2".format(zone),
-    )
+    with servers["ns9"].watch_log_from_start() as watcher:
+        line = f"zone {zone}/IN (signed): checkds: DS response from 10.53.0.2"
+        watcher.wait_for_line(line)
     keystate_check(parent, zone, "DSPublish")
 
     zone = "no-ent.ns5"
     zone_check(server, zone)
-    wait_for_log(
-        "ns9/named.run",
-        zone,
-        "zone {}/IN (signed): checkds: DS response from 10.53.0.5".format(zone),
-    )
+    with servers["ns9"].watch_log_from_start() as watcher:
+        line = f"zone {zone}/IN (signed): checkds: DS response from 10.53.0.5"
+        watcher.wait_for_line(line)
     keystate_check(parent, zone, "DSRemoved")
 
 
-def test_checkds_dspublished(named_port):
-    checkds_dspublished(named_port, "explicit", "10.53.0.8")
-    checkds_dspublished(named_port, "yes", "10.53.0.2")
+def test_checkds_dspublished(named_port, servers):
+    checkds_dspublished(named_port, servers, "explicit", "10.53.0.8")
+    checkds_dspublished(named_port, servers, "yes", "10.53.0.2")
 
 
-def test_checkds_dswithdrawn(named_port):
-    checkds_dswithdrawn(named_port, "explicit", "10.53.0.10")
-    checkds_dswithdrawn(named_port, "yes", "10.53.0.5")
+def test_checkds_dswithdrawn(named_port, servers):
+    checkds_dswithdrawn(named_port, servers, "explicit", "10.53.0.10")
+    checkds_dswithdrawn(named_port, servers, "yes", "10.53.0.5")
 
 
 def test_checkds_no(named_port):