run logging works

README.adoc

@@ -8146,7 +8146,7 @@ printf 'echo "second benchmark";m5 exit' > data/readfile
 ./run -a aarch64 -g -l 1
 ....
 
-Since this is such a common setup, we provide helper for it at: link:rootfs_overlay/gem5.sh[rootfs_overlay/gem5.sh].
+Since this is such a common setup, we provide helper for it at: link:rootfs_overlay/gem5.sh[rootfs_overlay/gem5.sh]. This script is analogous to gem5's in-tree link:https://github.com/gem5/gem5/blob/2b4b94d0556c2d03172ebff63f7fc502c3c26ff8/configs/boot/hack_back_ckpt.rcS[hack_back_ckpt.rcS], but with less noise.
 
 Other loophole possibilities include:
 
@@ -8998,13 +8998,13 @@ time \
 and this line is also saved to a file for convenience:
 
 ....
-cat "$(./getvar -a arm run_dir)/run.sh"
+cat "$(./getvar -a arm run_dir)/cmd.sh"
 ....
 
 or for gem5:
 
 ....
-cat "$(./getvar -a arm -g run_dir)/run.sh"
+cat "$(./getvar -a arm -g run_dir)/cmd.sh"
 ....
 
 Next, you will also want to give the relevant images to save them time. Zip the images with:
@@ -9422,10 +9422,10 @@ The action seems to be happening at: `hw/arm/virt.c`.
 **** `out/<arch>/buildroot/build/linux-custom`: symlink to a variant, custom madness that we do on top of Buildroot: <<linux-kernel-build-variants>>
 **** `out/<arch>/buildroot/build/linux-custom.<variant>`: what `linux-custom` points to
 *** `out/<arch>/qemu`: QEMU runtime outputs
-*** `out/<arch>/qemu/<run-id>/run.sh`: full CLI used to run QEMU. See: <<report-upstream-bugs>>
+*** `out/<arch>/qemu/<run-id>/cmd.sh`: full CLI used to run QEMU. See: <<report-upstream-bugs>>
 *** `out/<arch>/gem5/<run-id>/`: gem5 runtime outputs
 **** `out/<arch>/gem5/<run-id>/m5out`
-**** `out/<arch>/gem5/<run-id>/run.sh`: full CLI used to run gem5. See: <<report-upstream-bugs>>
+**** `out/<arch>/gem5/<run-id>/cmd.sh`: full CLI used to run gem5. See: <<report-upstream-bugs>>
 ** `out/common`: cross arch outputs, for when we can gain a lot of time and space by sharing things that are common across different archs.
 *** `out/common/dl/`: Buildroot caches downloaded source there due to `BR2_DL_DIR`
 *** `out/common/gem5/`: `arm` and `aarch64` have the same build.

common.py

@@ -6,6 +6,7 @@ import imp
 import subprocess
 import os
 import shlex
+import stat
 import sys
 
 this = sys.modules[__name__]
@@ -115,11 +116,18 @@ around when you checkout between branches.
     parser.set_defaults(**defaults)
     return parser
 
-def print_cmd(cmd):
+def print_cmd(cmd, cmd_file=None):
     out = []
     for arg in cmd:
         out.extend([shlex.quote(arg), ' \\\n'])
