Enhance error diagnostics when the first exec fails

When the first exec fails, strace used to print the trace of the child
process till its end, producing a lot of confusing output.
Enhance the diagnostics by hiding irrelevant parts of the trace.

* defs.h (TCB_CHECK_EXEC_SYSCALL): New macro.  Change values of TCB_*
macros listed after TCB_CHECK_EXEC_SYSCALL.
(check_exec_syscall): New macro.
* strace.c (dispatch_event) <TE_STOP_BEFORE_EXECVE>: Clear
TCB_CHECK_EXEC_SYSCALL flag.
* syscall.c (syscall_entering_trace): Do not clear TCB_HIDE_LOG when
TCB_CHECK_EXEC_SYSCALL is set, set TCB_CHECK_EXEC_SYSCALL along with
clearing TCB_HIDE_LOG.
(syscall_exiting_decode): Set TCB_HIDE_LOG if TCB_CHECK_EXEC_SYSCALL
is set.
* tests/first_exec_failure.test: New file.
* tests/Makefile.am (MISC_TESTS): Add first_exec_failure.test.

Closes: https://github.com/strace/strace/issues/88

diff --git a/defs.h b/defs.h
index b8d561aab61cccd54c6334321ec3c4db43b46c7f..9f1754c123f9ff143bbb699883e6129c6fc827c5 100644 (file)
--- a/defs.h
+++ b/defs.h
@@ -267,15 +267,16 @@ struct tcb {
 #define TCB_FILTERED   0x20    /* This system call has been filtered out */
 #define TCB_TAMPERED   0x40    /* A syscall has been tampered with */
 #define TCB_HIDE_LOG   0x80    /* We should hide everything (until execve) */
-#define TCB_SKIP_DETACH_ON_FIRST_EXEC  0x100   /* -b execve should skip detach on first execve */
-#define TCB_GRABBED    0x200   /* We grab the process and can catch it
+#define TCB_CHECK_EXEC_SYSCALL 0x100   /* Check whether this execve syscall succeeded */
+#define TCB_SKIP_DETACH_ON_FIRST_EXEC  0x200   /* -b execve should skip detach on first execve */
+#define TCB_GRABBED    0x400   /* We grab the process and can catch it
                                 * in the middle of a syscall */
-#define TCB_RECOVERING 0x400   /* We try to recover after detecting incorrect
+#define TCB_RECOVERING 0x800   /* We try to recover after detecting incorrect
                                 * syscall entering/exiting state */
-#define TCB_INJECT_DELAY_EXIT  0x800   /* Current syscall needs to be delayed
+#define TCB_INJECT_DELAY_EXIT  0x1000  /* Current syscall needs to be delayed
                                           on exit */
-#define TCB_DELAYED    0x1000  /* Current syscall has been delayed */
-#define TCB_TAMPERED_NO_FAIL 0x2000    /* We tamper tcb with syscall
+#define TCB_DELAYED    0x2000  /* Current syscall has been delayed */
+#define TCB_TAMPERED_NO_FAIL 0x4000    /* We tamper tcb with syscall
                                           that should not fail. */
 
 /* qualifier flags */
@@ -297,6 +298,7 @@ struct tcb {
 #define inject(tcp)    ((tcp)->qual_flg & QUAL_INJECT)
 #define filtered(tcp)  ((tcp)->flags & TCB_FILTERED)
 #define hide_log(tcp)  ((tcp)->flags & TCB_HIDE_LOG)
+#define check_exec_syscall(tcp)        ((tcp)->flags & TCB_CHECK_EXEC_SYSCALL)
 #define syscall_tampered(tcp)  ((tcp)->flags & TCB_TAMPERED)
 #define recovering(tcp)        ((tcp)->flags & TCB_RECOVERING)
 #define inject_delay_exit(tcp) ((tcp)->flags & TCB_INJECT_DELAY_EXIT)

diff --git a/strace.c b/strace.c
index 30dac0e93465780a8336dac063dde125d99b9c91..1710c371c5945febc8da5573d1efe8e83723a2f8 100644 (file)
--- a/strace.c
+++ b/strace.c
@@ -2528,6 +2528,8 @@ dispatch_event(const struct tcb_wait_data *wd)
                return true;
 
        case TE_STOP_BEFORE_EXECVE:
+               /* The syscall succeeded, clear the flag.  */
+               current_tcp->flags &= ~TCB_CHECK_EXEC_SYSCALL;
                /*
                 * Check that we are inside syscall now (next event after
                 * PTRACE_EVENT_EXEC should be for syscall exiting).  If it is

diff --git a/syscall.c b/syscall.c
index 04b9939728b19c1c95fc05e802ac01ba9eaff41b..2c80258dd5f17146ba5ed04c18c0507c8ce40f74 100644 (file)
--- a/syscall.c
+++ b/syscall.c
@@ -674,14 +674,15 @@ syscall_entering_trace(struct tcb *tcp, unsigned int *sig)
                                 * First exec* syscall makes the log visible.
                                 */
                                tcp->flags &= ~TCB_HIDE_LOG;
+                               /*
+                                * Check whether this exec* syscall succeeds.
+                                */
+                               tcp->flags |= TCB_CHECK_EXEC_SYSCALL;
                                break;
-                       default:
-                               tcp->flags |= TCB_FILTERED;
-                               return 0;
                }
        }
 
