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.
...
```
This commit is contained in:
Jake Hillion 2023-11-21 02:50:31 -08:00 committed by Jake Hillion
parent 8f71efc2d0
commit 9e2b48d713
3 changed files with 99 additions and 66 deletions

View File

@ -29,6 +29,7 @@
#include <cerrno> #include <cerrno>
#include <chrono> #include <chrono>
#include <cstddef> #include <cstddef>
#include <cstdio>
#include <cstring> #include <cstring>
#include <numeric> #include <numeric>
#include <span> #include <span>
@ -195,57 +196,92 @@ bool OIDebugger::singleStepFunc(pid_t pid, uint64_t real_end) {
} }
bool OIDebugger::setupLogFile(void) { bool OIDebugger::setupLogFile(void) {
// 1. Copy the log file path in out text segment // 1. Copy the anonymous file name into our text segment.
// 2. Run the syscall // 2. Open an anonymous memfd in the target with `memfd_create`.
// 3. Store the resulting fd in the segmentConfigFile // 3. Duplicate that fd to the debugger using `pidfd_getfd`.
if (!segConfig.existingConfig) { // 4. Store the resulting fds in OIDebugger.
auto logFilePath = bool ret = true;
fs::path("/tmp") / ("oid-" + std::to_string(traceePid) + ".jit.log");
auto logFilePathLen = strlen(logFilePath.c_str()) + 1; static const std::string kAnonFileName{"jit.log"};
if (logFilePathLen > textSegSize) {
LOG(ERROR) << "The Log File's path " << logFilePath << " ("
<< logFilePathLen << ") is too long for the text segment ("
<< textSegSize << ")";
return false;
}
/* // Copy the file name into the text segment so it can be referenced by the
* Using the text segment to store the path in the remote process' memory. // remote syscall. This will be overwritten later during relocation.
* The memory will be re-used anyway and the path will get overwritten. if (!writeTargetMemory((void*)(kAnonFileName.c_str()),
*/ reinterpret_cast<void*>(segConfig.textSegBase),
if (!writeTargetMemory((void*)logFilePath.c_str(), kAnonFileName.length() + 1)) {
(void*)segConfig.textSegBase, LOG(ERROR) << "Failed to write log file's name into target process";
logFilePathLen)) { return false;
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<SysOpen>(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;
} }
return true; auto traceeFd = remoteSyscall<MemfdCreate>(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<int>(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<int>(debuggerFd);
return ret;
} }
bool OIDebugger::cleanupLogFile(void) { bool OIDebugger::cleanupLogFile(void) {
return remoteSyscall<SysClose>(segConfig.logFile).has_value(); bool ret = true;
if (logFds.traceeFd == -1)
return ret;
if (!remoteSyscall<SysClose>(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 */ /* Set up traced process results and text segments */
@ -260,11 +296,6 @@ bool OIDebugger::segmentInit(void) {
LOG(ERROR) << "setUpSegment failed!!!"; LOG(ERROR) << "setUpSegment failed!!!";
return false; return false;
} }
if (!setupLogFile()) {
LOG(ERROR) << "setUpLogFile failed!!!";
return false;
}
} else { } else {
if (!unmapSegment(SegType::data)) { if (!unmapSegment(SegType::data)) {
LOG(ERROR) << "Failed to unmmap data segment"; LOG(ERROR) << "Failed to unmmap data segment";
@ -295,6 +326,13 @@ bool OIDebugger::segmentInit(void) {
auto now = high_resolution_clock::now().time_since_epoch(); auto now = high_resolution_clock::now().time_since_epoch();
segConfig.cookie = duration_cast<duration<uintptr_t, std::nano>>(now).count(); segConfig.cookie = duration_cast<duration<uintptr_t, std::nano>>(now).count();
if (generatorConfig.features[Feature::JitLogging]) {
if (!setupLogFile()) {
LOG(ERROR) << "setUpLogFile failed!!!";
return false;
}
}
return true; return true;
} }
@ -345,8 +383,7 @@ void OIDebugger::createSegmentConfigFile(void) {
<< " dataSegBase: " << segConfig.dataSegBase << " dataSegBase: " << segConfig.dataSegBase
<< " dataSegSize: " << segConfig.dataSegSize << " dataSegSize: " << segConfig.dataSegSize
<< " replayInstBase: " << segConfig.replayInstBase << " replayInstBase: " << segConfig.replayInstBase
<< " cookie: " << segConfig.cookie << " cookie: " << segConfig.cookie;
<< " logFile: " << segConfig.logFile;
assert(segConfig.existingConfig); assert(segConfig.existingConfig);
} }
@ -1767,11 +1804,6 @@ bool OIDebugger::unmapSegments(bool deleteSegConfFile) {
ret = false; ret = false;
} }
if (ret && !cleanupLogFile()) {
LOG(ERROR) << "Problem closing target process log file";
ret = false;
}
deleteSegmentConfig(deleteSegConfFile); deleteSegmentConfig(deleteSegConfFile);
return ret; return ret;
@ -1830,13 +1862,6 @@ bool OIDebugger::removeTraps(pid_t pid) {
it = activeTraps.erase(it); 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<SysFsync>(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 */ /* Resume the main thread now, so it doesn't have to wait on restoreState */
if (!contTargetThread(targetPid)) { if (!contTargetThread(targetPid)) {
return false; return false;
@ -2341,7 +2366,7 @@ bool OIDebugger::compileCode() {
} }
int logFile = int logFile =
generatorConfig.features[Feature::JitLogging] ? segConfig.logFile : 0; generatorConfig.features[Feature::JitLogging] ? logFds.traceeFd : 0;
if (!writeTargetMemory( if (!writeTargetMemory(
&logFile, (void*)syntheticSymbols["logFile"], sizeof(logFile))) { &logFile, (void*)syntheticSymbols["logFile"], sizeof(logFile))) {
LOG(ERROR) << "Failed to write logFile in probe's cookieValue"; 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 VLOG(1) << "Couldn't interrupt target pid " << p
<< " (Reason: " << strerror(errno) << ")"; << " (Reason: " << strerror(errno) << ")";
} }
VLOG(1) << "Waiting to stop PID : " << p; VLOG(1) << "Waiting to stop PID : " << p;
if (waitpid(p, 0, WSTOPPED) != 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) { if (ptrace(PTRACE_DETACH, p, 0L, 0L) < 0) {
LOG(ERROR) << "restoreState Couldn't detach target pid " << p LOG(ERROR) << "restoreState Couldn't detach target pid " << p
<< " (Reason: " << strerror(errno) << ")"; << " (Reason: " << strerror(errno) << ")";

View File

@ -249,6 +249,11 @@ class OIDebugger {
std::filesystem::path segConfigFilePath; std::filesystem::path segConfigFilePath;
std::filesystem::path customCodeFile; std::filesystem::path customCodeFile;
struct {
int traceeFd = -1;
int debuggerFd = -1;
} logFds;
struct c { struct c {
uintptr_t textSegBase{}; uintptr_t textSegBase{};
size_t textSegSize{}; size_t textSegSize{};
@ -259,7 +264,6 @@ class OIDebugger {
uintptr_t dataSegBase{}; uintptr_t dataSegBase{};
size_t dataSegSize{}; size_t dataSegSize{};
uintptr_t cookie{}; uintptr_t cookie{};
int logFile{};
} segConfig{}; } segConfig{};
/* /*

View File

@ -71,6 +71,8 @@ struct Syscall {
using SysOpen = Syscall<"open", SYS_open, int, const char*, int, mode_t>; using SysOpen = Syscall<"open", SYS_open, int, const char*, int, mode_t>;
using SysClose = Syscall<"close", SYS_close, int, int>; using SysClose = Syscall<"close", SYS_close, int, int>;
using SysFsync = Syscall<"fsync", SYS_fsync, 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 = using SysMmap =
Syscall<"mmap", SYS_mmap, void*, void*, size_t, int, int, int, off_t>; Syscall<"mmap", SYS_mmap, void*, void*, size_t, int, int, int, off_t>;