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: [2mmachine # [ 6.647826] dhcpcd[668]: eth0: adding default route via 10.0.2.2[0m [2mmachine # I've had a great day![0m (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) [1m[32msubtest: Blocks are working[0m machine: [1m[32mwaiting for TCP port 443[0m [2mmachine # Connection to localhost (::1) 443 port [tcp/https] succeeded![0m (finished: waiting for TCP port 443, in 0.03 seconds) machine: [1m[32mmust fail: curl -f https://example.com/ads 1>&2[0m [2mmachine # [ 6.730608] nscd[742]: 742 monitored file `/etc/resolv.conf` was written to[0m [2mmachine # [ 6.733071] privoxy[814]: 2022-04-14 09:41:01.695 7fa995c39640 Actions: +block{Fake ads} ... [2mmachine # curl: (22) The requested URL returned error: 403[0m [2mmachine # [ 6.753098] systemd[1]: Stopping Name Service Cache Daemon...[0m [2mmachine # [ 6.755632] systemd[1]: nscd.service: Deactivated successfully.[0m [2mmachine # [ 6.757069] systemd[1]: Stopped Name Service Cache Daemon.[0m (finished: must fail: curl -f https://example.com/ads 1>&2, in 0.07 seconds) machine: [1m[32mmust succeed: curl -f https://example.com/PRIVOXY-FORCE/ads 1>&2[0m [2mmachine # [ 6.765099] systemd[1]: Starting Name Service Cache Daemon...[0m [2mmachine # [ 6.781519] nscd[925]: 925 monitoring file `/etc/passwd` (1)[0m [2mmachine # [ 6.844105] systemd[1]: Reached target Network is Online.[0m [2mmachine # [ 6.848860] privoxy[814]: 2022-04-14 09:41:01.805 7fa995c39640 Actions: +block{Fake ads} ... [2mmachine # [ 6.856068] nscd[925]: 925 monitoring file `/etc/nsswitch.conf` (8)[0m [2mmachine # [ 6.858229] systemd[1]: Reached target Multi-User System.[0m [2mmachine # [ 6.858934] nscd[925]: 925 monitoring directory `/etc` (2)[0m [2mmachine # [ 6.861315] systemd[1]: Startup finished in 2.374s (kernel) + 4.451s (userspace) = 6.826s.[0m [2mmachine # Hot Nixpkgs PRs in your area. Click here![0m [2mmachine # [ 6.873055] nscd[925]: 925 monitoring directory `/etc` (2)[0m [2mmachine # [ 6.874489] nscd[925]: 925 monitoring file `/etc/nsswitch.conf` (8)[0m [2mmachine # [ 6.875599] nscd[925]: 925 monitoring directory `/etc` (2)[0m (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) [1m[32msubtest: Temporary certificates are cleaned[0m machine: [1m[32mmust succeed: test $(ls /run/privoxy/certs | wc -l) -gt 0[0m (finished: must succeed: test $(ls /run/privoxy/certs | wc -l) -gt 0, in 0.02 seconds) machine: [1m[32mmust succeed: date -s "$(date --date '12 days')"[0m (finished: must succeed: date -s "$(date --date '12 days')", in 0.02 seconds) [2mmachine # [ 6.959589] systemd[1]: Started Logrotate Service.[0m [2mmachine # [ 6.966685] systemd[1]: Starting Cleanup of Temporary Directories...[0m [2mmachine # [ 6.974783] systemd[1]: logrotate.service: Deactivated successfully.[0m [2mmachine # [ 7.004493] systemd[1]: systemd-tmpfiles-clean.service: Deactivated successfully.[0m [2mmachine # [ 7.005457] systemd[1]: Finished Cleanup of Temporary Directories.[0m machine: [1m[32mmust succeed: test $(ls /run/privoxy/certs | wc -l) -eq 0[0m (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 [1m[32mcleanup[0m kill machine (pid 8)
106 lines
3.3 KiB
Python
106 lines
3.3 KiB
Python
from colorama import Style, Fore
|
|
from contextlib import contextmanager
|
|
from typing import Any, Dict, Iterator
|
|
from queue import Queue, Empty
|
|
from xml.sax.saxutils import XMLGenerator
|
|
import codecs
|
|
import os
|
|
import sys
|
|
import time
|
|
import unicodedata
|
|
|
|
|
|
class Logger:
|
|
def __init__(self) -> None:
|
|
self.logfile = os.environ.get("LOGFILE", "/dev/null")
|
|
self.logfile_handle = codecs.open(self.logfile, "wb")
|
|
self.xml = XMLGenerator(self.logfile_handle, encoding="utf-8")
|
|
self.queue: "Queue[Dict[str, str]]" = Queue()
|
|
|
|
self.xml.startDocument()
|
|
self.xml.startElement("logfile", attrs={})
|
|
|
|
self._print_serial_logs = True
|
|
|
|
@staticmethod
|
|
def _eprint(*args: object, **kwargs: Any) -> None:
|
|
print(*args, file=sys.stderr, **kwargs)
|
|
|
|
def close(self) -> None:
|
|
self.xml.endElement("logfile")
|
|
self.xml.endDocument()
|
|
self.logfile_handle.close()
|
|
|
|
def sanitise(self, message: str) -> str:
|
|
return "".join(ch for ch in message if unicodedata.category(ch)[0] != "C")
|
|
|
|
def maybe_prefix(self, message: str, attributes: Dict[str, str]) -> str:
|
|
if "machine" in attributes:
|
|
return "{}: {}".format(attributes["machine"], message)
|
|
return message
|
|
|
|
def log_line(self, message: str, attributes: Dict[str, str]) -> None:
|
|
self.xml.startElement("line", attributes)
|
|
self.xml.characters(message)
|
|
self.xml.endElement("line")
|
|
|
|
def info(self, *args, **kwargs) -> None: # type: ignore
|
|
self.log(*args, **kwargs)
|
|
|
|
def warning(self, *args, **kwargs) -> None: # type: ignore
|
|
self.log(*args, **kwargs)
|
|
|
|
def error(self, *args, **kwargs) -> None: # type: ignore
|
|
self.log(*args, **kwargs)
|
|
sys.exit(1)
|
|
|
|
def log(self, message: str, attributes: Dict[str, str] = {}) -> None:
|
|
self._eprint(self.maybe_prefix(message, attributes))
|
|
self.drain_log_queue()
|
|
self.log_line(message, attributes)
|
|
|
|
def log_serial(self, message: str, machine: str) -> None:
|
|
self.enqueue({"msg": message, "machine": machine, "type": "serial"})
|
|
if self._print_serial_logs:
|
|
self._eprint(
|
|
Style.DIM + "{} # {}".format(machine, message) + Style.RESET_ALL
|
|
)
|
|
|
|
def enqueue(self, item: Dict[str, str]) -> None:
|
|
self.queue.put(item)
|
|
|
|
def drain_log_queue(self) -> None:
|
|
try:
|
|
while True:
|
|
item = self.queue.get_nowait()
|
|
msg = self.sanitise(item["msg"])
|
|
del item["msg"]
|
|
self.log_line(msg, item)
|
|
except Empty:
|
|
pass
|
|
|
|
@contextmanager
|
|
def nested(self, message: str, attributes: Dict[str, str] = {}) -> Iterator[None]:
|
|
self._eprint(
|
|
self.maybe_prefix(
|
|
Style.BRIGHT + Fore.GREEN + message + Style.RESET_ALL, attributes
|
|
)
|
|
)
|
|
|
|
self.xml.startElement("nest", attrs={})
|
|
self.xml.startElement("head", attributes)
|
|
self.xml.characters(message)
|
|
self.xml.endElement("head")
|
|
|
|
tic = time.time()
|
|
self.drain_log_queue()
|
|
yield
|
|
self.drain_log_queue()
|
|
toc = time.time()
|
|
self.log("(finished: {}, in {:.2f} seconds)".format(message, toc - tic))
|
|
|
|
self.xml.endElement("nest")
|
|
|
|
|
|
rootlog = Logger()
|