Introduce --strace flag for system call tracing

This is similar to the --ftrace (c function call trace) flag, except it's less noisy since it only logs system calls to stderr. Having this flag is valuable because (1) system call tracing tells us a lot about the behavior of complex programs and (2) it's usually very hard to get system call tracing on various operating systems, e.g. strace, ktrace, dtruss, truss, nttrace, etc. Especially on Apple platforms where even with the special boot trick, debuggers still aren't guaranteed to work. make -j8 o//examples o//examples/hello.com --strace This is enabled by default in MODE=, MODE=opt, and MODE=dbg. In MODE=dbg extra information will be printed. make -j8 MODE=dbg o/dbg/examples o/dbg/examples/hello.com --strace |& less This change also changes: - Rename IsText() → _istext() - Rename IsUtf8() → _isutf8() - Fix madvise() on Windows NT - Fix empty string case of inet_ntop() - vfork() wrapper now saves and restores errno - Update xsigaction() to yoink syscall support
jart · Mar 19, 2022 · 14e192e · 14e192e
1 parent c541225
commit 14e192e
Show file tree

Hide file tree

Showing 138 changed files with 1,507 additions and 619 deletions.
diff --git a/build/config.mk b/build/config.mk
@@ -5,6 +5,7 @@
 #
 #   - `make`
 #   - Backtraces
+#   - Syscall tracing
 #   - Function tracing
 #   - Reasonably small
 #   - Reasonably optimized
@@ -13,6 +14,7 @@ ifeq ($(MODE),)
 CONFIG_CCFLAGS +=		\
 	$(BACKTRACES)		\
 	$(FTRACE)		\
+	-DSYSDEBUG		\
 	-Og
 TARGET_ARCH ?=			\
 	-msse3
@@ -23,6 +25,8 @@ endif
 #   - `make MODE=opt`
 #   - Backtraces
 #   - More optimized
+#   - Syscall tracing
+#   - Function tracing
 #   - Reasonably small
 #   - No memory corruption detection
 #   - assert() / CHECK_xx() may leak code into binary for debuggability
@@ -35,6 +39,7 @@ CONFIG_CPPFLAGS +=		\
 CONFIG_CCFLAGS +=		\
 	$(BACKTRACES)		\
 	$(FTRACE)		\
+	-DSYSDEBUG		\
 	-O3
 TARGET_ARCH ?=			\
 	-march=native
@@ -122,6 +127,7 @@ CONFIG_CPPFLAGS +=		\
 CONFIG_CCFLAGS +=		\
 	$(BACKTRACES)		\
 	$(FTRACE)		\
+	-DSYSDEBUG		\
 	-O2			\
 	-fno-inline
 CONFIG_COPTS +=			\
@@ -287,7 +293,7 @@ endif
 # LLVM Mode
 ifeq ($(MODE), llvm)
 TARGET_ARCH ?= -msse3
-CONFIG_CCFLAGS += $(BACKTRACES) $(FTRACE) -O2
+CONFIG_CCFLAGS += $(BACKTRACES) $(FTRACE) -DSYSDEBUG -O2
 AS = clang
 CC = clang
 CXX = clang++

diff --git a/libc/calls/chdir.c b/libc/calls/chdir.c
@@ -17,6 +17,7 @@
 │ PERFORMANCE OF THIS SOFTWARE.                                                │
 ╚─────────────────────────────────────────────────────────────────────────────*/
 #include "libc/calls/internal.h"
+#include "libc/calls/strace.internal.h"
 #include "libc/dce.h"
 #include "libc/intrin/asan.internal.h"
 #include "libc/sysv/errfuns.h"
@@ -30,10 +31,14 @@
  * @see fchdir()
  */
 int chdir(const char *path) {
-  if (IsAsan() && !__asan_is_valid(path, 1)) return efault();
-  if (!IsWindows()) {
-    return sys_chdir(path);
+  int rc;
+  if (IsAsan() && !__asan_is_valid(path, 1)) {
+    rc = efault();
+  } else if (!IsWindows()) {
+    rc = sys_chdir(path);
   } else {
-    return sys_chdir_nt(path);
+    rc = sys_chdir_nt(path);
   }
+  STRACE("chdir(%#s) → %d% m", path, rc);
+  return rc;
 }
diff --git a/libc/calls/close.c b/libc/calls/close.c
@@ -19,7 +19,7 @@
 #include "libc/bits/weaken.h"
 #include "libc/calls/calls.h"
 #include "libc/calls/internal.h"
-#include "libc/calls/sysdebug.internal.h"
+#include "libc/calls/strace.internal.h"
 #include "libc/macros.internal.h"
 #include "libc/sock/internal.h"
 #include "libc/sysv/errfuns.h"
@@ -61,6 +61,6 @@ int close(int fd) {
     }
   }
   __releasefd(fd);
