[v2] linux-user/strace: Improve strace output for read() and getcwd()

The strace functionality in qemu-user lacks the possibility to trace
which real values get returned to pointers in userspace by syscalls.

For example, the read() and getcwd() syscalls currently only show the
destination address where the syscalls should put the return values:
2532 read(3,0xff80038c,512) = 512
2532 getcwd(0x18180,4096) = 9

With the patch below, one now can specify in print_syscall_late() which
syscalls should be executed first, before they get printed.
After adding the read() and getcwd() syscalls, we now get this output in
with strace instead:
1708 read(3,"\177ELF\1\2\1\3\0\0\0\0\0\0\0\0\0\3\0\17\0\0\0\1\0\2bl\0\0\04"...,512) = 512
1708 getcwd("/usr/bin",4096) = 9

This patch adds just the framework with the respective implemenations for
read() and getcwd(). If applied, more functions can be added easily later.

Signed-off-by: Helge Deller <deller@gmx.de>
---
Changes v2 to v1:
- Print syscall name, e.g. "read(" before calling the syscall. In case of
  crash people will then be able to see that it crashed in this "late" call.
  Based on feedback by Aleksandar Markovic <aleksandar.m.mail@gmail.com>

Patchew URL: https://patchew.org/QEMU/20191124115656.GA23850@ls3530.fritz.box/



Hi,

This series seems to have some coding style problems. See output below for
more information:

Subject: [PATCH v2] linux-user/strace: Improve strace output for read() and getcwd()
Type: series
Message-id: 20191124115656.GA23850@ls3530.fritz.box

=== TEST SCRIPT BEGIN ===
#!/bin/bash
git rev-parse base > /dev/null || exit 0
git config --local diff.renamelimit 0
git config --local diff.renames True
git config --local diff.algorithm histogram
./scripts/checkpatch.pl --mailback base..
=== TEST SCRIPT END ===

Updating 3c8cf5a9c21ff8782164d1def7f44bd888713384
Switched to a new branch 'test'
5d6b69e linux-user/strace: Improve strace output for read() and getcwd()

=== OUTPUT BEGIN ===
WARNING: line over 80 characters
#51: FILE: linux-user/strace.c:64:
+UNUSED static void print_encoded_string(abi_long addr, unsigned int maxlen, int last);

ERROR: storage class should be at the beginning of the declaration
#51: FILE: linux-user/strace.c:64:
+UNUSED static void print_encoded_string(abi_long addr, unsigned int maxlen, int last);

total: 1 errors, 1 warnings, 197 lines checked

Commit 5d6b69e0e07b (linux-user/strace: Improve strace output for read() and getcwd()) has style problems, please review.  If any of these errors
are false positives report them to the maintainer, see
CHECKPATCH in MAINTAINERS.
=== OUTPUT END ===

Test command exited with code: 1


