From 71415a4a6da9efffb99941e4bae5a478c2ffecec Mon Sep 17 00:00:00 2001 From: Billy Donahue Date: Fri, 14 Feb 2020 15:42:10 -0500 Subject: SERVER-46158 stacktrace_windows to LOGV2 - convert test from to pcrecpp.h - convert backslash to slash in filenames --- src/mongo/util/stacktrace_test.cpp | 98 ++++++------ src/mongo/util/stacktrace_windows.cpp | 276 ++++++++++++++++++---------------- 2 files changed, 200 insertions(+), 174 deletions(-) diff --git a/src/mongo/util/stacktrace_test.cpp b/src/mongo/util/stacktrace_test.cpp index b1d4d3b5986..cdb147128d8 100644 --- a/src/mongo/util/stacktrace_test.cpp +++ b/src/mongo/util/stacktrace_test.cpp @@ -39,8 +39,8 @@ #include #include #include +#include #include -#include #include #include #include @@ -168,14 +168,12 @@ TEST(StackTrace, PosixFormat) { tlog() << "trace:{" << trace << "}"; } - std::smatch m; - ASSERT_TRUE(std::regex_match(trace, - m, - std::regex(R"re(BACKTRACE: (\{.*\})\n)re" - R"re(((?:.|\n)*))re"))) + std::string jsonLine; + std::string traceBody; + ASSERT_TRUE(pcrecpp::RE(R"re(BACKTRACE: (\{.*\})\n)re" + R"re(((?:.|\n)*))re") + .FullMatch(trace, &jsonLine, &traceBody)) << "trace: {}"_format(trace); - std::string jsonLine = m[1].str(); - std::string traceBody = m[2].str(); if (kSuperVerbose) { tlog() << "jsonLine:{" << jsonLine << "}"; @@ -205,19 +203,11 @@ TEST(StackTrace, PosixFormat) { // Sanity check: make sure all BACKTRACE addrs are represented in the Frame section. std::vector humanAddrs; - static const std::regex re(R"re( Frame: (?:\{"a":"(.*?)",.*\})\n?)re"); - for (auto rei = std::sregex_iterator(traceBody.begin(), traceBody.end(), re); - rei != std::sregex_iterator(); - ++rei) { - if (kSuperVerbose) { - tlog() << "sregex_iterator fields {"; - for (size_t ei = 1; ei < rei->size(); ++ei) { - tlog() << " {:2d}: `{}`"_format(ei, (*rei)[ei]); - } - tlog() << "}"; - } - ASSERT_EQ(rei->size(), 2); - humanAddrs.push_back(fromHex((*rei)[1])); + + static const pcrecpp::RE re(R"re( Frame: (?:\{"a":"(.*?)",.*\})\n?)re"); + pcrecpp::StringPiece traceBodyPiece(traceBody); + for (uintptr_t addr; re.Consume(&traceBodyPiece, pcrecpp::Hex(&addr));) { + humanAddrs.push_back(addr); } std::vector btAddrs; @@ -226,13 +216,27 @@ TEST(StackTrace, PosixFormat) { } // Mac OS backtrace returns extra frames in "backtrace". -#if defined(__APPLE__) ASSERT_TRUE(std::search(btAddrs.begin(), btAddrs.end(), humanAddrs.begin(), humanAddrs.end()) == btAddrs.begin()) << LogVec(btAddrs) << " vs " << LogVec(humanAddrs); -#else - ASSERT_TRUE(btAddrs == humanAddrs) << LogVec(btAddrs) << " vs " << LogVec(humanAddrs); -#endif // __APPLE +} + + +std::vector splitLines(std::string in) { + std::vector lines; + while (true) { + auto pos = in.find("\n"); + if (pos == std::string::npos) { + break; + } else { + lines.push_back(in.substr(0, pos)); + in = in.substr(pos + 1); + } + } + if (!in.empty()) { + lines.push_back(in); + } + return lines; } TEST(StackTrace, WindowsFormat) { @@ -240,8 +244,7 @@ TEST(StackTrace, WindowsFormat) { return; } - // TODO: rough: string parts are not escaped and can contain the ' ' delimiter. - const std::string trace = [&] { + std::string trace = [&] { std::string s; stack_trace_test_detail::RecursionParam param{3, [&] { StringStackTraceSink sink{s}; @@ -250,25 +253,30 @@ TEST(StackTrace, WindowsFormat) { stack_trace_test_detail::recurseWithLinkage(param); return s; }(); - const std::regex re(R"re(()re" // line pattern open - R"re(([^\\]?))re" // moduleName: cannot have backslashes - R"re(\s*)re" // pad - R"re(.*)re" // sourceAndLine: empty, or "...\dir\file(line)" - R"re(\s*)re" // pad - R"re((?:)re" // symbolAndOffset: choice open non-capturing - R"re(\?\?\?)re" // raw case: "???" - R"re(|)re" // or - R"re((.*)\+0x[0-9a-f]*)re" // "symbolname+0x" lcHex... - R"re())re" // symbolAndOffset: choice close - R"re()\n)re"); // line pattern close, newline - auto mark = trace.begin(); - for (auto i = std::sregex_iterator(trace.begin(), trace.end(), re); i != std::sregex_iterator(); - ++i) { - mark = (*i)[0].second; + + std::vector lines = splitLines(trace); + + std::string jsonLine; + ASSERT_TRUE(pcrecpp::RE(R"re(BACKTRACE: (\{.*\}))re").FullMatch(lines[0], &jsonLine)); + + std::vector humanAddrs; + for (size_t i = 1; i < lines.size(); ++i) { + static const pcrecpp::RE re(R"re( Frame: (?:\{"a":"(.*?)",.*\}))re"); + uintptr_t addr; + ASSERT_TRUE(re.FullMatch(lines[i], pcrecpp::Hex(&addr))) << lines[i]; + humanAddrs.push_back(addr); + } + + BSONObj jsonObj = fromjson(jsonLine); // throwy + ASSERT_TRUE(jsonObj.hasField("backtrace")) << tojson(jsonObj); + std::vector btAddrs; + for (const auto& btElem : jsonObj["backtrace"].Obj()) { + btAddrs.push_back(fromHex(btElem.Obj()["a"].String())); } - ASSERT_TRUE(mark == trace.end()) - << "cannot match suffix: `" << trace.substr(mark - trace.begin()) << "` " - << "of trace: `" << trace << "`"; + + ASSERT_TRUE(std::search(btAddrs.begin(), btAddrs.end(), humanAddrs.begin(), humanAddrs.end()) == + btAddrs.begin()) + << LogVec(btAddrs) << " vs " << LogVec(humanAddrs); } std::string traceString() { diff --git a/src/mongo/util/stacktrace_windows.cpp b/src/mongo/util/stacktrace_windows.cpp index 582c8921ff2..14f00b58f25 100644 --- a/src/mongo/util/stacktrace_windows.cpp +++ b/src/mongo/util/stacktrace_windows.cpp @@ -27,7 +27,7 @@ * it in the license file. */ -#define MONGO_LOG_DEFAULT_COMPONENT ::mongo::logger::LogComponent::kControl +#define MONGO_LOGV2_DEFAULT_COMPONENT ::mongo::logv2::LogComponent::kControl #include "mongo/platform/basic.h" @@ -43,17 +43,23 @@ #include #include #include +#include #include #include #include #include +#include #include #include "mongo/base/init.h" +#include "mongo/bson/bsonobj.h" +#include "mongo/bson/bsonobjbuilder.h" +#include "mongo/bson/json.h" +#include "mongo/logv2/log.h" #include "mongo/stdx/mutex.h" #include "mongo/util/assert_util.h" #include "mongo/util/concurrency/mutex.h" -#include "mongo/util/log.h" +#include "mongo/util/stacktrace_json.h" #include "mongo/util/text.h" namespace mongo { @@ -61,6 +67,11 @@ namespace { const size_t kPathBufferSize = 1024; +struct Options { + bool withHumanReadable = false; + bool rawAddress = false; +}; + // On Windows the symbol handler must be initialized at process startup and cleaned up at shutdown. // This class wraps up that logic and gives access to the process handle associated with the // symbol handler. Because access to the symbol handler API is not thread-safe, it also provides @@ -84,10 +95,10 @@ public: << L";C:\\Windows\\System32;C:\\Windows"; const auto symbolPath = symbolPathBuilder.str(); - BOOL ret = SymInitializeW(handle, symbolPath.c_str(), TRUE); - if (ret == FALSE) { - error() << "Stack trace initialization failed, SymInitialize failed with error " - << errnoWithDescription(); + if (!SymInitializeW(handle, symbolPath.c_str(), TRUE)) { + LOGV2_ERROR(31443, + "Stack trace initialization failed, SymInitialize failed with error {err}", + "err"_attr = errnoWithDescription()); return; } @@ -143,23 +154,17 @@ MONGO_INITIALIZER(IntializeSymbolHandler)(::mongo::InitializerContext* ctx) { * * @param process Process handle * @param address Address to find - * @param returnedModuleName Returned module name */ -static void getModuleName(HANDLE process, DWORD64 address, std::string* returnedModuleName) { +static std::string getModuleName(HANDLE process, DWORD64 address) { IMAGEHLP_MODULE64 module64; memset(&module64, 0, sizeof(module64)); module64.SizeOfStruct = sizeof(module64); - BOOL ret = SymGetModuleInfo64(process, address, &module64); - if (FALSE == ret) { - returnedModuleName->clear(); - return; - } + if (!SymGetModuleInfo64(process, address, &module64)) + return {}; char* moduleName = module64.LoadedImageName; - char* backslash = strrchr(moduleName, '\\'); - if (backslash) { + if (char* backslash = strrchr(moduleName, '\\'); backslash) moduleName = backslash + 1; - } - *returnedModuleName = moduleName; + return moduleName; } /** @@ -167,36 +172,26 @@ static void getModuleName(HANDLE process, DWORD64 address, std::string* returned * * @param process Process handle * @param address Address to find - * @param returnedSourceAndLine Returned source code file name with line number */ -static void getSourceFileAndLineNumber(HANDLE process, - DWORD64 address, - std::string* returnedSourceAndLine) { +static std::pair getSourceLocation(HANDLE process, DWORD64 address) { IMAGEHLP_LINE64 line64; memset(&line64, 0, sizeof(line64)); line64.SizeOfStruct = sizeof(line64); - DWORD displacement32; - BOOL ret = SymGetLineFromAddr64(process, address, &displacement32, &line64); - if (FALSE == ret) { - returnedSourceAndLine->clear(); - return; - } - - std::string filename(line64.FileName); - std::string::size_type start = filename.find("\\src\\mongo\\"); - if (start == std::string::npos) { - start = filename.find("\\src\\third_party\\"); - } - if (start != std::string::npos) { - std::string shorter("..."); - shorter += filename.substr(start); - filename.swap(shorter); + DWORD offset; + if (!SymGetLineFromAddr64(process, address, &offset, &line64)) + return {}; + std::string filename = line64.FileName; + static constexpr const char* kDiscards[] = {R"(\src\mongo\)", R"(\src\third_party\)"}; + for (const char* const discard : kDiscards) { + if (auto start = filename.find(discard); start != std::string::npos) { + filename.replace(0, start, "..."); + break; + } } - static const size_t bufferSize = 32; - std::unique_ptr lineNumber(new char[bufferSize]); - _snprintf(lineNumber.get(), bufferSize, "(%u)", line64.LineNumber); - filename += lineNumber.get(); - returnedSourceAndLine->swap(filename); + for (char& c : filename) + if (c == '\\') + c = '/'; + return {std::move(filename), line64.LineNumber}; } /** @@ -205,48 +200,52 @@ static void getSourceFileAndLineNumber(HANDLE process, * @param process Process handle * @param address Address to find * @param symbolInfo Caller's pre-built SYMBOL_INFO struct (for efficiency) - * @param returnedSymbolAndOffset Returned symbol and offset */ -static void getsymbolAndOffset(HANDLE process, - DWORD64 address, - SYMBOL_INFO* symbolInfo, - std::string* returnedSymbolAndOffset) { - DWORD64 displacement64; - BOOL ret = SymFromAddr(process, address, &displacement64, symbolInfo); - if (FALSE == ret) { - *returnedSymbolAndOffset = "???"; - return; - } - std::string symbolString(symbolInfo->Name); - static const size_t bufferSize = 32; - std::unique_ptr symbolOffset(new char[bufferSize]); - _snprintf(symbolOffset.get(), bufferSize, "+0x%llx", displacement64); - symbolString += symbolOffset.get(); - returnedSymbolAndOffset->swap(symbolString); +static std::pair getSymbolAndOffset(HANDLE process, + DWORD64 address, + SYMBOL_INFO* symbolInfo) { + DWORD64 offset; + if (!SymFromAddr(process, address, &offset, symbolInfo)) + return {}; + return {symbolInfo->Name, offset}; } struct TraceItem { - std::string moduleName; - std::string sourceAndLine; - std::string symbolAndOffset; + uintptr_t address; + std::string module; + std::pair source; + std::pair symbol; }; -} // namespace - +void appendTrace(BSONObjBuilder* bob, + const std::vector& traceList, + const Options& options) { + auto bt = BSONArrayBuilder(bob->subarrayStart("backtrace")); + for (const auto& item : traceList) { + auto o = BSONObjBuilder(bt.subobjStart()); + if (options.rawAddress) + o.append("a", stack_trace_detail::Hex(item.address)); + if (!item.module.empty()) + o.append("module", item.module); + if (!item.source.first.empty()) { + o.append("file", item.source.first); + o.append("line", static_cast(item.source.second)); + } + if (!item.symbol.first.empty()) { + o.append("s", item.symbol.first); + o.append("s+", stack_trace_detail::Hex(item.symbol.second)); + } + } +} -/** - * Print stack trace (using a specified stack context) to `sink`> - * - * @param context execution state that produces the stack trace - * @param sink receives printed stack backtrace - */ -void printWindowsStackTrace(CONTEXT& context, StackTraceSink& sink) { +std::vector makeTraceList(CONTEXT& context) { + std::vector traceList; auto& symbolHandler = SymbolHandler::instance(); stdx::lock_guard lk(symbolHandler); if (!symbolHandler) { - error() << "Stack trace failed, symbol handler returned an invalid handle."; - return; + LOGV2_ERROR(31444, "Stack trace failed, symbol handler returned an invalid handle."); + return traceList; } STACKFRAME64 frame64; @@ -277,86 +276,105 @@ void printWindowsStackTrace(CONTEXT& context, StackTraceSink& sink) { symbolBuffer->SizeOfStruct = sizeof(SYMBOL_INFO); symbolBuffer->MaxNameLen = nameSize; - // build list - std::vector traceList; - TraceItem traceItem; - size_t moduleWidth = 0; - size_t sourceWidth = 0; for (size_t i = 0; i < kStackTraceFrameMax; ++i) { - BOOL ret = StackWalk64(imageType, - symbolHandler.getHandle(), - GetCurrentThread(), - &frame64, - &context, - NULL, - NULL, - NULL, - NULL); - if (ret == FALSE || frame64.AddrReturn.Offset == 0) { + if (!StackWalk64(imageType, + symbolHandler.getHandle(), + GetCurrentThread(), + &frame64, + &context, + NULL, + NULL, + NULL, + NULL)) + break; + if (!frame64.AddrReturn.Offset) break; - } DWORD64 address = frame64.AddrPC.Offset; - getModuleName(symbolHandler.getHandle(), address, &traceItem.moduleName); - size_t width = traceItem.moduleName.length(); - if (width > moduleWidth) { - moduleWidth = width; - } - getSourceFileAndLineNumber(symbolHandler.getHandle(), address, &traceItem.sourceAndLine); - width = traceItem.sourceAndLine.length(); - if (width > sourceWidth) { - sourceWidth = width; - } - getsymbolAndOffset( - symbolHandler.getHandle(), address, symbolBuffer, &traceItem.symbolAndOffset); - traceList.push_back(traceItem); + auto h = symbolHandler.getHandle(); + traceList.push_back({static_cast(address), + getModuleName(h, address), + getSourceLocation(h, address), + getSymbolAndOffset(h, address, symbolBuffer)}); } + return traceList; +} - // print list - ++moduleWidth; - ++sourceWidth; - size_t frameCount = traceList.size(); - for (size_t i = 0; i < frameCount; ++i) { - sink << traceList[i].moduleName << " "; - size_t width = traceList[i].moduleName.length(); - while (width < moduleWidth) { - sink << " "; - ++width; - } - sink << traceList[i].sourceAndLine << " "; - width = traceList[i].sourceAndLine.length(); - while (width < sourceWidth) { - sink << " "; - ++width; +void printTraceList(const std::vector& traceList, + StackTraceSink* sink, + const Options& options) { + using namespace fmt::literals; + if (traceList.empty()) + return; + BSONObjBuilder bob; + appendTrace(&bob, traceList, options); + const BSONObj bt = bob.done(); + + static constexpr char fmtBt[] = "BACKTRACE: {bt}"; + if (sink) { + *sink << fmt::format(fmtBt, "bt"_a = tojson(bt, ExtendedRelaxedV2_0_0)); + } else { + LOGV2_OPTIONS(31380, {logv2::LogTruncation::Disabled}, fmtBt, "bt"_attr = bt); + } + + if (options.withHumanReadable) { + if (auto elem = bt.getField("backtrace"); !elem.eoo()) { + for (const auto& fe : elem.Obj()) { + BSONObj frame = fe.Obj(); + static constexpr char fmtFrame[] = " Frame: {frame}"; + if (sink) { + *sink << "\n" + << fmt::format(fmtFrame, + "frame"_a = tojson(frame, ExtendedRelaxedV2_0_0)); + } else { + LOGV2(31445, fmtFrame, "frame"_attr = frame); + } + } } - sink << traceList[i].symbolAndOffset << "\n"; } } +/** `sink` can be nullptr to emit structured logs instead of writing to a sink. */ +void printWindowsStackTraceImpl(CONTEXT& context, StackTraceSink* sink) { + Options options{}; + options.withHumanReadable = true; + options.rawAddress = true; + printTraceList(makeTraceList(context), sink, options); +} + +void printWindowsStackTraceImpl(StackTraceSink* sink) { + CONTEXT context; + memset(&context, 0, sizeof(context)); + context.ContextFlags = CONTEXT_CONTROL; + RtlCaptureContext(&context); + printWindowsStackTraceImpl(context, sink); +} + +} // namespace + +void printWindowsStackTrace(CONTEXT& context, StackTraceSink& sink) { + printWindowsStackTraceImpl(context, &sink); +} + void printWindowsStackTrace(CONTEXT& context, std::ostream& os) { OstreamStackTraceSink sink{os}; - printWindowsStackTrace(context, sink); + printWindowsStackTraceImpl(context, &sink); } void printWindowsStackTrace(CONTEXT& context) { - printWindowsStackTrace(context, log(logger::LogComponent::kDefault).stream()); + printWindowsStackTraceImpl(context, nullptr); } void printStackTrace(StackTraceSink& sink) { - CONTEXT context; - memset(&context, 0, sizeof(context)); - context.ContextFlags = CONTEXT_CONTROL; - RtlCaptureContext(&context); - printWindowsStackTrace(context, sink); + printWindowsStackTraceImpl(&sink); } void printStackTrace(std::ostream& os) { OstreamStackTraceSink sink{os}; - printStackTrace(sink); + printWindowsStackTraceImpl(&sink); } void printStackTrace() { - // Disable truncation to accomodate our large JSON representation. - printStackTrace(log(logger::LogComponent::kDefault).setIsTruncatable(false).stream()); + printWindowsStackTraceImpl(nullptr); } } // namespace mongo -- cgit v1.2.1