FW/child_debug: use std::string more

framework/logging.cpp

@@ -774,6 +774,14 @@ static void log_message_preformatted(int thread_num, std::string_view msg)
     if (msg[0] == 'E')
         logging_mark_thread_failed(thread_num);
 
+    return log_message_preformatted(thread_num, level, msg);
+}
+
+void log_message_preformatted(int thread_num, int level, std::string_view msg)
+{
+    if (current_output_format() == SandstoneApplication::OutputFormat::no_output)
+        return;
+
     std::atomic<int> &messages_logged = sApp->thread_data(thread_num)->messages_logged;
     if (messages_logged.load(std::memory_order_relaxed) >= sApp->shmem->max_messages_per_thread)
         return;
@@ -1131,15 +1139,6 @@ void logging_finish()
 {
 }
 
-LoggingStream logging_user_messages_stream(int thread_num, int level)
-{
-    LoggingStream stream(sApp->thread_data(thread_num)->log_fd);
-    sApp->thread_data(thread_num)->messages_logged.fetch_add(1, std::memory_order_relaxed);
-    uint8_t code = message_code(UserMessages, level);
-    stream.write(code);
-    return stream;
-}
-
 static inline void assert_log_message(const char *fmt)
 {
     assert(fmt);

framework/sandstone_p.h

@@ -281,42 +281,6 @@ struct SandstoneBackgroundScan
 #endif
 };
 
-class LoggingStream
-{
-public:
-    LoggingStream(int fd = -1) : fd(fd) {}
-    LoggingStream(const LoggingStream &) = delete;
-    LoggingStream &operator=(const LoggingStream &) = delete;
-    constexpr LoggingStream(LoggingStream &&other) : fd(other.fd)
-    {
-        other.fd = -1;
-    }
-    constexpr LoggingStream &operator=(LoggingStream &&other)
-    {
-        std::swap(fd, other.fd);
-        return *this;
-    }
-
-    ~LoggingStream()
-    {
-        if (fd != -1)
-            write('\0');
-    }
-    operator int() const
-    {
-        return fd;
-    }
-
-    template <typename... Args> ssize_t write(Args &&... args)
-    {
-        return writevec(fd, std::forward<Args>(args)...);
-    }
-
-private:
-    int fd;
-    friend LoggingStream logging_user_messages_stream(int thread_num, int level);
-};
-
 struct SandstoneApplication : public InterruptMonitor, public test_the_test_data<SandstoneConfig::Debug>
 {
     enum class OutputFormat : int8_t {
@@ -654,6 +618,7 @@ static_assert(std::is_trivially_copyable_v<SandstoneApplication::SharedMemory>);
 static_assert(std::is_trivially_destructible_v<SandstoneApplication::SharedMemory>);
 
 /* logging.cpp */
+void log_message_preformatted(int thread_num, int level, std::string_view msg);
 int logging_stdout_fd(void);
 void logging_init_global(void);
 void logging_init_global_child();
@@ -673,7 +638,6 @@ void logging_flush(void);
 void logging_init(const struct test *test);
 void logging_init_child_preexec();
 void logging_finish();
-LoggingStream logging_user_messages_stream(int thread_num, int level);
 TestResult logging_print_results(std::span<const ChildExitStatus> status, int *tc, const struct test *test);
 
 /* random.cpp */

framework/sysdeps/unix/child_debug.cpp

@@ -29,8 +29,9 @@
 #include <poll.h>
 #include <signal.h>
 #include <stdio.h>
-#include <sys/socket.h>
 #include <sys/resource.h>
+#include <sys/socket.h>
+#include <sys/stat.h>
 #include <sys/uio.h>
 #include <sys/wait.h>
 #include <ucontext.h>
@@ -450,12 +451,44 @@ static int run_process(int stdout_fd, const char *args[])
     return -1;
 }
 
-static void communicate_gdb_backtrace(int log, int in, int out, uintptr_t handle, int cpu)
+static std::string run_process(const char *args[])
+{
+    // Not using a pipe here because we don't know how much the child process
+    // will write, and run_process() above waits for it to end.
+    int stdout_fd = open_memfd(MemfdCloseOnExec);
+    int ret = run_process(stdout_fd, args);
+
+    std::string log;
+    if (ret < 0)
+        return log;
+
+    // read the entire output
+    struct stat st;
+    if (fstat(stdout_fd, &st) < 0 || st.st_size == 0)
+        return log;
+
+    ssize_t total_read = 0;
+    log.resize(st.st_size);
+    while (total_read < log.size()) {
+        EINTR_LOOP(ret, read(stdout_fd, log.data() + total_read, log.size() - total_read));
+        if (ret <= 0)
+            break;
+    }
+    log.resize(total_read);
+    return log;
+}
+
+static auto communicate_gdb_backtrace(int in, int out, uintptr_t handle)
 {
     using namespace std::chrono;
     using namespace std::chrono_literals;
     constexpr auto GdbCommunicationTimeout = SandstoneConfig::Debug ? 1h : 30s;
 
+    struct R {
+        std::string thread_info;    // output of "frame" and "x/i $pc" (if Python is supported)
+        std::string backtrace;      // output of "thread apply all bt full"
+    } result;
+
     ssize_t ret;
     char buf[4096];
     auto deadline = coarse_steady_clock::now() + GdbCommunicationTimeout;
@@ -482,11 +515,11 @@ static void communicate_gdb_backtrace(int log, int in, int out, uintptr_t handle
         static const char needle[] = "(gdb) ";
         ret = wait_for_more();
         if (ret <= 0)
-            return;
+            return result;
 
         ret = read(in, buf, sizeof(buf) - 1);
         if (ret <= 0)
-            return;
+            return result;
         buf[ret] = '\0';
 
         // ### the needle may be split between buffers!
@@ -500,31 +533,31 @@ static void communicate_gdb_backtrace(int log, int in, int out, uintptr_t handle
     // send a python command setting the search handle
     ret = dprintf(out, gdb_preamble_commands, handle);
     if (ret <= 0)
-        return;
+        return result;
     ret = wait_for_more();
     if (ret <= 0)
-        return;
+        return result;
 
     ret = read(in, buf, sizeof(buf) - 1);
     if (ret <= 0)
-        return;
+        return result;
     buf[ret] = '\0';
 
     bool send_python = handle && (strcmp(buf, "ok\n") == 0);
     if (send_python) {
         ret = write(out, gdb_python_commands, strlen(gdb_python_commands));
         if (ret != ssize_t(strlen(gdb_python_commands)))
-            return;
+            return result;
 
         // skip the >>>>> caused by the multi-line python command
         for (;;) {
             ret = wait_for_more();
             if (ret <= 0)
-                return;
+                return result;
 
             ret = read(in, buf, sizeof(buf) - 1);
             if (ret <= 0)
-                return;
+                return result;
             buf[ret] = '\0';
 
             char *msg = buf;
@@ -541,53 +574,43 @@ static void communicate_gdb_backtrace(int log, int in, int out, uintptr_t handle
         for (;;) {
             static const char needle[] = "..Done..\n";
             if (ret >= strlen(needle) && strcmp(buf + ret - strlen(needle), needle) == 0) {
-                buf[ret - strlen(needle)] = '\0';
+                result.thread_info = std::string_view(buf, ret - strlen(needle));
                 break;
             }
 
             ssize_t ret2 = wait_for_more();
             if (ret2 <= 0)
-                return;
+                return result;
 
             ret2 = read(in, buf + ret, sizeof(buf) - ret);
             if (ret2 <= 0)
-                return;
+                return result;
             buf[ret + ret2] = '\0';
             ret += ret2;
         }
-
-        if (cpu != -1) {
-            // log to the specific CPU
-            log_message(cpu, SANDSTONE_LOG_WARNING "%s", buf);
-        } else {
-            IGNORE_RETVAL(write(log, buf, strlen(buf)));
-        }
     }
 
     // now get the actual backtrace (includes "quit")
     ret = write(out, gdb_bt_commands, strlen(gdb_bt_commands));
     if (ret != ssize_t(strlen(gdb_bt_commands)))
-        return;
+        return result;
 
     // splice backtrace from gdb to our log file
     for (;;) {
         ret = wait_for_more();
         if (ret <= 0)
-            return;
+            return result;
 
-#if defined(SPLICE_F_NONBLOCK)
-        ret = splice(in, nullptr, log, nullptr, std::numeric_limits<int>::max(),
-                     SPLICE_F_NONBLOCK);
-#else
         ret = read(in, buf, sizeof(buf));
-        if (ret > 0)
-            IGNORE_RETVAL(write(log, buf, ret));
-#endif
         if (ret == -1 && (errno == EINTR || errno == EWOULDBLOCK))
             continue;
         if (ret <= 0)
-            return;
+            return result;
+
+        result.backtrace += std::string_view(buf, ret);
     }
+
+    return result;
 }
 
 static void generate_backtrace(const char *pidstr, uintptr_t handle = 0, int cpu = -1)
@@ -634,10 +657,11 @@ static void generate_backtrace(const char *pidstr, uintptr_t handle = 0, int cpu
         sigaction(SIGPIPE, &ign_sigpipe, &old_sigpipe);
     }
 
-    {
-        LoggingStream stream = logging_user_messages_stream(-1, LOG_LEVEL_VERBOSE(2));
-        communicate_gdb_backtrace(stream, gdb_out.in(), gdb_in.out(), handle, cpu);
-    }
+    auto r = communicate_gdb_backtrace(gdb_out.in(), gdb_in.out(), handle);
+    if (r.thread_info.size())
+        log_message(cpu, SANDSTONE_LOG_WARNING "%s", r.thread_info.c_str());
+    if (r.backtrace.size())
+        log_message_preformatted(-1, LOG_LEVEL_VERBOSE(2), r.backtrace);
 
     // close the pipes and wait for gdb to exit
     gdb_in.close_output();
@@ -874,20 +898,17 @@ static void print_crash_info(const char *pidstr, CrashContext &ctx)
 
     // now include the register state
     if (handle && ctx.contents & CrashContext::MachineContext) {
-        char *buffer = nullptr;
-        size_t buflen = 0;
-        FILE *log = open_memstream(&buffer, &buflen);
-        fprintf(log, "Registers:\n");
+        std::string log;
 
 #ifdef __x86_64__
         dump_gprs(log, &ctx.mc);
         dump_xsave(log, ctx.xsave_buffer.data(), ctx.xsave_buffer.size(), -1);
 #endif
 
-        fclose(log);
-        logging_user_messages_stream(cpu, LOG_LEVEL_VERBOSE(2))
-                .write(std::string_view(buffer, buflen));
-        free(buffer);
+        if (log.size()) {
+            log.insert(0, "Registers:\n");
+            log_message_preformatted(cpu, LOG_LEVEL_VERBOSE(2), log);
+        }
     }
 }
 
@@ -1059,8 +1080,7 @@ void debug_hung_child(pid_t child)
     if (on_hang_action == print_ps_on_hang) {
         const char *ps_args[] =
             { "ps", "Hww", "-opid,tid,psr,vsz,rss,wchan,%cpu,stat,time,comm,args", buf, nullptr };
-        LoggingStream stream = logging_user_messages_stream(-1, LOG_LEVEL_VERBOSE(2));
-        run_process(stream, ps_args);
+        log_message_preformatted(-1, LOG_LEVEL_VERBOSE(2), run_process(ps_args));
     } else if (SandstoneConfig::ChildBacktrace) {
         if (on_hang_action == attach_gdb_on_hang) {
             attach_gdb(buf);

framework/sysdeps/windows/child_debug.cpp

@@ -140,7 +140,7 @@ static LONG WINAPI handler(EXCEPTION_POINTERS *info)
 }
 
 #ifdef __x86_64__
-static void print_non_gprs(FILE *log, PCONTEXT ctx)
+static void print_non_gprs(std::string &log, PCONTEXT ctx)
 {
     // Windows doesn't store the XSAVE state in a contiguous block, so
     // we have to put it back together.
@@ -283,31 +283,16 @@ void debug_crashed_child()
             cpu = ctx->header.thread_num = -1;
         print_exception_info(ctx);
 
-        // no open_memstream() or fcookieopen() in MSVCRT or UCRT, so we use
-        // a real file
-        if (!log)
-            log.f = tmpfile();
-        if (!log)
-            continue;
-
-        fseek(log, 0, SEEK_SET);
-        fprintf(log, "Registers:\n");
+        std::string log;
 #ifdef __x86_64__
         dump_gprs(log, &ctx->fixedContext);
         print_non_gprs(log, &ctx->fixedContext);
 #endif
 
-        long size = ftell(log);
-        if (size < 0)
-            continue;
-        if (buf.size() < size_t(size))
-            buf.resize(size);
-
-        fseek(log, 0, SEEK_SET);
-        size = fread(buf.data(), 1, size, log);
-
-        logging_user_messages_stream(cpu, LOG_LEVEL_VERBOSE(2))
-                .write(std::string_view(buf.data(), size));
+        if (log.size()) {
+            log.insert(0, "Registers:\n");
+            log_message_preformatted(cpu, LOG_LEVEL_VERBOSE(2), log);
+        }
     }
 
     // got here on failure