The full log is available at
http://patchew.org/logs/20191124115656.GA23850@ls3530.fritz.box/testing.checkpatch/?type=message.
---
Email generated automatically by Patchew [https://patchew.org/].
Please send your feedback to patchew-devel@redhat.com

On 24.11.19 13:38, no-reply@patchew.org wrote:
> Patchew URL: https://patchew.org/QEMU/20191124115656.GA23850@ls3530.fritz.box/
> ...
> This series seems to have some coding style problems. See output below for
> more information:
>
> Subject: [PATCH v2] linux-user/strace: Improve strace output for read() and getcwd()
> ...
> === OUTPUT BEGIN ===
> WARNING: line over 80 characters
> #51: FILE: linux-user/strace.c:64:
> +UNUSED static void print_encoded_string(abi_long addr, unsigned int maxlen, int last);
>
> ERROR: storage class should be at the beginning of the declaration
> #51: FILE: linux-user/strace.c:64:
> +UNUSED static void print_encoded_string(abi_long addr, unsigned int maxlen, int last);

IMHO the error is bogus.
This is the part of the patch:

diff --git a/linux-user/strace.c b/linux-user/strace.c
index de43238fa4..dc963accd5 100644
--- a/linux-user/strace.c
+++ b/linux-user/strace.c
@@ -61,6 +61,7 @@ UNUSED static void print_open_flags(abi_long, int);
 UNUSED static void print_syscall_prologue(const struct syscallname *);
 UNUSED static void print_syscall_epilogue(const struct syscallname *);
 UNUSED static void print_string(abi_long, int);
+UNUSED static void print_encoded_string(abi_long addr, unsigned int maxlen, int last);
 UNUSED static void print_buf(abi_long addr, abi_long len, int last);
 UNUSED static void print_raw_param(const char *, abi_long, int);
 UNUSED static void print_timeval(abi_ulong, int);

Maybe the warning is somewhat real, but *if* I should cut the line to
less than 80 chars, where should I break it?
E.g. like this?

+UNUSED static void print_encoded_string(abi_long addr, unsigned int maxlen,
+					 int last);
 UNUSED static void print_buf(abi_long addr, abi_long len, int last);

Helge

On Sun, Nov 24, 2019 at 12:56 PM Helge Deller <deller@gmx.de> wrote:
>
> The strace functionality in qemu-user lacks the possibility to trace
> which real values get returned to pointers in userspace by syscalls.
>
> For example, the read() and getcwd() syscalls currently only show the
> destination address where the syscalls should put the return values:
> 2532 read(3,0xff80038c,512) = 512
> 2532 getcwd(0x18180,4096) = 9
>
> With the patch below, one now can specify in print_syscall_late() which
> syscalls should be executed first, before they get printed.
> After adding the read() and getcwd() syscalls, we now get this output in
> with strace instead:
> 1708 read(3,"\177ELF\1\2\1\3\0\0\0\0\0\0\0\0\0\3\0\17\0\0\0\1\0\2bl\0\0\04"...,512) = 512
> 1708 getcwd("/usr/bin",4096) = 9
>
> This patch adds just the framework with the respective implemenations for
> read() and getcwd(). If applied, more functions can be added easily later.
>
> Signed-off-by: Helge Deller <deller@gmx.de>
> ---
> Changes v2 to v1:
> - Print syscall name, e.g. "read(" before calling the syscall. In case of
>   crash people will then be able to see that it crashed in this "late" call.
>   Based on feedback by Aleksandar Markovic <aleksandar.m.mail@gmail.com>
>

Very nice output if everything goes nice and dendy.

Still not good for people that use strace when something goes wrong.
The output for read() scenario for crash/hang situations is reduced to:

read(

while it used to be

read(3,0xff80038c,512)

This is a regression.

Please consider the content of the patch to be an option, settable
by end user.

Best regards,
Aleksandar




>
> diff --git a/linux-user/qemu.h b/linux-user/qemu.h
> index f6f5fe5fbb..65557660a9 100644
> --- a/linux-user/qemu.h
> +++ b/linux-user/qemu.h
> @@ -371,6 +371,10 @@ extern long safe_syscall_base(int *pending, long number, ...);
>  int host_to_target_waitstatus(int status);
>
>  /* strace.c */
> +const struct syscallname *print_syscall_prologue_num(int num);
> +void print_syscall_late(const struct syscallname *sc,
> +              abi_long arg1, abi_long arg2, abi_long arg3,
> +              abi_long arg4, abi_long arg5, abi_long arg6);
>  void print_syscall(int num,
>                     abi_long arg1, abi_long arg2, abi_long arg3,
>                     abi_long arg4, abi_long arg5, abi_long arg6);
> diff --git a/linux-user/strace.c b/linux-user/strace.c
> index de43238fa4..dc963accd5 100644
> --- a/linux-user/strace.c
> +++ b/linux-user/strace.c
> @@ -61,6 +61,7 @@ UNUSED static void print_open_flags(abi_long, int);
>  UNUSED static void print_syscall_prologue(const struct syscallname *);
>  UNUSED static void print_syscall_epilogue(const struct syscallname *);
>  UNUSED static void print_string(abi_long, int);
> +UNUSED static void print_encoded_string(abi_long addr, unsigned int maxlen, int last);
>  UNUSED static void print_buf(abi_long addr, abi_long len, int last);
>  UNUSED static void print_raw_param(const char *, abi_long, int);
>  UNUSED static void print_timeval(abi_ulong, int);
> @@ -1196,6 +1197,26 @@ print_syscall_prologue(const struct syscallname *sc)
>      gemu_log("%s(", sc->name);
>  }
>
> +void
> +print_syscall_late(const struct syscallname *sc,
> +              abi_long arg1, abi_long arg2, abi_long arg3,
> +              abi_long arg4, abi_long arg5, abi_long arg6)
> +{
> +    const char *format = TARGET_ABI_FMT_ld "," TARGET_ABI_FMT_ld ","
> +                    TARGET_ABI_FMT_ld "," TARGET_ABI_FMT_ld ","
> +                    TARGET_ABI_FMT_ld "," TARGET_ABI_FMT_ld ")";
> +
> +    if (sc->call != NULL) {
> +        sc->call(sc, arg1, arg2, arg3, arg4, arg5, arg6);
> +    } else {
> +        if (sc->format != NULL) {
> +            format = sc->format;
> +        }
> +        gemu_log(format, arg1, arg2, arg3, arg4, arg5, arg6);
> +    }
> +}
> +
> +
>  /*ARGSUSED*/
>  static void
>  print_syscall_epilogue(const struct syscallname *sc)
> @@ -1204,6 +1225,37 @@ print_syscall_epilogue(const struct syscallname *sc)
>      gemu_log(")");
>  }
>
> +#define MAX_ENCODED_CHARS 32
> +static void
> +print_encoded_string(abi_long addr, unsigned int maxlen, int last)
> +{
> +    unsigned int maxout;
> +    char *s, *str;
> +
> +    s = lock_user_string(addr);
> +    if (s == NULL) {
> +        /* can't get string out of it, so print it as pointer */
> +        print_pointer(addr, last);
> +        return;
> +    }
> +
> +    str = s;
> +    gemu_log("\"");
> +    maxout = MIN(maxlen, MAX_ENCODED_CHARS);
> +    while (maxout--) {
> +        unsigned char c = *str++;
> +        if (isprint(c)) {
> +            gemu_log("%c", c);
> +        } else {
> +            gemu_log("\\%o", (unsigned int) c);
> +        }
> +    }
> +    unlock_user(s, addr, 0);
> +
> +    gemu_log("\"%s%s", maxlen > MAX_ENCODED_CHARS ? "..." : "",
> +                    get_comma(last));
> +}
> +
>  static void
>  print_string(abi_long addr, int last)
>  {
> @@ -1633,6 +1685,18 @@ print_futimesat(const struct syscallname *name,
>  }
>  #endif
>
> +#ifdef TARGET_NR_getcwd
> +static void
> +print_getcwd(const struct syscallname *name,
> +    abi_long arg0, abi_long arg1, abi_long arg2,
> +    abi_long arg3, abi_long arg4, abi_long arg5)
> +{
> +    print_string(arg0, 0);
> +    print_raw_param("%u", arg1, 1);
> +    print_syscall_epilogue(name);
> +}
> +#endif
> +
>  #ifdef TARGET_NR_settimeofday
>  static void
>  print_settimeofday(const struct syscallname *name,
> @@ -2428,6 +2492,19 @@ print_fstatat64(const struct syscallname *name,
>  #define print_newfstatat    print_fstatat64
>  #endif
>
> +#ifdef TARGET_NR_read
> +static void
> +print_read(const struct syscallname *name,
> +    abi_long arg0, abi_long arg1, abi_long arg2,
> +    abi_long arg3, abi_long arg4, abi_long arg5)
> +{
> +    print_raw_param("%d", arg0, 0);
> +    print_encoded_string(arg1, arg2, 0);
> +    print_raw_param("%u", arg2, 1);
> +    print_syscall_epilogue(name);
> +}
> +#endif
> +
>  #ifdef TARGET_NR_readlink
>  static void
>  print_readlink(const struct syscallname *name,
> @@ -2817,6 +2894,22 @@ static int nsyscalls = ARRAY_SIZE(scnames);
>  /*
>   * The public interface to this module.
>   */
> +
> +const struct syscallname *print_syscall_prologue_num(int num)
> +{
> +    int i;
> +
> +    gemu_log("%d ", getpid());
> +
> +    for (i = 0; i < nsyscalls; i++)
> +        if (scnames[i].nr == num) {
> +            print_syscall_prologue(&scnames[i]);
> +            return &scnames[i];
> +        }
> +    gemu_log("Unknown syscall %d\n", num);
> +    return NULL; /* will crash qemu */
> +}
> +
>  void
>  print_syscall(int num,
>                abi_long arg1, abi_long arg2, abi_long arg3,
> diff --git a/linux-user/strace.list b/linux-user/strace.list
> index d49a1e92a8..220b1f4c46 100644
> --- a/linux-user/strace.list
> +++ b/linux-user/strace.list
> @@ -272,7 +272,7 @@
>  { TARGET_NR_getcpu, "getcpu" , "%s(%p,%d)", NULL, NULL },
>  #endif
>  #ifdef TARGET_NR_getcwd
> -{ TARGET_NR_getcwd, "getcwd" , "%s(%p,%d)", NULL, NULL },
> +{ TARGET_NR_getcwd, "getcwd" , NULL, print_getcwd, NULL },
>  #endif
>  #ifdef TARGET_NR_getdents
>  { TARGET_NR_getdents, "getdents" , NULL, NULL, NULL },
> @@ -1080,7 +1080,7 @@
>  { TARGET_NR_quotactl, "quotactl" , NULL, NULL, NULL },
>  #endif
>  #ifdef TARGET_NR_read
> -{ TARGET_NR_read, "read" , "%s(%d,%#x,%d)", NULL, NULL },
> +{ TARGET_NR_read, "read" , NULL, print_read, NULL },
>  #endif
>  #ifdef TARGET_NR_readahead
>  { TARGET_NR_readahead, "readahead" , NULL, NULL, NULL },
> diff --git a/linux-user/syscall.c b/linux-user/syscall.c
> index ce399a55f0..7207826137 100644
> --- a/linux-user/syscall.c
> +++ b/linux-user/syscall.c
> @@ -12069,6 +12069,21 @@ static abi_long do_syscall1(void *cpu_env, int num, abi_long arg1,
>      return ret;
>  }
>
> +/*
> + * True if this syscall should be printed after having called the native
> + * syscall, so that values which are fed back to userspace gets printed.
> + */
> +static int is_print_syscall_late(int syscall)
> +{
> +    switch (syscall) {
> +    case TARGET_NR_getcwd:
> +    case TARGET_NR_read:
> +        return 1;
> +    default:
> +        return 0;
> +    }
> +}
> +
>  abi_long do_syscall(void *cpu_env, int num, abi_long arg1,
>                      abi_long arg2, abi_long arg3, abi_long arg4,
>                      abi_long arg5, abi_long arg6, abi_long arg7,
> @@ -12095,9 +12110,20 @@ abi_long do_syscall(void *cpu_env, int num, abi_long arg1,
>                           arg2, arg3, arg4, arg5, arg6, arg7, arg8);
>
>      if (unlikely(do_strace)) {
> -        print_syscall(num, arg1, arg2, arg3, arg4, arg5, arg6);
> +        const struct syscallname *sc;
> +        int late_printing;
> +
> +        late_printing = is_print_syscall_late(num);
> +        if (late_printing) {
> +            sc = print_syscall_prologue_num(num);
> +        } else {
> +            print_syscall(num, arg1, arg2, arg3, arg4, arg5, arg6);
> +        }
>          ret = do_syscall1(cpu_env, num, arg1, arg2, arg3, arg4,
>                            arg5, arg6, arg7, arg8);
> +        if (late_printing) {
> +            print_syscall_late(sc, arg1, arg2, arg3, arg4, arg5, arg6);
> +        }
>          print_syscall_ret(num, ret);
>      } else {
>          ret = do_syscall1(cpu_env, num, arg1, arg2, arg3, arg4,