Flock: log checking

Checking is done inline and asynchronously, every log message should be
explicitly expected, otherwise it's reported. It also has an implicit
timeout of 1s for the log message to appear, otherwise it fails as well.

.gitmodules

@@ -0,0 +1,3 @@
+[submodule "python/asyncinotify"]
+	path = python/asyncinotify
+	url = https://github.com/ProCern/asyncinotify.git

flock/bgp-secondary/bird_dest.conf

@@ -1,4 +1,4 @@
-log "bird.log" all;
+log "{{ m.logs[0].name }}" all;
 
 router id 2;
 

flock/bgp-secondary/bird_src.conf

@@ -1,12 +1,12 @@
-log "bird.log" all;
+log "{{ m.logs[0].name }}" all;
 
 router id 1;
 define epoch = {{ t.epoch % 2 }};
 
 ipv6 table master6 sorted;
 
-debug tables all;
-debug channels all;
+#debug tables all;
+#debug channels all;
 
 protocol device {
 	scan time 10;

flock/bgp-secondary/test.py

@@ -4,7 +4,7 @@ import asyncio
 from python.BIRD.Test import Test, BIRDInstance
 
 class ThisTest(Test):
-    async def test(self):
+    async def prepare(self):
         # Set epoch
         self.epoch = 0
 
@@ -17,9 +17,7 @@ class ThisTest(Test):
                 "L": await self.link("L", "src", "dest")
                 }
 
-        # Start machines and links
-        await self.start()
-
+    async def test(self):
         # Startup check
         await self.route_dump(10, "startup")
 
@@ -53,7 +51,11 @@ class ThisTest(Test):
         # Update configuration
         self.epoch = 1
         self.src.write_config(test=self)
-        await self.src.configure()
+        await self.src.configure(expected_logs=[
+            f"<INFO> Reconfiguring$",
+            f"<INFO> Reloading channel LINK.ipv6",
+            f"<INFO> Reconfigured$",
+            ])
         await self.route_dump(5, f"check-reconfig")
 
         # Disable worst to best
@@ -79,7 +81,11 @@ class ThisTest(Test):
         # Update configuration once again
         self.epoch = 2
         self.src.write_config(test=self)
-        await self.src.configure()
+        await self.src.configure(expected_logs=[
+            f"<INFO> Reconfiguring$",
+            f"<INFO> Reloading channel LINK.ipv6",
+            f"<INFO> Reconfigured$",
+            ])
         await self.route_dump(5, f"check-reconfig")
 
         # Disable best to worst
@@ -102,5 +108,9 @@ class ThisTest(Test):
             await self.src.enable(p)
             await self.route_dump(1, f"enable-{p}")
 
-        # Finish
+        # Pre-cleanup log checker
+        self.src.default_log_checker.append(f"{self.src.logprefix} <RMT> LINK: Received: Administrative shutdown")
+        self.dest.default_log_checker.append(f"{self.dest.logprefix} <RMT> LINK: Received: Administrative shutdown")
+
+        # Regular cleanup
         await self.cleanup()

python/BIRD/LogChecker.py

@@ -0,0 +1,74 @@
+import asyncio
+import re
+
+from python.asyncinotify.src.asyncinotify import Inotify, Mask
+
+class UnexpectedLogException(Exception):
+    pass
+
+class LogSeen:
+    lino: int
+    buf: str
+    groups: object
+
+class LogExpectedStub:
+    def __init__(self, pattern):
+        self.pattern = re.compile(pattern) if type(pattern) is str else pattern
+        self.seen = []
+
+    def check(self, buf):
+        return self.pattern.match(buf)
+
+    def store(self, data):
+        self.seen.append(data)
+
+class LogExpectedFuture(LogExpectedStub):
+    def __init__(self, pattern):
+        super().__init__(pattern)
+        self.done = asyncio.Future()
+
+    def store(self, data):
+        self.done.set_result(data)
+
+class LogChecker:
+    def __init__(self, name, expected=None):
+        self.name = name
+        self.expected = [
+                LogExpectedStub(e) if isinstance(e, str) else e
+                for e in expected
+                ] if expected is not None else []
+        self.task = None
+
+    def check(self, buf):
+        for p in self.expected:
+            if (g := p.check(buf)) is not None:
+                p.store(g)
+                return
+
+        raise UnexpectedLogException(buf)
+
+    async def run(self):
+        with (Inotify() as inot, open(self.name, "r") as f):
+            inot.add_watch(self.name, Mask.MODIFY)
+            buf = None
+            while True:
+                buf = f.readline()
+                if len(buf) > 0 and buf[-1] == "\n":
+                    self.check(buf)
+                else:
+                    break
+
+            async for event in inot:
+                while True:
+                    buf += f.readline()
+                    if len(buf) > 0 and buf[-1] == "\n":
+                        self.check(buf)
+                        buf = ""
+                    else:
+                        break
+
+    def append(self, pat):
+        if type(pat) is str:
+            self.expected.append(LogExpectedStub(pat))
+        else:
+            self.expected.append(pat)