-    print(''.join(out))
+    out = ''.join(out)
+    print(out)
+    if cmd_file is not None:
+        with open(cmd_file, 'w') as f:
+            f.write('#!/usr/bin/env bash\n')
+            f.write(out)
+        st = os.stat(cmd_file)
+        os.chmod(cmd_file, st.st_mode | stat.S_IXUSR)
 
 def setup(parser, **extra_args):
     """
@@ -185,6 +193,7 @@ def setup(parser, **extra_args):
         this.executable = this.qemu_executable
         this.run_dir = this.qemu_run_dir
         this.termout_file = this.qemu_termout_file
+    this.cmd_file = os.path.join(this.run_dir, 'cmd.sh')
     if args.arch == 'arm':
         this.linux_image = os.path.join('arch', 'arm', 'boot', 'zImage')
     elif args.arch == 'aarch64':

rootfs_overlay/gem5.sh

@@ -1,5 +1,5 @@
 #!/bin/sh
-# This covers the most common setup to run a benchmark in gem5 and exit.
+# https://github.com/cirosantilli/linux-kernel-module-cheat#gem5-restore-new-scrip
 m5 checkpoint
 m5 resetstats
 m5 readfile | sh

run

@@ -5,6 +5,7 @@ import shlex
 import signal
 import subprocess
 import sys
+import re
 
 import common
 
@@ -21,7 +22,7 @@ parser.add_argument(
     help='Run GDB on the emulator itself.'
 )
 kvm_group.add_argument(
-    '-d', '--debug', default=False, action='store_true',
+    '-d', '--debug-guest', default=False, action='store_true',
     help='Wait for GDB to connect before starting execution'
 )
 parser.add_argument(
@@ -171,7 +172,7 @@ if args.debug_vm:
     debug_vm = ['gdb', '-q', '-ex', 'start', '--args']
 else:
     debug_vm = []
-if args.debug:
+if args.debug_guest:
     extra_qemu_args.append('-S')
 if args.kernel_cli_extra_after_dash_base64 is not None:
     kernel_cli_extra_after_dash += ' lkmc_eval_base64="{}"'.format(common.base64_encode(args.kernel_cli_extra_after_dash_base64))
@@ -365,7 +366,7 @@ if args.tmux:
             'sleep 2;./gem5-shell -n {} {}' \
             .format(args.run_id, args.tmux_args)
         ])
-    elif args.debug:
+    elif args.debug_guest:
         # TODO find a nicer way to forward all those args automatically.
         # Part of me wants to: https://github.com/jonathanslenders/pymux
         # but it cannot be used as a library properly it seems, and it is
@@ -376,33 +377,41 @@ if args.tmux:
         ])
 
 cmd += extra_emulator_args
-common.print_cmd(cmd)
+do_tee = not debug_vm
+if do_tee:
+    stdout=subprocess.PIPE
+    stderr=subprocess.STDOUT
+else:
+    stdout=None
+    stderr=None
+common.print_cmd(cmd, common.cmd_file)
 # Otherwise Ctrl + C gives an ugly Python stack trace for gem5 (QEMU takes over terminal and is fine).
 signal.signal(signal.SIGINT, signal.SIG_IGN)
-subprocess.Popen(cmd, env=env).wait()
+# https://stackoverflow.com/questions/15535240/python-popen-write-to-stdout-and-log-file-simultaneously/52090802#52090802
+with subprocess.Popen(cmd, stdout=stdout, stderr=stderr, env=env) as proc:
+    if do_tee:
+        with open(common.termout_file, 'bw') as logfile:
+            while True:
+                byte = proc.stdout.read(1)
+                if byte:
+                    sys.stdout.buffer.write(byte)
+                    sys.stdout.flush()
+                    logfile.write(byte)
+                else:
+                    break
 signal.signal(signal.SIGINT, signal.SIG_DFL)
-
-#cmd="time \\
-#${cmd}${extra_emulator_args}"
-#if [ -z "$debug_vm" ]; then
-#  cmd="${cmd}\
-#|& tee >(ts -s %.s > ${common.termout_file})\
-#"
-#fi
-#"${common.root_dir}/eeval" "$cmd" "${common.run_dir}/run.sh"
-#cmd_out=$?
-#if [ "$cmd_out" -ne 0 ]; then
-#  exit "$cmd_out"
-#fi
-
-# TODO
-## Check if guest panicked.
-#if args.gem5:
-#    # We have to do some parsing here because gem5 exits with status 0 even when panic happens.
-#    # Grepping for '^panic: ' does not work because some errors don't show that message.
-#    panic_msg = '--- BEGIN LIBC BACKTRACE ---$'
-#else:
-#    panic_msg = 'Kernel panic - not syncing'
-#if grep -E -e "$panic_msg" -q "common.termout_file"; then
-#    print('Simulation error detected by parsing logs. Exiting with status 1.', file=sys.stderr)
-#    sys.exit(1)
+if proc.returncode != 0:
+    sys.exit(proc.returncode)
+# Check if guest panicked.
+if args.gem5:
+    # We have to do some parsing here because gem5 exits with status 0 even when panic happens.
+    # Grepping for '^panic: ' does not work because some errors don't show that message.
+    panic_msg = '--- BEGIN LIBC BACKTRACE ---$'
+else:
+    panic_msg = 'Kernel panic - not syncing'
+panic_re = re.compile(panic_msg)
+with open(common.termout_file, 'r') as logfile:
+    for line in logfile:
+        if panic_re.search(line):
+            print('Simulation error detected by parsing logs. Exiting with status 1.', file=sys.stderr)
+            sys.exit(1)