🌱 Less noise for unit-test (#1732)

Author: guettli

docs/caph/04-developers/01-development-guide.md

@@ -80,6 +80,25 @@ With `make test`, all unit tests are triggered. If they fail out of nowhere, the
 
 With `make generate`, new CRDs are generated. This is necessary if you change the API.
 
+## Running unit-tests locally
+
+Developing unit-tests (which do not need a running cluster) are much faster. We recommend to do
+that.
+
+A common way to run one particular unit-test is like this:
+
+```console
+reset; ginkgo run --focus "foo" ./controllers/... | ./hack/filter-caph-controller-manager-logs.py -
+```
+
+Explanation:
+
+- `reset`: Reset the terminal so you can scroll back to the first line of output easily.
+- `ginkgo run --focus "foo" ./controllers/...`: Run tests in the controllers directory, but only those
+  whose `It("...")` contains "foo".
+- `./hack/filter-caph-controller-manager-logs.py -`: Filter the output to avoid being overwhelmed.
+  You can configure the script to exclude lines or individual key/value pairs of the JSON log lines.
+
 ## Running local e2e test
 
 If you are interested in running the E2E tests locally, then you can use the following commands:

hack/filter-caph-controller-manager-logs.py

@@ -18,16 +18,47 @@
 import sys
 import json
 
-keys_to_skip = ['controller', 'controllerGroup', 'controllerKind', 'reconcileID',
-                'HetznerCluster', 'Cluster',
-                'namespace', 'name', 'Machine', 'stack', 'stacktrace',
-                'logger',
-                ]
+keys_to_skip = [
+    "controller",
+    "controllerGroup",
+    "controllerKind",
+    "reconcileID",
+    "HetznerCluster",
+    "Cluster",
+    "namespace",
+    "name",
+    "Machine",
+    "stack",
+    "stacktrace",
+    "logger",
+]
+
+# Only show the name. Not a nested struct.
+# in: 'HCloudMachine': {'name': 'myname', 'namespace': '...'}
+# out:'HCloudMachine': 'myname'
+keys_to_name = [
+    "HCloudMachine",
+    "HCloudMachineTemplate",
+    "HCloudRemediation",
+    "HCloudRemediationTemplate",
+    "HetznerBareMetalHost",
+    "HetznerBareMetalMachine",
+    "HetznerBareMetalMachineTemplate",
+    "HetznerBareMetalRemediation",
+    "HetznerBareMetalRemediationTemplate",
+    "HetznerCluster",
+    "HetznerClusterTemplate",
+]
+
+rows_to_skip_regex = [
+    r"maxprocs: Leaving GOMAXPROCS=\d+: CPU quota undefined",
+    r"^Random Seed: \d+",
+]
+
+rows_to_trigger_test_filter = ["Running Suite:"]
 
+# List of fixed-strings.
 rows_to_skip = [
-    'controller-runtime.webhook', 'certwatcher/certwatcher', 'Registering a validating webhook',
-    'Registering a mutating webhook', 'Starting EventSource',
-    'Starting Controller',
     '"Starting workers" controller/controller',
     '"starting manager"',
     '"Starting metrics server"',
@@ -40,8 +71,6 @@
     '"Serving metrics server"',
     '"Starting webhook server"',
     '"Serving webhook server"',
-    'attempting to acquire leader lease caph-system/hetzner.cluster.x-k8s.io.',
-    'Update to resource only changes insignificant fields',
     '"approved csr"',
     '"Registering webhook"',
     '"Stopping and waiting for',
@@ -50,16 +79,58 @@
     "'statusCode': 200, 'method': 'GET', 'url': 'https://robot-ws.your-server.de",
 ]
 
+rows_to_skip_for_tests = [
+    "attempting to acquire leader lease caph-system/hetzner.cluster.x-k8s.io.",
+    "Update to resource only changes insignificant fields",
+    '"Wait completed, proceeding to shutdown the manager"',
+    '"starting control plane" logger="controller-runtime.test-env"',
+    '"installing CRDs" logger="controller-runtime.test-env"',
+    '"reading CRDs from path"',
+    '"read CRDs from file"',
+    '"installing CRD"',
+    '"adding API in waitlist" logger="controller-runtime.test-env"',
+    '"installing webhooks" logger="controller-runtime.test-env"',
+    '"installing mutating webhook" logger="controller-runtime.test-env"',
+    '"installing validating webhook" logger="controller-runtime.test-env"',
+    'cluster.x-k8s.io\\": prefer a domain-qualified finalizer',
+    '"Update to resource changes significant fields, will enqueue event"',
+    '"Wait for update being in local cache"',
+    '"Created load balancer"',
+    '"Created network with opts',
+    '"Starting workers" controller="',
+    '"controller-runtime.certwatcher"',
+    "controller-runtime.webhook",
+    "certwatcher/certwatcher",
+    "Registering a validating webhook",
+    "Registering a mutating webhook",
+    "Starting EventSource",
+    "Starting Controller",
+    "Wait completed, proceeding to shutdown the manager",
+    "unable to decode an event from the watch stream: context canceled",
+    "client rate limiter Wait returned an error: context canceled",
+    'os-ssh-secret": context canceled',
+    "http: TLS handshake error from 127.0.0.1:",
+    '"Cluster infrastructure did not become ready, blocking further processing"',
+    'predicate="IgnoreInsignificant',
+    '"HetznerCluster is not available yet"',
+    '"Unable to write event (broadcaster is shut down)"',
+    '"Unable to write event (may retry after sleeping)"',
+]
+
+
 def main():
 
-    if len(sys.argv) == 1 or sys.argv[1] in ['-h', '--help']:
-        print('''%s [file|-]
+    if len(sys.argv) == 1 or sys.argv[1] in ["-h", "--help"]:
+        print(
+            """%s [file|-]
     filter the logs of caph-controller-manager.
     Used for debugging.
-    ''' % sys.argv[0])
+    """
+            % sys.argv[0]
+        )
         sys.exit(1)
 
-    if sys.argv[1] == '-':
+    if sys.argv[1] == "-":
         fd = sys.stdin
     else:
         fd = open(sys.argv[1])
@@ -68,17 +139,68 @@ def main():
 
 def read_logs(fd):
     for line in fd:
-        handle_line(line)
+        try:
+            handle_line(line)
+        except BrokenPipeError:
+            return
+
+
+ansi_pattern = re.compile(r"\x1B\[[0-9;]*[A-Za-z]")
+
+filtering_test_data = False
+
+
+def write_line(line):
+    ascii_line = ansi_pattern.sub("", line)
+    for r in rows_to_trigger_test_filter:
+        if r in ascii_line:
+            global filtering_test_data
+            filtering_test_data = True
+            rows_to_skip.extend(rows_to_skip_for_tests)
+
+    for r in rows_to_skip:
+        if r in ascii_line:
+            return
+    for r in rows_to_skip_regex:
+        if re.search(r, ascii_line):
+            return
+    sys.stdout.write(line)
+
 
 def handle_line(line):
-    if not line.startswith('{'):
-        sys.stdout.write(line)
+    # Extract leading dots (•) and print them on a separate line
+    leading_dots = ""
+    while line.startswith("•"):
+        leading_dots += "•"
+        line = line[1:]
+    if leading_dots:
+        print(leading_dots)
+    if not (line.startswith("{") and line.rstrip().endswith("}")):
+        write_line(line)
+        return
+    try:
+        data = json.loads(line)
+    except json.decoder.JSONDecodeError as err:
+        write_line("\n")
+        write_line(str(err))
+        write_line(line)
+        write_line("\n")
         return
-    data = json.loads(line)
     for key in keys_to_skip:
         data.pop(key, None)
-    t = data.pop('time', '')
-    t = re.sub(r'^.*T(.+)*\..+$', r'\1', t) # '2023-04-17T12:12:53.423Z
+
+    # in: 'HCloudMachine': {'name': 'myname', 'namespace': '...'}
+    # out:'HCloudMachine': 'myname'
+    for key in keys_to_name:
+        value = data.get(key)
+        if not value:
+            continue
+        name = value.get("name")
+        if name:
+            data[key] = name
+
+    t = data.pop("time", "")
+    t = re.sub(r"^.*T(.+)*\..+$", r"\1", t)  # '2023-04-17T12:12:53.423Z
 
     # skip too long entries
     for key, value in list(data.items()):
@@ -87,20 +209,24 @@ def handle_line(line):
         if len(value) > 1_000:
             data[key] = value[:1_000] + "...cut..."
 
-    level = data.pop('level', '').ljust(5)
-    file = data.pop('file', '')
-    message = data.pop('message', '')
-
-    if not data:
-        data=''
+    level = data.pop("level", "").ljust(5)
+    file = data.pop("file", "")
+    message = data.pop("message", "")
+
+    if data:
+        values = []
+        for key, value in data.items():
+            value = str(value)
+            if any(c.isspace() for c in value):
+                value = f"<{value}>"
+            values.append(f"{key}={value}")
+        data = " ".join(values)
+    else:
+        data = ""
 
     new_line = f'{t} {level} "{message}" {file} {data}\n'
-    for r in rows_to_skip:
-        if r in new_line:
-            return
-
-    sys.stdout.write(new_line)
+    write_line(new_line)
 
 
-if __name__ == '__main__':
+if __name__ == "__main__":
     main()

hack/test-unit.sh

@@ -37,4 +37,4 @@ hack/tools/bin/gotestsum \
     --junitfile=.coverage/junit.xml \
     --format testname -- \
     -covermode=atomic -coverprofile=.coverage/cover.out -p=1 -timeout 5m \
-    ./controllers/... ./pkg/... ./api/...
+    ./controllers/... ./pkg/... ./api/... | ./hack/filter-caph-controller-manager-logs.py -

test/helpers/envtest.go

@@ -60,6 +60,7 @@ import (
 	hcloudclient "github.com/syself/cluster-api-provider-hetzner/pkg/services/hcloud/client"
 	fakeclient "github.com/syself/cluster-api-provider-hetzner/pkg/services/hcloud/client/fake"
 	"github.com/syself/cluster-api-provider-hetzner/pkg/services/hcloud/mockedsshclient"
+	"github.com/syself/cluster-api-provider-hetzner/pkg/utils"
 )
 
 func init() {
@@ -150,6 +151,7 @@ func NewTestEnvironment() *TestEnvironment {
 			// Disable MetricsServer, so that two tests processes can run concurrently
 			BindAddress: "0",
 		},
+		Logger: utils.GetDefaultLogger("info"),
 	})
 	if err != nil {
 		klog.Fatalf("unable to create manager: %s", err)