From 9e2b48d7131ee7114bd650f6b0b1d5c913184325 Mon Sep 17 00:00:00 2001 From: Jake Hillion Date: Tue, 21 Nov 2023 02:50:31 -0800 Subject: [PATCH] jitlog: use a memfd and glog Summary: Changes jitlog to use a memfd, an anonymous in memory file descriptor, rather than a file on disk. Also clean up this fd at the end of an OID run rather than leaving it in the hope it's valid next time. A previous attempt to land this used a `char*` from the OID process space in the remote target syscall. Somehow this works with our integration test target, but not globally. Changed to use the previous behaviour of putting the syscall arg in the empty text segment. In doing this I noticed that the text segment wouldn't be initialised at this point on a fresh process, so we were copying into effectively an uninitialised address. Move the jit log fd setup to after the segment setup accordingly. Test plan: - CI - Tested on an integration test target as before. Works. - Created a new target that definitely doesn't have this string in (simple for loop). Failed before, works now. Example: ```sh $ OID_TEST_ARGS='-fjit-logging' stest OidIntegration.simple_struct ... I1121 02:57:36.136890 500897 OIDebugger.cpp:269] Outputting JIT logs: I1121 02:57:36.136896 500897 OIDebugger.cpp:272] JITLOG: SimpleStruct @00007ffc639be180 I1121 02:57:36.136899 500897 OIDebugger.cpp:272] JITLOG: a @00007ffc639be180 I1121 02:57:36.136901 500897 OIDebugger.cpp:272] JITLOG: obj @00007ffc639be180 I1121 02:57:36.136904 500897 OIDebugger.cpp:272] JITLOG: b @00007ffc639be184 I1121 02:57:36.136905 500897 OIDebugger.cpp:272] JITLOG: obj @00007ffc639be184 I1121 02:57:36.136907 500897 OIDebugger.cpp:272] JITLOG: c @00007ffc639be188 I1121 02:57:36.136909 500897 OIDebugger.cpp:272] JITLOG: obj @00007ffc639be188 I1121 02:57:36.136911 500897 OIDebugger.cpp:278] Finished outputting JIT logs. ... ``` --- oi/OIDebugger.cpp | 157 +++++++++++++++++++++++++++------------------- oi/OIDebugger.h | 6 +- oi/Syscall.h | 2 + 3 files changed, 99 insertions(+), 66 deletions(-) diff --git a/oi/OIDebugger.cpp b/oi/OIDebugger.cpp index 07faec6..64dbdf8 100644 --- a/oi/OIDebugger.cpp +++ b/oi/OIDebugger.cpp @@ -29,6 +29,7 @@ #include #include #include +#include #include #include #include @@ -195,57 +196,92 @@ bool OIDebugger::singleStepFunc(pid_t pid, uint64_t real_end) { } bool OIDebugger::setupLogFile(void) { - // 1. Copy the log file path in out text segment - // 2. Run the syscall - // 3. Store the resulting fd in the segmentConfigFile - if (!segConfig.existingConfig) { - auto logFilePath = - fs::path("/tmp") / ("oid-" + std::to_string(traceePid) + ".jit.log"); + // 1. Copy the anonymous file name into our text segment. + // 2. Open an anonymous memfd in the target with `memfd_create`. + // 3. Duplicate that fd to the debugger using `pidfd_getfd`. + // 4. Store the resulting fds in OIDebugger. + bool ret = true; - auto logFilePathLen = strlen(logFilePath.c_str()) + 1; - if (logFilePathLen > textSegSize) { - LOG(ERROR) << "The Log File's path " << logFilePath << " (" - << logFilePathLen << ") is too long for the text segment (" - << textSegSize << ")"; - return false; - } + static const std::string kAnonFileName{"jit.log"}; - /* - * Using the text segment to store the path in the remote process' memory. - * The memory will be re-used anyway and the path will get overwritten. - */ - if (!writeTargetMemory((void*)logFilePath.c_str(), - (void*)segConfig.textSegBase, - logFilePathLen)) { - LOG(ERROR) << "Failed to write Log File's path into target process"; - return false; - } - - /* - * Execute the `open(2)` syscall on the remote process. - * We use the O_SYNC flags to ensure each write we do make it on the disk. - * Another option would have been O_DSYNC, but since the logs get always - * appended to the end of the file, the file size always changes and - * we have to update the metadata everytime anyways. - * So O_SYNC won't incure a performance penalty, compared to O_DSYNC, - * and ensure we can use the metadata for future automation, etc. - */ - auto fd = remoteSyscall(segConfig.textSegBase, // path - O_CREAT | O_APPEND | O_WRONLY, // flags - S_IRUSR | S_IWUSR | S_IRGRP); // mode - if (!fd.has_value()) { - LOG(ERROR) << "Failed to open Log File " << logFilePath; - return false; - } - - segConfig.logFile = *fd; + // Copy the file name into the text segment so it can be referenced by the + // remote syscall. This will be overwritten later during relocation. + if (!writeTargetMemory((void*)(kAnonFileName.c_str()), + reinterpret_cast(segConfig.textSegBase), + kAnonFileName.length() + 1)) { + LOG(ERROR) << "Failed to write log file's name into target process"; + return false; } - return true; + auto traceeFd = remoteSyscall(segConfig.textSegBase, 0); + if (!traceeFd.has_value()) { + LOG(ERROR) << "Failed to create memory log file"; + return false; + } + logFds.traceeFd = *traceeFd; + + auto traceePidFd = syscall(SYS_pidfd_open, traceePid, 0); + if (traceePidFd == -1) { + PLOG(ERROR) << "Failed to open child pidfd"; + return false; + } + auto debuggerFd = syscall(SYS_pidfd_getfd, traceePidFd, *traceeFd, 0); + if (close(static_cast(traceePidFd)) != 0) { + PLOG(ERROR) << "Failed to close pidfd"; + ret = false; + } + if (debuggerFd == -1) { + PLOG(ERROR) << "Failed to duplicate child memfd to debugger"; + return false; + } + + logFds.debuggerFd = static_cast(debuggerFd); + return ret; } bool OIDebugger::cleanupLogFile(void) { - return remoteSyscall(segConfig.logFile).has_value(); + bool ret = true; + if (logFds.traceeFd == -1) + return ret; + + if (!remoteSyscall(logFds.traceeFd).has_value()) { + LOG(ERROR) << "Remote close failed"; + ret = false; + } + + if (logFds.debuggerFd == -1) + return ret; + + FILE* logs = fdopen(logFds.debuggerFd, "r"); + if (logs == NULL) { + PLOG(ERROR) << "Failed to fdopen jitlog"; + return false; + } + if (fseek(logs, 0, SEEK_SET) != 0) { + PLOG(ERROR) << "Failed to fseek jitlog"; + return false; + } + + char* line = nullptr; + size_t read = 0; + VLOG(1) << "Outputting JIT logs:"; + errno = 0; + while ((read = getline(&line, &read, logs)) != (size_t)-1) { + VLOG(1) << "JITLOG: " << line; + } + if (errno) { + PLOG(ERROR) << "getline"; + return false; + } + VLOG(1) << "Finished outputting JIT logs."; + + free(line); + if (fclose(logs) == -1) { + PLOG(ERROR) << "fclose"; + return false; + } + + return ret; } /* Set up traced process results and text segments */ @@ -260,11 +296,6 @@ bool OIDebugger::segmentInit(void) { LOG(ERROR) << "setUpSegment failed!!!"; return false; } - - if (!setupLogFile()) { - LOG(ERROR) << "setUpLogFile failed!!!"; - return false; - } } else { if (!unmapSegment(SegType::data)) { LOG(ERROR) << "Failed to unmmap data segment"; @@ -295,6 +326,13 @@ bool OIDebugger::segmentInit(void) { auto now = high_resolution_clock::now().time_since_epoch(); segConfig.cookie = duration_cast>(now).count(); + if (generatorConfig.features[Feature::JitLogging]) { + if (!setupLogFile()) { + LOG(ERROR) << "setUpLogFile failed!!!"; + return false; + } + } + return true; } @@ -345,8 +383,7 @@ void OIDebugger::createSegmentConfigFile(void) { << " dataSegBase: " << segConfig.dataSegBase << " dataSegSize: " << segConfig.dataSegSize << " replayInstBase: " << segConfig.replayInstBase - << " cookie: " << segConfig.cookie - << " logFile: " << segConfig.logFile; + << " cookie: " << segConfig.cookie; assert(segConfig.existingConfig); } @@ -1767,11 +1804,6 @@ bool OIDebugger::unmapSegments(bool deleteSegConfFile) { ret = false; } - if (ret && !cleanupLogFile()) { - LOG(ERROR) << "Problem closing target process log file"; - ret = false; - } - deleteSegmentConfig(deleteSegConfFile); return ret; @@ -1830,13 +1862,6 @@ bool OIDebugger::removeTraps(pid_t pid) { it = activeTraps.erase(it); } - if (generatorConfig.features[Feature::JitLogging]) { - /* Flush the JIT log, so it's always written on disk at least once */ - if (!remoteSyscall(segConfig.logFile).has_value()) { - LOG(ERROR) << "Failed to flush the JIT Log"; - } - } - /* Resume the main thread now, so it doesn't have to wait on restoreState */ if (!contTargetThread(targetPid)) { return false; @@ -2341,7 +2366,7 @@ bool OIDebugger::compileCode() { } int logFile = - generatorConfig.features[Feature::JitLogging] ? segConfig.logFile : 0; + generatorConfig.features[Feature::JitLogging] ? logFds.traceeFd : 0; if (!writeTargetMemory( &logFile, (void*)syntheticSymbols["logFile"], sizeof(logFile))) { LOG(ERROR) << "Failed to write logFile in probe's cookieValue"; @@ -2411,7 +2436,6 @@ void OIDebugger::restoreState(void) { VLOG(1) << "Couldn't interrupt target pid " << p << " (Reason: " << strerror(errno) << ")"; } - VLOG(1) << "Waiting to stop PID : " << p; if (waitpid(p, 0, WSTOPPED) != p) { @@ -2558,6 +2582,9 @@ void OIDebugger::restoreState(void) { } } + if (!cleanupLogFile()) + LOG(ERROR) << "failed to cleanup log file!"; + if (ptrace(PTRACE_DETACH, p, 0L, 0L) < 0) { LOG(ERROR) << "restoreState Couldn't detach target pid " << p << " (Reason: " << strerror(errno) << ")"; diff --git a/oi/OIDebugger.h b/oi/OIDebugger.h index 3997616..793fab1 100644 --- a/oi/OIDebugger.h +++ b/oi/OIDebugger.h @@ -249,6 +249,11 @@ class OIDebugger { std::filesystem::path segConfigFilePath; std::filesystem::path customCodeFile; + struct { + int traceeFd = -1; + int debuggerFd = -1; + } logFds; + struct c { uintptr_t textSegBase{}; size_t textSegSize{}; @@ -259,7 +264,6 @@ class OIDebugger { uintptr_t dataSegBase{}; size_t dataSegSize{}; uintptr_t cookie{}; - int logFile{}; } segConfig{}; /* diff --git a/oi/Syscall.h b/oi/Syscall.h index 521e5ec..59ce775 100644 --- a/oi/Syscall.h +++ b/oi/Syscall.h @@ -71,6 +71,8 @@ struct Syscall { using SysOpen = Syscall<"open", SYS_open, int, const char*, int, mode_t>; using SysClose = Syscall<"close", SYS_close, int, int>; using SysFsync = Syscall<"fsync", SYS_fsync, int, int>; +using MemfdCreate = + Syscall<"memfd_create", SYS_memfd_create, int, const char*, unsigned int>; using SysMmap = Syscall<"mmap", SYS_mmap, void*, void*, size_t, int, int, int, off_t>;