[PATCH 6/7] kunit: tool: Serialise output written from multiple threads

[Mark Brown <broonie@kernel.org>]

Python's text streams are not thread safe. If two threads write to
sys.stdout at the same time the stream's internal buffer can be
corrupted, resulting in lost output and runs of NUL bytes or heap
garbage being written in its place. This isn't an issue currently, but
will be when we implement support for parallel test execution.

Add a lock to kunit_printer which Printer.print() takes around each
write, and route the other prints that can run concurrently with the
test results through the printer: the kernel start banners and timeout
message in kunit_kernel, and the raw, JSON and JUnit output to stdout.
Prints that only happen before any kernel is started, such as during
configuration and build, are left alone.

No change in output when a single kernel is run at a time.

Signed-off-by: Mark Brown <broonie@kernel.org>
---
 tools/testing/kunit/kunit.py         | 4 ++--
 tools/testing/kunit/kunit_junit.py   | 3 ++-
 tools/testing/kunit/kunit_kernel.py  | 7 ++++---
 tools/testing/kunit/kunit_printer.py | 9 ++++++++-
 4 files changed, 16 insertions(+), 7 deletions(-)

diff --git a/tools/testing/kunit/kunit.py b/tools/testing/kunit/kunit.py
index 971e70b0fb1a..0132687cdd43 100755
--- a/tools/testing/kunit/kunit.py
+++ b/tools/testing/kunit/kunit.py
@@ -272,7 +272,7 @@ def parse_tests(request: KunitParseRequest, metadata: kunit_json.Metadata, input
 		elif request.raw_output == 'kunit':
 			output = kunit_parser.extract_tap_lines(output)
 		for line in output:
-			print(line.rstrip())
+			stdout.print(line.rstrip())
 		parse_time = time.time() - parse_start
 		return KunitResult(KunitStatus.SUCCESS, parse_time), fake_test
 
@@ -302,7 +302,7 @@ def _write_test_results(request: KunitParseRequest, metadata: kunit_json.Metadat
 					test=test,
 					metadata=metadata)
 		if request.json == 'stdout':
-			print(json_str)
+			stdout.print(json_str)
 		else:
 			with open(request.json, 'w') as f:
 				f.write(json_str)
diff --git a/tools/testing/kunit/kunit_junit.py b/tools/testing/kunit/kunit_junit.py
index 3622070358e7..a15c6061003f 100644
--- a/tools/testing/kunit/kunit_junit.py
+++ b/tools/testing/kunit/kunit_junit.py
@@ -6,6 +6,7 @@
 
 from xml.sax.saxutils import quoteattr, XMLGenerator
 import xml.etree.ElementTree as ET
+import kunit_printer
 from kunit_parser import Test, TestStatus
 from typing import Optional
 
@@ -51,7 +52,7 @@ def get_junit_result(test: Test) -> str:
 def print_junit_result(test: Test) -> None:
 	root_element = get_test_suite(test, None)
 	ET.indent(root_element)
-	ET.dump(root_element)
+	kunit_printer.stdout.print(ET.tostring(root_element, encoding='unicode'))
 
 # Write an entire XML file for the test structure starting at test
 def write_junit_result(test: Test, filename: str) -> None:
diff --git a/tools/testing/kunit/kunit_kernel.py b/tools/testing/kunit/kunit_kernel.py
index 1d3226f5a136..508bd62eaa40 100644
--- a/tools/testing/kunit/kunit_kernel.py
+++ b/tools/testing/kunit/kunit_kernel.py
@@ -21,6 +21,7 @@ from typing import Iterator, List, Optional, Tuple, Any
 from types import FrameType
 
 import kunit_config
+import kunit_printer
 import qemu_config
 
 KCONFIG_PATH = '.config'
@@ -132,7 +133,7 @@ class LinuxSourceTreeOperationsQemu(LinuxSourceTreeOperations):
 				'-accel', 'tcg',
 				'-serial', self._serial] + self._extra_qemu_params
 		# Note: shlex.join() does what we want, but requires python 3.8+.
-		print('Running tests with:\n$', ' '.join(shlex.quote(arg) for arg in qemu_command))
+		kunit_printer.stdout.print('Running tests with:\n$ ' + ' '.join(shlex.quote(arg) for arg in qemu_command))
 		return subprocess.Popen(qemu_command,
 					stdin=subprocess.PIPE,
 					stdout=subprocess.PIPE,
@@ -154,7 +155,7 @@ class LinuxSourceTreeOperationsUml(LinuxSourceTreeOperations):
 		"""Runs the Linux UML binary. Must be named 'linux'."""
 		linux_bin = os.path.join(build_dir, 'linux')
 		params.extend(['mem=1G', 'console=tty', 'kunit_shutdown=halt'])
-		print('Running tests with:\n$', linux_bin, ' '.join(shlex.quote(arg) for arg in params))
+		kunit_printer.stdout.print('Running tests with:\n$ ' + linux_bin + ' ' + ' '.join(shlex.quote(arg) for arg in params))
 		return subprocess.Popen([linux_bin] + params,
 					   stdin=subprocess.PIPE,
 					   stdout=subprocess.PIPE,
@@ -402,7 +403,7 @@ class LinuxSourceTree:
 			try:
 				process.wait(timeout=timeout)
 			except Exception as e:
-				print(e)
+				kunit_printer.stdout.print(str(e))
 				process.terminate()
 				process.wait()
 		waiter = threading.Thread(target=_wait_proc)
diff --git a/tools/testing/kunit/kunit_printer.py b/tools/testing/kunit/kunit_printer.py
index ca119f61fe79..440aa7667ece 100644
--- a/tools/testing/kunit/kunit_printer.py
+++ b/tools/testing/kunit/kunit_printer.py
@@ -8,10 +8,16 @@
 
 import datetime
 import sys
+import threading
 import typing
 
 _RESET = '\033[0;0m'
 
+# Python's text streams aren't thread safe: concurrent writes to
+# sys.stdout from several threads can lose output or write garbage. All
+# output from the tool should go through this lock.
+print_lock = threading.Lock()
+
 class Printer:
 	"""Wraps a file object, providing utilities for coloring output, etc."""
 
@@ -25,7 +31,8 @@ class Printer:
 
 	def print(self, message: str) -> None:
 		if self._print:
-			print(message, file=self._output)
+			with print_lock:
+				print(message, file=self._output)
 
 	def print_with_timestamp(self, message: str) -> None:
 		ts = datetime.datetime.now().strftime('%H:%M:%S')

-- 
2.47.3