-       if (!traced(tcp) || (tracing_paths && !pathtrace_match(tcp))) {
+       if (hide_log(tcp) || !traced(tcp) || (tracing_paths && !pathtrace_match(tcp))) {
                tcp->flags |= TCB_FILTERED;
                return 0;
        }
@@ -740,6 +741,11 @@ syscall_exiting_decode(struct tcb *tcp, struct timespec *pts)
        if (filtered(tcp))
                return 0;
 
+       if (check_exec_syscall(tcp)) {
+               /* The check failed, hide the log.  */
+               tcp->flags |= TCB_HIDE_LOG;
+       }
+
 #if SUPPORTED_PERSONALITIES > 1
        update_personality(tcp, tcp->currpers);
 #endif

diff --git a/tests/Makefile.am b/tests/Makefile.am
index 5bb580a6509878799a10e70c647d9af5bef28a91..e77c6bee264b478b86d853b03bad190969950635 100644 (file)
--- a/tests/Makefile.am
+++ b/tests/Makefile.am
@@ -320,6 +320,7 @@ MISC_TESTS = \
        filter-unavailable.test \
        filtering_fd-syntax.test \
        filtering_syscall-syntax.test \
+       first_exec_failure.test \
        get_regs.test \
        inject-nf.test \
        interactive_block.test \

diff --git a/tests/first_exec_failure.test b/tests/first_exec_failure.test
new file mode 100755 (executable)
index 0000000..4e39f10
--- /dev/null
+++ b/tests/first_exec_failure.test
@@ -0,0 +1,50 @@
+#!/bin/sh
+#
+# Check error diagnostics when the first exec fails.
+#
+# Copyright (c) 2016-2018 The strace developers.
+# All rights reserved.
+#
+# Redistribution and use in source and binary forms, with or without
+# modification, are permitted provided that the following conditions
+# are met:
+# 1. Redistributions of source code must retain the above copyright
+#    notice, this list of conditions and the following disclaimer.
+# 2. Redistributions in binary form must reproduce the above copyright
+#    notice, this list of conditions and the following disclaimer in the
+#    documentation and/or other materials provided with the distribution.
+# 3. The name of the author may not be used to endorse or promote products
+#    derived from this software without specific prior written permission.
+#
+# THIS SOFTWARE IS PROVIDED BY THE AUTHOR ``AS IS'' AND ANY EXPRESS OR
+# IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO, THE IMPLIED WARRANTIES
+# OF MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE ARE DISCLAIMED.
+# IN NO EVENT SHALL THE AUTHOR BE LIABLE FOR ANY DIRECT, INDIRECT,
+# INCIDENTAL, SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT
+# NOT LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF USE,
+# DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND ON ANY
+# THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT
+# (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE OF
+# THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
+
+. "${srcdir=.}/init.sh"
+
+$STRACE / 2> "$LOG" &&
+       dump_log_and_fail_with \
+               "$STRACE / failed to handle the error properly"
+
+check_prog head
+check_prog tail
+
+head -n1 < "$LOG" > "$OUT"
+cat > "$EXP" <<__EOF__
+execve\("/", \["/"\], 0x[[:xdigit:]]+ /\* [[:digit:]]+ vars \*/\) += -1 EACCES \(Permission denied\)
+__EOF__
+match_grep "$OUT" "$EXP"
+
+tail -n +2 < "$LOG" > "$OUT"
+cat > "$EXP" <<__EOF__
+$STRACE_EXE: exec: Permission denied
++++ exited with 1 +++
+__EOF__
+match_diff "$OUT" "$EXP"