Re: [PATCH] linux-user: Improve strace output for read() and getcwd()

[Helge Deller]

On 23.11.19 12:34, Aleksandar Markovic wrote:
> On Thursday, November 21, 2019, Helge Deller <address@hidden 
> <mailto:address@hidden>> 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.
>
>
> Great out-of-the-box idea! However, there are some things that are
> not thought over yet. There is a good reason why strace happens
> "early": if something crash-like happens during syscall translation,
> we still have trace of original target syscall. In case of "late"
> flavor, we don't have anything. Another potentially problematic
> aspect is that end user certainly should know whether the trace was
> done "early" or "late" - otherwise, there will be, for certain, cases
> of misinterpretation / misleading / confusion of end users.

Thanks for the feedback - I'm shortly sending a v2 version which
prints the syscall name with an open parenthesis, e.g. "read(" or "getcwd(",
before calling the syscall. That way you can see where it crashed/hangs...

Helge

>
> Yours,
> Aleksandar
>
>
>  
>
>     Signed-off-by: Helge Deller <address@hidden <mailto:address@hidden>>
>
>     diff --git a/linux-user/strace.c b/linux-user/strace.c
>     index de43238fa4..ff254732af 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);
>     @@ -1204,6 +1205,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 +1665,19 @@ 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_syscall_prologue(name);
>     +    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 +2473,20 @@ 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_syscall_prologue(name);
>     +    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,
>     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..c0079ca2b7 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 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,16 @@ 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);
>     +        int late_printing;
>     +        late_printing = print_syscall_late(num);
>     +        if (!late_printing) {
>     +            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(num, arg1, arg2, arg3, arg4, arg5, arg6);
>     +        }
>              print_syscall_ret(num, ret);
>          } else {
>              ret = do_syscall1(cpu_env, num, arg1, arg2, arg3, arg4,
>