From ca1b1f6dc088b9e46662bdb55ef603dcbae9757b Mon Sep 17 00:00:00 2001 From: rnhmjoj Date: Thu, 14 Apr 2022 10:35:11 +0200 Subject: [PATCH] nixos/test-driver: highlight driver log lines MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit There is a whole lot of noise in a NixOS test log due to journal, commands, and test driver messages all being mixing together. With this commit the test driver messages are highlighted so you don't have to squint too much to see where a subtest starts and ends or what was the last command being run. Here's an excerpt from a highlighted log: machine # [ 6.647826] dhcpcd[668]: eth0: adding default route via 10.0.2.2 machine # I've had a great day! (finished: must succeed: curl -sfL https://example.com/how-are-you? | tee /dev/stderr, in 0.19 seconds) (finished: subtest: Privoxy can filter https requests, in 0.22 seconds) subtest: Blocks are working machine: waiting for TCP port 443 machine # Connection to localhost (::1) 443 port [tcp/https] succeeded! (finished: waiting for TCP port 443, in 0.03 seconds) machine: must fail: curl -f https://example.com/ads 1>&2 machine # [ 6.730608] nscd[742]: 742 monitored file `/etc/resolv.conf` was written to machine # [ 6.733071] privoxy[814]: 2022-04-14 09:41:01.695 7fa995c39640 Actions: +block{Fake ads} ... machine # curl: (22) The requested URL returned error: 403 machine # [ 6.753098] systemd[1]: Stopping Name Service Cache Daemon... machine # [ 6.755632] systemd[1]: nscd.service: Deactivated successfully. machine # [ 6.757069] systemd[1]: Stopped Name Service Cache Daemon. (finished: must fail: curl -f https://example.com/ads 1>&2, in 0.07 seconds) machine: must succeed: curl -f https://example.com/PRIVOXY-FORCE/ads 1>&2 machine # [ 6.765099] systemd[1]: Starting Name Service Cache Daemon... machine # [ 6.781519] nscd[925]: 925 monitoring file `/etc/passwd` (1) machine # [ 6.844105] systemd[1]: Reached target Network is Online. machine # [ 6.848860] privoxy[814]: 2022-04-14 09:41:01.805 7fa995c39640 Actions: +block{Fake ads} ... machine # [ 6.856068] nscd[925]: 925 monitoring file `/etc/nsswitch.conf` (8) machine # [ 6.858229] systemd[1]: Reached target Multi-User System. machine # [ 6.858934] nscd[925]: 925 monitoring directory `/etc` (2) machine # [ 6.861315] systemd[1]: Startup finished in 2.374s (kernel) + 4.451s (userspace) = 6.826s. machine # Hot Nixpkgs PRs in your area. Click here! machine # [ 6.873055] nscd[925]: 925 monitoring directory `/etc` (2) machine # [ 6.874489] nscd[925]: 925 monitoring file `/etc/nsswitch.conf` (8) machine # [ 6.875599] nscd[925]: 925 monitoring directory `/etc` (2) (finished: must succeed: curl -f https://example.com/PRIVOXY-FORCE/ads 1>&2, in 0.12 seconds) (finished: subtest: Blocks are working, in 0.22 seconds) subtest: Temporary certificates are cleaned machine: must succeed: test $(ls /run/privoxy/certs | wc -l) -gt 0 (finished: must succeed: test $(ls /run/privoxy/certs | wc -l) -gt 0, in 0.02 seconds) machine: must succeed: date -s "$(date --date '12 days')" (finished: must succeed: date -s "$(date --date '12 days')", in 0.02 seconds) machine # [ 6.959589] systemd[1]: Started Logrotate Service. machine # [ 6.966685] systemd[1]: Starting Cleanup of Temporary Directories... machine # [ 6.974783] systemd[1]: logrotate.service: Deactivated successfully. machine # [ 7.004493] systemd[1]: systemd-tmpfiles-clean.service: Deactivated successfully. machine # [ 7.005457] systemd[1]: Finished Cleanup of Temporary Directories. machine: must succeed: test $(ls /run/privoxy/certs | wc -l) -eq 0 (finished: must succeed: test $(ls /run/privoxy/certs | wc -l) -eq 0, in 0.01 seconds) (finished: subtest: Temporary certificates are cleaned, in 0.15 seconds) (finished: run the VM test script, in 7.44 seconds) test script finished in 7.48s cleanup kill machine (pid 8) --- nixos/lib/test-driver/test_driver/driver.py | 2 +- nixos/lib/test-driver/test_driver/logger.py | 8 ++++++-- 2 files changed, 7 insertions(+), 3 deletions(-) diff --git a/nixos/lib/test-driver/test_driver/driver.py b/nixos/lib/test-driver/test_driver/driver.py index 0e5f013193f..e32f6810ca8 100644 --- a/nixos/lib/test-driver/test_driver/driver.py +++ b/nixos/lib/test-driver/test_driver/driver.py @@ -86,7 +86,7 @@ class Driver: def subtest(self, name: str) -> Iterator[None]: """Group logs under a given test name""" - with rootlog.nested(name): + with rootlog.nested("subtest: " + name): try: yield return True diff --git a/nixos/lib/test-driver/test_driver/logger.py b/nixos/lib/test-driver/test_driver/logger.py index 5b3091a5129..59ed2954723 100644 --- a/nixos/lib/test-driver/test_driver/logger.py +++ b/nixos/lib/test-driver/test_driver/logger.py @@ -1,4 +1,4 @@ -from colorama import Style +from colorama import Style, Fore from contextlib import contextmanager from typing import Any, Dict, Iterator from queue import Queue, Empty @@ -81,7 +81,11 @@ class Logger: @contextmanager def nested(self, message: str, attributes: Dict[str, str] = {}) -> Iterator[None]: - self._eprint(self.maybe_prefix(message, attributes)) + self._eprint( + self.maybe_prefix( + Style.BRIGHT + Fore.GREEN + message + Style.RESET_ALL, attributes + ) + ) self.xml.startElement("nest", attrs={}) self.xml.startElement("head", attributes)