Re: [kvm-unit-tests v2 8/8] scripts: pretty print stack traces

[Andrew Jones <drjones@redhat.com>]

On Wed, Mar 02, 2016 at 05:09:38PM -0800, Peter Feiner wrote:
> Optionally pretty print stacks in test.log with 'run_tests.sh -p'.
> 
> The script runs addresses through addr2line to get file names and line
> numbers.  Also prints out source code lines if files are available.
> For example
> 
> 0x004013f5: ac_test_exec at x86/access.c:818
>             }
>       >     ac_test_setup_pte(at, pool);
>             r = ac_test_do_access(at);
> 0x004014dd: ac_test_run at x86/access.c:852
>                 ++tests;
>       >         successes += ac_test_exec(&at, &pool);
>             } while (ac_test_bump(&at));
> 0x0040157d: main at x86/access.c:873
>             printf("starting test\n\n");
>       >     r = ac_test_run();
>             return r ? 0 : 1;
> 0x0040028e: start64 at x86/cstart64.S:206
>                 lea __argv(%rip), %rsi
>       >         call main
>                 mov %eax, %edi
> 
> Signed-off-by: Peter Feiner <pfeiner@google.com>
> ---
>  run_tests.sh                   | 10 +++++--
>  scripts/pretty_print_stacks.py | 61 ++++++++++++++++++++++++++++++++++++++++++
>  2 files changed, 69 insertions(+), 2 deletions(-)
>  create mode 100755 scripts/pretty_print_stacks.py
> 
> diff --git a/run_tests.sh b/run_tests.sh
> index 2c8af36..13bc089 100755
> --- a/run_tests.sh
> +++ b/run_tests.sh
> @@ -1,6 +1,7 @@
>  #!/bin/bash
>  
>  verbose="no"
> +pretty="no"
>  
>  if [ ! -f config.mak ]; then
>      echo "run ./configure && make first. See ./configure -h"
> @@ -18,6 +19,7 @@ Usage: $0 [-g group] [-h] [-v]
>      -g: Only execute tests in the given group
>      -h: Output this help text
>      -v: Enables verbose mode
> +    -p: Pretty print stack traces in test.log
>  
>  Set the environment variable QEMU=/path/to/qemu-system-ARCH to
>  specify the appropriate qemu binary for ARCH-run.
> @@ -27,8 +29,9 @@ EOF
>  
>  RUNTIME_arch_run="./$TEST_DIR/run"
>  source scripts/runtime.bash
> +log_redir=">> test.log"
>  
> -while getopts "g:hv" opt; do
> +while getopts "g:hvp" opt; do
>      case $opt in
>          g)
>              only_group=$OPTARG
> @@ -40,13 +43,16 @@ while getopts "g:hv" opt; do
>          v)
>              verbose="yes"
>              ;;
> +        p)
> +           log_redir="> >(./scripts/pretty_print_stacks.py \$kernel >> test.log)"
> +           ;;
>          *)
>              exit
>              ;;
>      esac
>  done
>  
> -RUNTIME_arch_run="./$TEST_DIR/run >> test.log"
> +RUNTIME_arch_run="./$TEST_DIR/run $log_redir"
>  config=$TEST_DIR/unittests.cfg
>  rm -f test.log
>  echo > test.log
> diff --git a/scripts/pretty_print_stacks.py b/scripts/pretty_print_stacks.py
> new file mode 100755
> index 0000000..49564bd
> --- /dev/null
> +++ b/scripts/pretty_print_stacks.py
> @@ -0,0 +1,61 @@
> +#!/usr/bin/env python
> +
> +import re
> +import subprocess
> +import sys
> +
> +if len(sys.argv) != 2:
> +    sys.stderr.write('usage: %s <kernel>\n' % sys.argv[0])
> +    sys.exit(1)
> +
> +binary = sys.argv[1]
> +
> +# Subvert output buffering.
> +def puts(string):
> +    sys.stdout.write(string)
> +    sys.stdout.flush()
> +
> +try:
> +    while True:
> +        # Subvert input buffering.
> +        line = sys.stdin.readline()
> +        if line == '':
> +            break
> +
> +        if not line.strip().startswith('STACK:'):
> +            puts(line)
> +            continue
> +
> +        addrs = line.split()[1:]
> +        # Output like this:
> +        #        0x004002be: start64 at path/to/kvm-unit-tests/x86/cstart64.S:208
> +        #         (inlined by) test_ept_violation at path/to/kvm-unit-tests/x86/vmx_tests.c:1719 (discriminator 1)
> +        cmd = ['addr2line', '-e', binary, '-i', '-f', '--pretty', '--address']
> +        cmd.extend(addrs)
> +
> +        p = subprocess.Popen(cmd, stdout=subprocess.PIPE)
> +        out, err = p.communicate()
> +        if p.returncode != 0:
> +            puts(line)
> +            continue
> +
> +        for line in out.splitlines():
> +            m = re.match('(.*) at [^ ]*/kvm-unit-tests/([^ ]*):([0-9]+)(.*)', line)
> +            if m is None:
> +                puts('%s\n' % line)
> +                continue
> +
> +            head, path, line, tail = m.groups()
> +            line = int(line)
> +            puts('%s at %s:%d%s\n' % (head, path, line, tail))
> +            try:
> +                lines = open(path).readlines()
> +            except IOError:
> +                continue
> +            if line > 1:
> +                puts('        %s\n' % lines[line - 2].rstrip())
> +            puts('      > %s\n' % lines[line - 1].rstrip())
> +            if line < len(lines):
> +                puts('        %s\n' % lines[line].rstrip())
> +except:
> +    sys.exit(1)
> -- 
> 2.7.0.rc3.207.g0ac5344

I think this probably could have been written in bash, but I'm not
overly opposed to adding python scripts, as I think we're pretty safe
adding that dependency, particularly when its use can be disabled.

wrt to enabling/disabling it though, how about we create a new configure
command line option instead. One that defaults to on, if the architecture
supports pretty-printing, but can be switched off. Then, run_tests.sh,
which sources config.mak, can just turn pretty printing on by default
when it's available, rather than introducing the -p option, which I
think we'd always want to use when we can.

Thanks,
drew