On Mon, Oct 4, 2021 at 4:58 PM David Gow davidgow@google.com wrote:
On Tue, Oct 5, 2021 at 7:46 AM Daniel Latypov dlatypov@google.com wrote:
On Mon, Oct 4, 2021 at 4:34 PM 'David Gow' via KUnit Development kunit-dev@googlegroups.com wrote:
On Tue, Oct 5, 2021 at 1:01 AM Daniel Latypov dlatypov@google.com wrote:
Currently, `run_kernel()` dumps all the kernel output to a file (.kunit/test.log) and then opens the file and yields it to callers. This made it easier to respect the requested timeout, if any.
But it means that we can't yield the results in real time, either to the parser or to stdout (if --raw_output is set).
This change spins up a background thread to enforce the timeout, which allows us to yield the kernel output in real time, while also copying it to the .kunit/test.log file. It's also careful to ensure that the .kunit/test.log file is complete, even in the kunit_parser throws an exception/otherwise doesn't consume every line, see the new `finally` block and unit test.
For example:
$ ./tools/testing/kunit/kunit.py run --arch=x86_64 --raw_output <configure + build steps> ...
<can now see output from QEMU in real time>
This does not currently have a visible effect when --raw_output is not passed, as kunit_parser.py currently only outputs everything at the end. But that could change, and this patch is a necessary step towards showing parsed test results in real time.
Signed-off-by: Daniel Latypov dlatypov@google.com
tools/testing/kunit/kunit_kernel.py | 73 +++++++++++++++----------- tools/testing/kunit/kunit_tool_test.py | 17 ++++++ 2 files changed, 60 insertions(+), 30 deletions(-)
diff --git a/tools/testing/kunit/kunit_kernel.py b/tools/testing/kunit/kunit_kernel.py index 2c6f916ccbaf..b8cba8123aa3 100644 --- a/tools/testing/kunit/kunit_kernel.py +++ b/tools/testing/kunit/kunit_kernel.py @@ -12,7 +12,8 @@ import subprocess import os import shutil import signal -from typing import Iterator, Optional, Tuple +import threading +from typing import Iterator, List, Optional, Tuple
from contextlib import ExitStack
@@ -103,8 +104,8 @@ class LinuxSourceTreeOperations(object): if stderr: # likely only due to build warnings print(stderr.decode())
def run(self, params, timeout, build_dir, outfile) -> None:pass
def start(self, params: List[str], build_dir: str) -> subprocess.Popen:raise RuntimeError('not implemented!')class LinuxSourceTreeOperationsQemu(LinuxSourceTreeOperations): @@ -123,7 +124,7 @@ class LinuxSourceTreeOperationsQemu(LinuxSourceTreeOperations): kconfig.parse_from_string(self._kconfig) base_kunitconfig.merge_in_entries(kconfig)
def run(self, params, timeout, build_dir, outfile):
def start(self, params: List[str], build_dir: str) -> subprocess.Popen: kernel_path = os.path.join(build_dir, self._kernel_path) qemu_command = ['qemu-system-' + self._qemu_arch, '-nodefaults',@@ -134,18 +135,10 @@ class LinuxSourceTreeOperationsQemu(LinuxSourceTreeOperations): '-nographic', '-serial stdio'] + self._extra_qemu_params print('Running tests with:\n$', ' '.join(qemu_command))
with open(outfile, 'w') as output:process = subprocess.Popen(' '.join(qemu_command),stdin=subprocess.PIPE,stdout=output,stderr=subprocess.STDOUT,text=True, shell=True)try:process.wait(timeout=timeout)except Exception as e:print(e)process.terminate()return process
return subprocess.Popen(' '.join(qemu_command),stdout=subprocess.PIPE,stderr=subprocess.STDOUT,text=True, shell=True)class LinuxSourceTreeOperationsUml(LinuxSourceTreeOperations): """An abstraction over command line operations performed on a source tree.""" @@ -175,17 +168,13 @@ class LinuxSourceTreeOperationsUml(LinuxSourceTreeOperations): kunit_parser.print_with_timestamp( 'Starting Kernel with all configs takes a few minutes...')
def run(self, params, timeout, build_dir, outfile):
def start(self, params: List[str], build_dir: str) -> subprocess.Popen: """Runs the Linux UML binary. Must be named 'linux'.""" linux_bin = get_file_path(build_dir, 'linux')
outfile = get_outfile_path(build_dir)with open(outfile, 'w') as output:process = subprocess.Popen([linux_bin] + params,stdin=subprocess.PIPE,This breaks --raw_output under UML for me. Including the stdin=subprocess.PIPE again seems to fix it.
Can you give an example of what it does?
I don't see any issues with --raw_output under UML with the patch as-is. I was mainly testing this with UML, and I must have ran it some 10s of times, so I'm a bit surprised.
On an earlier version, I saw some mangling of --raw_output (\n was missing), but that went away after some revisions.
Yeah, that's the sort of thing I'm seeing: \n being treated as just a new line (without the carriage return). It happens pretty consistently, though sometimes the text wraps and sometimes (well, once) everything gets forced into the last column of the terminal. I've not been able to get it to work at all without having stdin be subprocess.PIPE.
I can't repro in the shell I was using while writing this. Starting up a new session, I get: * good * bad x3 * good * bad x3 * good * bad x3 * bad, but not as bad (phew, I thought this was cursed)
.kunit/test.log contains the output with proper \n each time I checked.
Doesn't seem to repro when redirected into a file:
$ ./tools/testing/kunit/kunit.py exec --raw_output > /tmp/out && diff /tmp/out .kunit/test.log | grep -m1 '^>'
Piping it through cat also seems 100% fine: $ ./tools/testing/kunit/kunit.py exec --raw_output | cat
So having stdin be subprocess.PIPE sorta makes sense in some twisted way. I can also now repro that setting stdin=subprocess.PIPE seems to fix it.
I don't want to put back subprocess.PIPE, but I'm not confident in being able to find a better solution...
It occurs both under tmux and not, and under Konsole and xterm, so it doesn't appear to be specific to any given terminal implementation. Still occurs even after running 'reset', and with a clean build. QEMU-based --raw_output works fine.