python/BIRD/Test.py

@@ -11,6 +11,7 @@ sys.path.insert(0, "/home/maria/flock")
 from flock.Hypervisor import Hypervisor
 from flock.Machine import Machine
 from .CLI import CLI, Transport
+from .LogChecker import LogChecker, LogExpectedFuture
 
 # TODO: move this to some aux file
 class Differs(Exception):
@@ -119,11 +120,18 @@ class BIRDBinDir:
 default_bindir = BIRDBinDir.get(".")
 
 class BIRDInstance(CLI):
-    def __init__(self, mach: Machine, bindir=None, conf=None):
+    logprefix = "^\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2}\.\d{3} \[\d{4}\]"
+
+    def __init__(self, mach: Machine, bindir=None, conf=None, logs=None):
         self.mach = mach
         self.workdir = self.mach.workdir
         self.bindir = BIRDBinDir.get(bindir) if bindir is not None else default_bindir
         self.conf = conf if conf is not None else f"bird_{mach.name}.conf"
+        if logs is None:
+            self.default_log_checker = LogChecker(name=self.workdir/"bird.log")
+            self.logs = [ self.default_log_checker ]
+        else:
+            self.logs = logs
 
         super().__init__(
                 transport=MinimalistTransport(
@@ -134,13 +142,62 @@ class BIRDInstance(CLI):
 
     def write_config(self, test):
         with (open(self.conf, "r") as s, open(self.workdir / "bird.conf", "w") as f):
-            f.write(jinja2.Environment().from_string(s.read()).render(t=test))
+            f.write(jinja2.Environment().from_string(s.read()).render(t=test, m=self))
+
+    async def logchecked(self, coro, pattern):
+        if type(pattern) is str:
+            exp = [ LogExpectedFuture(f"{self.logprefix} {pattern}") ]
+        else:
+            exp = [ LogExpectedFuture(f"{self.logprefix} {p}") for p in pattern ]
+
+        self.default_log_checker.expected += exp
+
+        async with asyncio.timeout(5):
+            await asyncio.gather(
+                    coro,
+                    *[ e.done for e in exp ]
+                    )
+
+        for e in exp:
+            self.default_log_checker.expected.remove(e)
+
+    async def down(self):
+        await self.logchecked(
+                super().down(),
+                [
+                "<INFO> Shutting down",
+                "<FATAL> Shutdown completed",
+                ]
+                )
+
+    async def configure(self, *args, expected_logs=f"<INFO> Reconfiguring$", **kwargs):
+        await self.logchecked(super().configure(*args, **kwargs), expected_logs)
+
+    async def enable(self, proto: str):
+        await self.logchecked(super().enable(proto), f"<INFO> Enabling protocol {proto}$")
+
+    async def disable(self, proto: str):
+        await self.logchecked(super().disable(proto), f"<INFO> Disabling protocol {proto}$")
 
     async def start(self, test):
         self.bindir.copy(self.workdir)
         self.write_config(test)
+
         await test.hcom("run_in", self.mach.name, "./bird", "-l")
 
+        exp = LogExpectedFuture(f"{self.logprefix} <INFO> Started$")
+        self.default_log_checker.expected.append(exp)
+
+        async def started():
+            async with asyncio.timeout(1):
+                await exp.done
+
+            self.default_log_checker.expected.remove(exp)
+
+        return [
+                l.run() for l in self.logs
+                ] + [ started() ]
+
     async def cleanup(self):
         # Send down command and wait for BIRD to actually finish
         await self.down()
@@ -148,8 +205,8 @@ class BIRDInstance(CLI):
             await asyncio.sleep(0.1)
 
         # Remove known files
-        for f in ("bird.conf", "bird.log"):
-            (self.workdir / f).unlink()
+        for f in (self.workdir / "bird.conf", *[ l.name for l in self.logs ]):
+            f.unlink()
 
         self.bindir.cleanup(self.workdir)
 
@@ -177,6 +234,8 @@ class Test:
         self._starting = False
         self._stopped = None
 
+        self.background_tasks = []
+
         self.ipv6_pxgen = self.ipv6_prefix.subnets(new_prefix=self.ipv6_link_pxlen)
         self.ipv4_pxgen = self.ipv4_prefix.subnets(new_prefix=self.ipv4_link_pxlen)
 
@@ -251,7 +310,7 @@ class Test:
                 raise NotImplementedError("virtual bridge")
 
     async def start(self):
-        await asyncio.gather(*[ v.start(test=self) for v in self.machine_index.values() ])
+        return await asyncio.gather(*[ v.start(test=self) for v in self.machine_index.values() ])
 
     async def cleanup(self):
         await asyncio.gather(*[ v.cleanup() for v in self.machine_index.values() ])
@@ -261,8 +320,26 @@ class Test:
 
     async def run(self):
         try:
+            await self.prepare()
+            tasks = [ t for q in await self.start() for t in q ]
+
+            async def arun():
+                await asyncio.gather(*tasks)
+                raise Exception("No auxiliary task, what?")
+
+            atask = asyncio.create_task(arun())
+
+            async def trun():
                 await self.test()
+                atask.cancel()
+
+            await asyncio.gather(atask, trun())
+
+        except asyncio.exceptions.CancelledError as e:
+            if not atask.cancelled():
+                raise e
         finally:
+            print("cleaning up")
             await self.cleanup()
 
     async def route_dump(self, timeout, name, full=True, machines=None, check_timeout=10, check_retry_timeout=0.5):
@@ -273,6 +350,8 @@ class Test:
         else:
             name = f"dump-{self.route_dump_id:04d}-{name}.yaml"
 
+        print(f"{name}\t{self.route_dump_id}\t", end="", flush=True)
+
         # Collect machines to dump
         if machines is None:
             machines = self.machine_index.values()
@@ -308,7 +387,7 @@ class Test:
                 dump = await obtain()
                 with open(name, "w") as y:
                     yaml.dump_all(dump, y)
-                print(f"{name}\t{self.route_dump_id}\t[ SAVED ]")
+                print(f"[ SAVED ]")
 
             case Test.CHECK:
                 with open(name, "r") as y:
@@ -323,7 +402,7 @@ class Test:
                                 deep_eq(c, dump, True)
 #                            if deep_eq(c, dump):
                                 spent = asyncio.get_running_loop().time() - to.when() + check_timeout
-                                print(f"{name}\t{self.route_dump_id}\t[  OOK  ]\t{spent:.6f}s")
+                                print(f"[  OOK  ]\t{spent:.6f}s")
                                 return True
                             except Differs as d:
                                 if self.show_difs:
@@ -332,7 +411,7 @@ class Test:
                             seen.append(dump)
                             await asyncio.sleep(check_retry_timeout)
                 except TimeoutError as e:
-                    print(f"{name}\t{self.route_dump_id}\t[ BAD  ]")
+                    print(f"[ BAD  ]")
                     for q in range(len(seen)):
                         with open(f"__result_bad_{q}__{name}", "w") as y:
                             yaml.dump_all(seen[q], y)

python/asyncinotify

@@ -0,0 +1 @@
+Subproject commit 64997528db8a0d2cc14d3cc50d2caa26210aa080