-  SYSDEBUG("close(%d) -> %d", fd, rc);
+  STRACE("%s(%d) → %d% m", "close", fd, rc);
   return rc;
 }
diff --git a/libc/calls/commandv.c b/libc/calls/commandv.c
@@ -19,7 +19,7 @@
 #include "libc/bits/bits.h"
 #include "libc/bits/safemacros.internal.h"
 #include "libc/calls/calls.h"
-#include "libc/calls/sysdebug.internal.h"
+#include "libc/calls/strace.internal.h"
 #include "libc/dce.h"
 #include "libc/errno.h"
 #include "libc/log/libfatal.internal.h"
@@ -159,6 +159,6 @@ noasan char *commandv(const char *name, char pathbuf[hasatleast PATH_MAX]) {
       errno = f;
     }
   }
-  SYSDEBUG("commandv(%#s, %p) → %#s% m", name, pathbuf, res);
+  STRACE("commandv(%#s, %p) → %#s% m", name, pathbuf, res);
   return res;
 }
diff --git a/libc/runtime/describeframe.c → libc/calls/describeframe.c b/libc/runtime/describeframe.c → libc/calls/describeframe.c
@@ -16,7 +16,7 @@
 │ TORTIOUS ACTION, ARISING OUT OF OR IN CONNECTION WITH THE USE OR             │
 │ PERFORMANCE OF THIS SOFTWARE.                                                │
 ╚─────────────────────────────────────────────────────────────────────────────*/
-#include "libc/log/libfatal.internal.h"
+#include "libc/intrin/kprintf.h"
 #include "libc/macros.internal.h"
 #include "libc/runtime/memtrack.internal.h"
 #include "libc/runtime/runtime.h"
