diff options
author | Billy Donahue <billy.donahue@mongodb.com> | 2020-03-25 17:04:16 -0400 |
---|---|---|
committer | Evergreen Agent <no-reply@evergreen.mongodb.com> | 2020-04-02 02:05:48 +0000 |
commit | d2789d7e75be524212b8b6ab213577c69632fbfd (patch) | |
tree | 81f654f8d5593d2e1e905301411711149ca54650 | |
parent | cad10292bbd4f8e237c5ba85ec9265c21eddec38 (diff) | |
download | mongo-d2789d7e75be524212b8b6ab213577c69632fbfd.tar.gz |
SERVER-46801 Convert unittest library to structured logs.
Add logv2::LogComponent::kTest
-rw-r--r-- | src/mongo/logger/log_component.cpp | 4 | ||||
-rw-r--r-- | src/mongo/logger/log_component.h | 1 | ||||
-rw-r--r-- | src/mongo/logv2/log_component.cpp | 4 | ||||
-rw-r--r-- | src/mongo/logv2/log_component.h | 1 | ||||
-rw-r--r-- | src/mongo/unittest/death_test.cpp | 3 | ||||
-rw-r--r-- | src/mongo/unittest/unittest.cpp | 188 |
6 files changed, 109 insertions, 92 deletions
diff --git a/src/mongo/logger/log_component.cpp b/src/mongo/logger/log_component.cpp index 682348ab866..257c72668a5 100644 --- a/src/mongo/logger/log_component.cpp +++ b/src/mongo/logger/log_component.cpp @@ -149,6 +149,8 @@ StringData LogComponent::toStringData() const { return "transaction"_sd; case kConnectionPool: return "connectionPool"_sd; + case kTest: + return "test"_sd; case kNumLogComponents: return "total"_sd; // No default. Compiler should complain if there's a log component that's not handled. @@ -239,6 +241,8 @@ StringData LogComponent::getNameForLog() const { return "TXN "_sd; case kConnectionPool: return "CONNPOOL"_sd; + case kTest: + return "TEST "_sd; case kNumLogComponents: return "TOTAL "_sd; // No default. Compiler should complain if there's a log component that's not handled. diff --git a/src/mongo/logger/log_component.h b/src/mongo/logger/log_component.h index 378023e7c84..f216af088cd 100644 --- a/src/mongo/logger/log_component.h +++ b/src/mongo/logger/log_component.h @@ -72,6 +72,7 @@ public: kTracking, kTransaction, kConnectionPool, + kTest, kNumLogComponents, }; diff --git a/src/mongo/logv2/log_component.cpp b/src/mongo/logv2/log_component.cpp index 697b6ec0eeb..d7122f4f082 100644 --- a/src/mongo/logv2/log_component.cpp +++ b/src/mongo/logv2/log_component.cpp @@ -148,6 +148,8 @@ StringData LogComponent::toStringData() const { return "transaction"_sd; case kConnectionPool: return "connectionPool"_sd; + case kTest: + return "test"_sd; case kNumLogComponents: return "total"_sd; case kAutomaticDetermination: @@ -241,6 +243,8 @@ StringData LogComponent::getNameForLog() const { return "TXN"_sd; case kConnectionPool: return "CONNPOOL"_sd; + case kTest: + return "TEST"_sd; case kNumLogComponents: return "TOTAL"_sd; case kAutomaticDetermination: diff --git a/src/mongo/logv2/log_component.h b/src/mongo/logv2/log_component.h index 434aeff992f..f9a2a7345c7 100644 --- a/src/mongo/logv2/log_component.h +++ b/src/mongo/logv2/log_component.h @@ -74,6 +74,7 @@ public: kTracking, kTransaction, kConnectionPool, + kTest, kNumLogComponents }; diff --git a/src/mongo/unittest/death_test.cpp b/src/mongo/unittest/death_test.cpp index 5a41fbb41c0..31add6149ac 100644 --- a/src/mongo/unittest/death_test.cpp +++ b/src/mongo/unittest/death_test.cpp @@ -26,7 +26,7 @@ * exception statement from all source files in the program, then also delete * it in the license file. */ -#define MONGO_LOG_DEFAULT_COMPONENT ::mongo::logger::LogComponent::kDefault +#define MONGO_LOGV2_DEFAULT_COMPONENT ::mongo::logv2::LogComponent::kTest #include "mongo/platform/basic.h" @@ -47,7 +47,6 @@ #include "mongo/logv2/log.h" #include "mongo/util/assert_util.h" -#include "mongo/util/log.h" #include "mongo/util/quick_exit.h" #define checkSyscall(EXPR) \ diff --git a/src/mongo/unittest/unittest.cpp b/src/mongo/unittest/unittest.cpp index 3e6fd6d8b3c..2d0a1863cb5 100644 --- a/src/mongo/unittest/unittest.cpp +++ b/src/mongo/unittest/unittest.cpp @@ -28,6 +28,7 @@ */ #define MONGO_LOG_DEFAULT_COMPONENT ::mongo::logger::LogComponent::kDefault +#define MONGO_LOGV2_DEFAULT_COMPONENT ::mongo::logv2::LogComponent::kTest #include "mongo/platform/basic.h" @@ -56,6 +57,7 @@ #include "mongo/logv2/log_domain.h" #include "mongo/logv2/log_domain_global.h" #include "mongo/logv2/log_manager.h" +#include "mongo/logv2/log_truncation.h" #include "mongo/logv2/plain_formatter.h" #include "mongo/platform/mutex.h" #include "mongo/util/assert_util.h" @@ -108,6 +110,22 @@ MONGO_INITIALIZER_WITH_PREREQUISITES(UnitTestOutput, ("GlobalLogManager", "defau class Result { public: + struct FailStatus { + std::string test; + std::string type; + std::string error; + std::string extra; + + friend std::ostream& operator<<(std::ostream& os, const FailStatus& f) { + return os // + << "{test: " << f.test // + << ", type: " << f.type // + << ", error: " << f.error // + << ", extra: " << f.extra // + << "}"; + } + }; + Result(const std::string& name) : _name(name), _rc(0), _tests(0), _fails(), _asserts(0), _millis(0) {} @@ -125,6 +143,28 @@ public: return ss.str(); } + BSONObj toBSON() const { + BSONObjBuilder bob; + bob.append("name", _name); + bob.append("tests", _tests); + bob.appendNumber("fails", _fails.size()); + bob.append("asserts", _asserts); + bob.append("time", Milliseconds(_millis).toBSON()); + { + auto arr = BSONArrayBuilder(bob.subarrayStart("failures")); + for (const auto& m : _messages) { + auto o = BSONObjBuilder(arr.subobjStart()); + o.append("test", m.test); + o.append("type", m.type); + o.append("error", m.error); + if (!m.extra.empty()) { + o.append("extra", m.extra); + } + } + } + return bob.obj(); + } + int rc() { return _rc; } @@ -136,34 +176,11 @@ public: std::vector<std::string> _fails; int _asserts; int _millis; - std::vector<std::string> _messages; + std::vector<FailStatus> _messages; }; namespace { -/** - * This unsafe scope guard allows exceptions in its destructor. Thus, if it goes out of scope when - * an exception is active and the guard function also throws an exception, the program will call - * std::terminate. This should only be used in unittests where termination on exception is okay. - */ -template <typename F> -class UnsafeScopeGuard { -public: - UnsafeScopeGuard(F fun) : _fun(fun) {} - - ~UnsafeScopeGuard() noexcept(false) { - _fun(); - } - -private: - F _fun; -}; - -template <typename F> -UnsafeScopeGuard<F> MakeUnsafeScopeGuard(F fun) { - return UnsafeScopeGuard<F>(std::move(fun)); -} - // Attempting to read the featureCompatibilityVersion parameter before it is explicitly initialized // with a meaningful value will trigger failures as of SERVER-32630. void setUpFCV() { @@ -452,59 +469,52 @@ std::unique_ptr<Result> Suite::run(const std::string& filter, for (const auto& tc : _tests) { if (filter.size() && tc.name.find(filter) == std::string::npos) { - LOGV2_DEBUG(23057, - 1, - "\t skipping test: {tc_name} because it doesn't match filter", - "tc_name"_attr = tc.name); + LOGV2_DEBUG(23057, 1, "skipped due to filter", "test"_attr = tc.name); continue; } if (fileNameFilter.size() && tc.fileName.find(fileNameFilter) == std::string::npos) { - LOGV2_DEBUG(23058, - 1, - "\t skipping test: {tc_fileName} because it doesn't match fileNameFilter", - "tc_fileName"_attr = tc.fileName); + LOGV2_DEBUG(23058, 1, "skipped due to fileNameFilter", "testFile"_attr = tc.fileName); continue; } ++r->_tests; - bool passes = false; - - std::ostringstream err; - err << tc.name << "\t"; - + struct Event { + std::string type; + std::string error; + std::string extra; + }; try { - for (int x = 0; x < runsPerTest; x++) { - std::ostringstream runTimes; - if (runsPerTest > 1) { - runTimes << " (" << x + 1 << "/" << runsPerTest << ")"; + try { + for (int x = 0; x < runsPerTest; x++) { + LOGV2(23059, + "Running", + "test"_attr = tc.name, + "rep"_attr = x + 1, + "reps"_attr = runsPerTest); + TestSuiteEnvironment environment; + tc.fn(); } - - LOGV2(23059, - "\t going to run test: {tc_name}{runTimes_str}", - "tc_name"_attr = tc.name, - "runTimes_str"_attr = runTimes.str()); - TestSuiteEnvironment environment; - tc.fn(); + } catch (const TestAssertionFailureException& ae) { + throw Event{"TestAssertionFailureException", ae.toString(), ae.getStacktrace()}; + } catch (const DBException& e) { + throw Event{"DBException", e.toString()}; + } catch (const std::exception& e) { + throw Event{"std::exception", e.what()}; + } catch (int x) { + throw Event{"int", std::to_string(x)}; } - passes = true; - } catch (const TestAssertionFailureException& ae) { - err << ae.toString() << " in test " << tc.name << '\n' << ae.getStacktrace(); - } catch (const DBException& e) { - err << "DBException: " << e.toString() << " in test " << tc.name; - } catch (const std::exception& e) { - err << "std::exception: " << e.what() << " in test " << tc.name; - } catch (int x) { - err << "caught int " << x << " in test " << tc.name; - } - - if (!passes) { - std::string s = err.str(); - // Don't truncate failure messages, e.g: stacktraces. - log().setIsTruncatable(false) << "FAIL: " << s; + } catch (const Event& e) { + LOGV2_OPTIONS(4680100, + {logv2::LogTruncation::Disabled}, + "FAIL", + "test"_attr = tc.name, + "type"_attr = e.type, + "error"_attr = e.error, + "extra"_attr = e.extra); r->_fails.push_back(tc.name); - r->_messages.push_back(s); + r->_messages.push_back({tc.name, e.type, e.error, e.extra}); } } @@ -513,7 +523,7 @@ std::unique_ptr<Result> Suite::run(const std::string& filter, r->_millis = timer.millis(); - LOGV2(23060, "\t DONE running tests"); + LOGV2(23060, "Done running tests"); return r; } @@ -523,15 +533,15 @@ int Suite::run(const std::vector<std::string>& suites, const std::string& fileNameFilter, int runsPerTest) { if (suitesMap().empty()) { - LOGV2(23061, "error: no suites registered."); + LOGV2_ERROR(23061, "no suites registered."); return EXIT_FAILURE; } for (unsigned int i = 0; i < suites.size(); i++) { if (suitesMap().count(suites[i]) == 0) { - LOGV2(23062, - "invalid test suite [{suites_i}], use --list to see valid names", - "suites_i"_attr = suites[i]); + LOGV2_ERROR(23062, + "invalid test suite, use --list to see valid names", + "suite"_attr = suites[i]); return EXIT_FAILURE; } } @@ -550,12 +560,11 @@ int Suite::run(const std::vector<std::string>& suites, std::shared_ptr<Suite>& s = suitesMap()[name]; fassert(16145, s != nullptr); - LOGV2(23063, "going to run suite: {name}", "name"_attr = name); - results.push_back(s->run(filter, fileNameFilter, runsPerTest)); + LOGV2(23063, "Running", "suite"_attr = name); + auto result = s->run(filter, fileNameFilter, runsPerTest); + results.push_back(std::move(result)); } - LOGV2(23064, "**************************************************"); - int rc = 0; int tests = 0; @@ -563,41 +572,40 @@ int Suite::run(const std::vector<std::string>& suites, int millis = 0; Result totals("TOTALS"); - std::vector<std::string> failedSuites; + std::vector<BSONObj> failedSuites; for (const auto& r : results) { - log().setIsTruncatable(false) << r->toString(); if (abs(r->rc()) > abs(rc)) rc = r->rc(); tests += r->_tests; if (!r->_fails.empty()) { - failedSuites.push_back(r->toString()); - for (const std::string& s : r->_fails) { - totals._fails.push_back(r->_name + "/" + s); + failedSuites.push_back(r->toBSON()); + for (const std::string& failedTest : r->_fails) { + totals._fails.push_back(r->_name + "/" + failedTest); } } asserts += r->_asserts; millis += r->_millis; } - results.clear(); - totals._tests = tests; totals._asserts = asserts; totals._millis = millis; - LOGV2(23065, "{totals}", "totals"_attr = totals.toString()); + for (const auto& r : results) { + LOGV2_OPTIONS( + 4680101, {logv2::LogTruncation::Disabled}, "Result", "suite"_attr = r->toBSON()); + } + LOGV2(23065, "Totals", "totals"_attr = totals.toBSON()); // summary if (!totals._fails.empty()) { - LOGV2(23066, "Failing tests:"); - for (const std::string& s : totals._fails) { - LOGV2(23067, "\t {s} Failed", "s"_attr = s); - } - LOGV2(23068, - "FAILURE - {totals_fails_size} tests in {failedSuites_size} suites failed", - "totals_fails_size"_attr = totals._fails.size(), - "failedSuites_size"_attr = failedSuites.size()); + LOGV2_OPTIONS(23068, + {logv2::LogTruncation::Disabled}, + "FAILURE", + "failedTestsCount"_attr = totals._fails.size(), + "failedSuitesCount"_attr = failedSuites.size(), + "failedTests"_attr = totals._fails); } else { LOGV2(23069, "SUCCESS - All tests in all suites passed"); } @@ -655,7 +663,7 @@ TestAssertionFailure::~TestAssertionFailure() noexcept(false) { if (!_stream.str().empty()) { _exception.setMessage(_exception.getMessage() + " " + _stream.str()); } - LOGV2_ERROR(23070, "Throwing exception: {exception}", "exception"_attr = _exception); + LOGV2_ERROR(23070, "Throwing exception", "exception"_attr = _exception); throw _exception; } |