@@ -28,21 +28,19 @@
 noasan const char *DescribeFrame(int x) {
   /* asan runtime depends on this function */
   char *p;
-  static char buf[128];
+  static char buf[32];
   if (IsShadowFrame(x)) {
-    p = buf;
-    p = __stpcpy(p, " shadow of ");
-    p = __fixcpy(p, UNSHADOW(ADDR(x)), 48);
+    ksnprintf(buf, sizeof(buf), " /*shadow:%.12p*/", UNSHADOW(ADDR(x)));
     return buf;
-    return " shadow ";
+    return " /*shadow*/ ";
   } else if (IsAutoFrame(x)) {
-    return " automap";
+    return " /*automap*/";
   } else if (IsFixedFrame(x)) {
-    return " fixed  ";
+    return " /*fixed*/  ";
   } else if (IsArenaFrame(x)) {
-    return " arena  ";
+    return " /*arena*/  ";
   } else if (IsStaticStackFrame(x)) {
-    return " stack  ";
+    return " /*stack*/  ";
   } else {
     return "";
   }

diff --git a/libc/runtime/describemapping.c → libc/calls/describemapping.c b/libc/runtime/describemapping.c → libc/calls/describemapping.c
@@ -20,19 +20,26 @@
 #include "libc/sysv/consts/map.h"
 #include "libc/sysv/consts/prot.h"
 
+static noasan char DescribeMapType(int flags) {
+  switch (flags & MAP_TYPE) {
+    case MAP_FILE:
+      return 'f';
+    case MAP_PRIVATE:
+      return 'p';
+    case MAP_SHARED:
+      return 's';
+    default:
+      return '?';
+  }
+}
+
 noasan char *DescribeMapping(int prot, int flags, char p[hasatleast 8]) {
   /* asan runtime depends on this function */
   p[0] = (prot & PROT_READ) ? 'r' : '-';
   p[1] = (prot & PROT_WRITE) ? 'w' : '-';
   p[2] = (prot & PROT_EXEC) ? 'x' : '-';
-  if (flags & MAP_PRIVATE) {
-    p[3] = 'p';
-  } else if (flags & MAP_SHARED) {
-    p[3] = 's';
-  } else {
-    p[3] = '?';
-  }
-  p[4] = (flags & MAP_ANONYMOUS) ? 'a' : 'f';
+  p[3] = DescribeMapType(flags);
+  p[4] = (flags & MAP_ANONYMOUS) ? 'a' : '-';
   p[5] = (flags & MAP_GROWSDOWN) ? 'S' : '-';
   p[6] = (flags & MAP_FIXED) ? 'F' : '-';
   p[7] = 0;

diff --git a/libc/runtime/directmap-metal.c → libc/calls/directmap-metal.c b/libc/runtime/directmap-metal.c → libc/calls/directmap-metal.c
diff --git a/libc/runtime/directmap-nt.c → libc/calls/directmap-nt.c b/libc/runtime/directmap-nt.c → libc/calls/directmap-nt.c
@@ -18,7 +18,7 @@
 ╚─────────────────────────────────────────────────────────────────────────────*/
 #include "libc/calls/calls.h"
 #include "libc/calls/internal.h"
-#include "libc/calls/sysdebug.internal.h"
+#include "libc/calls/strace.internal.h"
 #include "libc/macros.internal.h"
 #include "libc/nt/enum/filemapflags.h"
 #include "libc/nt/enum/pageflags.h"
@@ -46,14 +46,14 @@ textwindows noasan struct DirectMap sys_mmap_nt(void *addr, size_t size,
     dm.maphandle = CreateFileMappingNuma(-1, &kNtIsInheritable,
                                          kNtPageExecuteReadwrite, upsize >> 32,
                                          upsize, NULL, kNtNumaNoPreferredNode);
-    SYSDEBUG("CreateFileMappingNuma(-1, kNtPageExecuteReadwrite, 0x%x/0x%x) -> "
-             "0x%x",
-             upsize, size, dm.maphandle);
+    STRACE(
+        "CreateFileMappingNuma(-1, kNtPageExecuteReadwrite, %'zu/%'zu) -> %p",
+        upsize, size, dm.maphandle);
     if (dm.maphandle) {
       dm.addr =
           MapViewOfFileExNuma(dm.maphandle, kNtFileMapWrite | kNtFileMapExecute,
                               0, 0, upsize, addr, kNtNumaNoPreferredNode);
-      SYSDEBUG("MapViewOfFileExNuma(WX, 0x%x) -> addr:0x%x", addr, dm.addr);
+      STRACE("MapViewOfFileExNuma(WX, %p) → addr:%p", addr, dm.addr);
       if (dm.addr) {
         for (i = 0; i < size; i += got) {
           got = 0;
@@ -78,20 +78,16 @@ textwindows noasan struct DirectMap sys_mmap_nt(void *addr, size_t size,
         (prot & PROT_WRITE) ? kNtPageExecuteReadwrite : kNtPageExecuteRead,
         handle != -1 ? 0 : size >> 32, handle != -1 ? 0 : size, NULL,
         kNtNumaNoPreferredNode);
-    SYSDEBUG("CreateFileMappingNuma(fhand:%d, prot:%s, size:0x%x) -> "
-             "handle:0x%x",
-             handle, (prot & PROT_WRITE) ? "XRW" : "XR",
-             handle != -1 ? 0 : size);
+    STRACE("CreateFileMappingNuma(fhand:%ld, prot:%s, size:%'zu) → %p", handle,
+           (prot & PROT_WRITE) ? "XRW" : "XR", handle != -1 ? 0 : size);
     if (dm.maphandle) {
       dm.addr = MapViewOfFileExNuma(
           dm.maphandle,
           (prot & PROT_WRITE) ? kNtFileMapWrite | kNtFileMapExecute
                               : kNtFileMapRead | kNtFileMapExecute,
           off >> 32, off, size, addr, kNtNumaNoPreferredNode);
-      SYSDEBUG(
-          "MapViewOfFileExNuma(prot:%s, off:0x%x, size:0x%x, addr:0x%x) -> "
-          "addr:0x%x",
-          (prot & PROT_WRITE) ? "WX" : "RX", off, size, addr, dm.addr);
+      STRACE("MapViewOfFileExNuma(prot:%s, off:%'ld, size:%'zu, addr:%p) → %p",
+             (prot & PROT_WRITE) ? "WX" : "RX", off, size, addr, dm.addr);
       if (dm.addr) {
         return dm;
       } else {

diff --git a/libc/runtime/directmap.c → libc/calls/directmap.c b/libc/runtime/directmap.c → libc/calls/directmap.c
@@ -17,7 +17,7 @@
 │ PERFORMANCE OF THIS SOFTWARE.                                                │
 ╚─────────────────────────────────────────────────────────────────────────────*/
 #include "libc/calls/internal.h"
-#include "libc/calls/sysdebug.internal.h"
+#include "libc/calls/strace.internal.h"
 #include "libc/errno.h"
 #include "libc/nt/runtime.h"
 #include "libc/runtime/directmap.internal.h"
@@ -36,20 +36,18 @@ noasan struct DirectMap sys_mmap(void *addr, size_t size, int prot, int flags,
                                  int fd, int64_t off) {
   /* asan runtime depends on this function */
   char mode[8];
-  struct DirectMap dm;
+  struct DirectMap d;
   if (!IsWindows() && !IsMetal()) {
-    dm.addr = __sys_mmap(addr, size, prot, flags, fd, off, off);
-    SYSDEBUG("sys_mmap(0x%p%s, 0x%x, %s, %d, %d) -> 0x%p %s", addr,
-             DescribeFrame((intptr_t)addr >> 16), size,
-             DescribeMapping(prot, flags, mode), (long)fd, off, dm.addr,
-             dm.addr != MAP_FAILED ? "" : strerror(errno));
-    dm.maphandle = kNtInvalidHandleValue;
-    return dm;
+    d.addr = __sys_mmap(addr, size, prot, flags, fd, off, off);
+    d.maphandle = kNtInvalidHandleValue;
   } else if (IsMetal()) {
-    return sys_mmap_metal(addr, size, prot, flags, fd, off);
+    d = sys_mmap_metal(addr, size, prot, flags, fd, off);
   } else {
-    return sys_mmap_nt(addr, size, prot, flags,
-                       fd != -1 ? g_fds.p[fd].handle : kNtInvalidHandleValue,
-                       off);
+    d = sys_mmap_nt(addr, size, prot, flags,
+                    fd != -1 ? g_fds.p[fd].handle : kNtInvalidHandleValue, off);
   }
+  STRACE("sys_mmap(%.12p%s, %'zu, %s, %d, %'ld) → {%.12p, %p}% m", addr,
+         DescribeFrame((intptr_t)addr >> 16), size,
+         DescribeMapping(prot, flags, mode), fd, off, d.addr, d.maphandle);
+  return d;
 }
diff --git a/libc/calls/dup.c b/libc/calls/dup.c
@@ -18,7 +18,7 @@
 ╚─────────────────────────────────────────────────────────────────────────────*/
 #include "libc/calls/calls.h"
 #include "libc/calls/internal.h"
-#include "libc/calls/sysdebug.internal.h"
+#include "libc/calls/strace.internal.h"
 #include "libc/dce.h"
 
 /**
@@ -36,6 +36,6 @@ int dup(int fd) {
   } else {
     fd2 = sys_dup_nt(fd, -1, 0);
   }
-  SYSDEBUG("dup(%d) -> %d", fd, fd2);
+  STRACE("%s(%d) → %d% m", "dup", fd, fd2);
   return fd2;
 }
diff --git a/libc/calls/dup2.c b/libc/calls/dup2.c
@@ -18,7 +18,7 @@
 ╚─────────────────────────────────────────────────────────────────────────────*/
 #include "libc/calls/calls.h"
 #include "libc/calls/internal.h"
-#include "libc/calls/sysdebug.internal.h"
+#include "libc/calls/strace.internal.h"
 #include "libc/dce.h"
 
 /**
@@ -32,11 +32,14 @@
  * @vforksafe
  */
 int dup2(int oldfd, int newfd) {
-  SYSDEBUG("dup2(%d, %d)", oldfd, newfd);
-  if (oldfd == newfd) return newfd;
-  if (!IsWindows()) {
-    return sys_dup3(oldfd, newfd, 0);
+  int rc;
+  if (oldfd == newfd) {
+    rc = newfd;
+  } else if (!IsWindows()) {
+    rc = sys_dup3(oldfd, newfd, 0);
   } else {
-    return sys_dup_nt(oldfd, newfd, 0);
+    rc = sys_dup_nt(oldfd, newfd, 0);
   }
+  STRACE("dup2(%d, %d) → %d% m", oldfd, newfd, rc);
+  return rc;
 }
diff --git a/libc/calls/dup3.c b/libc/calls/dup3.c
@@ -18,7 +18,7 @@
 ╚─────────────────────────────────────────────────────────────────────────────*/
 #include "libc/calls/calls.h"
 #include "libc/calls/internal.h"
-#include "libc/calls/sysdebug.internal.h"
+#include "libc/calls/strace.internal.h"
 #include "libc/dce.h"
 #include "libc/sysv/errfuns.h"
 
@@ -36,10 +36,12 @@
  * @see dup(), dup2()
  */
 int dup3(int oldfd, int newfd, int flags) {
-  SYSDEBUG("dup3(%d, %d, %d)", oldfd, newfd, flags);
+  int rc;
   if (!IsWindows()) {
-    return sys_dup3(oldfd, newfd, flags);
+    rc = sys_dup3(oldfd, newfd, flags);
   } else {
-    return sys_dup_nt(oldfd, newfd, flags);
+    rc = sys_dup_nt(oldfd, newfd, flags);
   }
+  STRACE("dup3(%d, %d, %d) → %d% m", oldfd, newfd, flags, rc);
+  return rc;
 }