lix/tests/unit/libutil/logging.cc

371 lines
14 KiB
C++
Raw Permalink Normal View History

Improve error formatting Changes: * The divider lines are gone. These were in practice a bit confusing, in particular with --show-trace or --keep-going, since then there were multiple lines, suggesting a start/end which wasn't the case. * Instead, multi-line error messages are now indented to align with the prefix (e.g. "error: "). * The 'description' field is gone since we weren't really using it. * 'hint' is renamed to 'msg' since it really wasn't a hint. * The error is now printed *before* the location info. * The 'name' field is no longer printed since most of the time it wasn't very useful since it was just the name of the exception (like EvalError). Ideally in the future this would be a unique, easily googleable error ID (like rustc). * "trace:" is now just "…". This assumes error contexts start with something like "while doing X". Example before: error: --- AssertionError ---------------------------------------------------------------------------------------- nix at: (7:7) in file: /home/eelco/Dev/nixpkgs/pkgs/applications/misc/hello/default.nix 6| 7| x = assert false; 1; | ^ 8| assertion 'false' failed ----------------------------------------------------- show-trace ----------------------------------------------------- trace: while evaluating the attribute 'x' of the derivation 'hello-2.10' at: (192:11) in file: /home/eelco/Dev/nixpkgs/pkgs/stdenv/generic/make-derivation.nix 191| // (lib.optionalAttrs (!(attrs ? name) && attrs ? pname && attrs ? version)) { 192| name = "${attrs.pname}-${attrs.version}"; | ^ 193| } // (lib.optionalAttrs (stdenv.hostPlatform != stdenv.buildPlatform && !dontAddHostSuffix && (attrs ? name || (attrs ? pname && attrs ? version)))) { Example after: error: assertion 'false' failed at: (7:7) in file: /home/eelco/Dev/nixpkgs/pkgs/applications/misc/hello/default.nix 6| 7| x = assert false; 1; | ^ 8| … while evaluating the attribute 'x' of the derivation 'hello-2.10' at: (192:11) in file: /home/eelco/Dev/nixpkgs/pkgs/stdenv/generic/make-derivation.nix 191| // (lib.optionalAttrs (!(attrs ? name) && attrs ? pname && attrs ? version)) { 192| name = "${attrs.pname}-${attrs.version}"; | ^ 193| } // (lib.optionalAttrs (stdenv.hostPlatform != stdenv.buildPlatform && !dontAddHostSuffix && (attrs ? name || (attrs ? pname && attrs ? version)))) {
2021-01-20 23:27:36 +00:00
#if 0
2020-06-06 08:22:32 +00:00
#include "logging.hh"
#include "nixexpr.hh"
#include "util.hh"
2020-06-19 20:54:41 +00:00
#include <fstream>
2020-06-06 08:22:32 +00:00
#include <gtest/gtest.h>
namespace nix {
/* ----------------------------------------------------------------------------
* logEI
* --------------------------------------------------------------------------*/
const char *test_file =
"previous line of code\n"
"this is the problem line of code\n"
"next line of code\n";
const char *one_liner =
"this is the other problem line of code";
2020-06-06 08:22:32 +00:00
TEST(logEI, catpuresBasicProperties) {
MakeError(TestError, Error);
ErrorInfo::programName = std::optional("error-unit-test");
try {
throw TestError("an error for testing purposes");
} catch (Error &e) {
testing::internal::CaptureStderr();
logger->logEI(e.info());
auto str = testing::internal::GetCapturedStderr();
2020-06-16 07:44:19 +00:00
ASSERT_STREQ(str.c_str(),"\x1B[31;1merror:\x1B[0m\x1B[34;1m --- TestError --- error-unit-test\x1B[0m\nan error for testing purposes\n");
2020-06-06 08:22:32 +00:00
}
}
TEST(logEI, jsonOutput) {
SymbolTable testTable;
auto problem_file = testTable.create("random.nix");
testing::internal::CaptureStderr();
makeJSONLogger(*logger)->logEI({
.name = "error name",
.msg = HintFmt("this hint has %1% templated %2%!!",
"yellow",
"values"),
.errPos = Pos(foFile, problem_file, 02, 13)
});
auto str = testing::internal::GetCapturedStderr();
2020-12-22 15:23:57 +00:00
ASSERT_STREQ(str.c_str(), "@nix {\"action\":\"msg\",\"column\":13,\"file\":\"random.nix\",\"level\":0,\"line\":2,\"msg\":\"\\u001b[31;1merror:\\u001b[0m\\u001b[34;1m --- error name --- error-unit-test\\u001b[0m\\n\\u001b[34;1mat: \\u001b[33;1m(2:13)\\u001b[34;1m in file: \\u001b[0mrandom.nix\\n\\nerror without any code lines.\\n\\nthis hint has \\u001b[33;1myellow\\u001b[0m templated \\u001b[33;1mvalues\\u001b[0m!!\",\"raw_msg\":\"this hint has \\u001b[33;1myellow\\u001b[0m templated \\u001b[33;1mvalues\\u001b[0m!!\"}\n");
}
2020-06-06 08:22:32 +00:00
TEST(logEI, appendingHintsToPreviousError) {
MakeError(TestError, Error);
ErrorInfo::programName = std::optional("error-unit-test");
try {
auto e = Error("initial error");
throw TestError(e.info());
} catch (Error &e) {
ErrorInfo ei = e.info();
ei.msg = HintFmt("%s; subsequent error message.", Uncolored(e.info().msg.str()));
2020-06-06 08:22:32 +00:00
testing::internal::CaptureStderr();
logger->logEI(ei);
auto str = testing::internal::GetCapturedStderr();
ASSERT_STREQ(str.c_str(), "\x1B[31;1merror:\x1B[0m\x1B[34;1m --- TestError --- error-unit-test\x1B[0m\ninitial error; subsequent error message.\n");
2020-06-06 08:22:32 +00:00
}
}
TEST(logEI, picksUpSysErrorExitCode) {
MakeError(TestError, Error);
ErrorInfo::programName = std::optional("error-unit-test");
try {
auto x = readFile(-1);
}
catch (SysError &e) {
testing::internal::CaptureStderr();
logError(e.info());
auto str = testing::internal::GetCapturedStderr();
ASSERT_STREQ(str.c_str(), "\x1B[31;1merror:\x1B[0m\x1B[34;1m --- SysError --- error-unit-test\x1B[0m\nstatting file: \x1B[33;1mBad file descriptor\x1B[0m\n");
2020-06-06 08:22:32 +00:00
}
}
TEST(logEI, loggingErrorOnInfoLevel) {
testing::internal::CaptureStderr();
logger->logEI({ .level = lvlInfo,
2020-06-19 21:28:13 +00:00
.name = "Info name",
});
2020-06-06 08:22:32 +00:00
auto str = testing::internal::GetCapturedStderr();
2020-06-16 07:44:19 +00:00
ASSERT_STREQ(str.c_str(), "\x1B[32;1minfo:\x1B[0m\x1B[34;1m --- Info name --- error-unit-test\x1B[0m\nInfo description\n");
2020-06-06 08:22:32 +00:00
}
TEST(logEI, loggingErrorOnTalkativeLevel) {
2020-06-07 13:24:49 +00:00
verbosity = lvlTalkative;
2020-06-06 08:22:32 +00:00
testing::internal::CaptureStderr();
logger->logEI({ .level = lvlTalkative,
.name = "Talkative name",
2020-06-19 21:28:13 +00:00
});
2020-06-06 08:22:32 +00:00
auto str = testing::internal::GetCapturedStderr();
2020-06-16 07:44:19 +00:00
ASSERT_STREQ(str.c_str(), "\x1B[32;1mtalk:\x1B[0m\x1B[34;1m --- Talkative name --- error-unit-test\x1B[0m\nTalkative description\n");
2020-06-06 08:22:32 +00:00
}
TEST(logEI, loggingErrorOnChattyLevel) {
2020-06-07 13:24:49 +00:00
verbosity = lvlChatty;
2020-06-06 08:22:32 +00:00
testing::internal::CaptureStderr();
logger->logEI({ .level = lvlChatty,
.name = "Chatty name",
2020-06-19 21:28:13 +00:00
});
2020-06-06 08:22:32 +00:00
auto str = testing::internal::GetCapturedStderr();
2020-06-16 07:44:19 +00:00
ASSERT_STREQ(str.c_str(), "\x1B[32;1mchat:\x1B[0m\x1B[34;1m --- Chatty name --- error-unit-test\x1B[0m\nTalkative description\n");
2020-06-06 08:22:32 +00:00
}
TEST(logEI, loggingErrorOnDebugLevel) {
2020-06-07 13:24:49 +00:00
verbosity = lvlDebug;
2020-06-06 08:22:32 +00:00
testing::internal::CaptureStderr();
logger->logEI({ .level = lvlDebug,
.name = "Debug name",
2020-06-19 21:28:13 +00:00
});
2020-06-06 08:22:32 +00:00
auto str = testing::internal::GetCapturedStderr();
2020-06-16 07:44:19 +00:00
ASSERT_STREQ(str.c_str(), "\x1B[33;1mdebug:\x1B[0m\x1B[34;1m --- Debug name --- error-unit-test\x1B[0m\nDebug description\n");
2020-06-06 08:22:32 +00:00
}
TEST(logEI, loggingErrorOnVomitLevel) {
2020-06-07 13:24:49 +00:00
verbosity = lvlVomit;
2020-06-06 08:22:32 +00:00
testing::internal::CaptureStderr();
logger->logEI({ .level = lvlVomit,
.name = "Vomit name",
2020-06-19 21:28:13 +00:00
});
2020-06-06 08:22:32 +00:00
auto str = testing::internal::GetCapturedStderr();
2020-06-16 07:44:19 +00:00
ASSERT_STREQ(str.c_str(), "\x1B[32;1mvomit:\x1B[0m\x1B[34;1m --- Vomit name --- error-unit-test\x1B[0m\nVomit description\n");
2020-06-06 08:22:32 +00:00
}
/* ----------------------------------------------------------------------------
* logError
* --------------------------------------------------------------------------*/
TEST(logError, logErrorWithoutHintOrCode) {
testing::internal::CaptureStderr();
logError({
.name = "name",
2020-06-19 21:28:13 +00:00
});
2020-06-06 08:22:32 +00:00
auto str = testing::internal::GetCapturedStderr();
2020-06-16 07:44:19 +00:00
ASSERT_STREQ(str.c_str(), "\x1B[31;1merror:\x1B[0m\x1B[34;1m --- name --- error-unit-test\x1B[0m\nerror description\n");
2020-06-06 08:22:32 +00:00
}
TEST(logError, logErrorWithPreviousAndNextLinesOfCode) {
SymbolTable testTable;
auto problem_file = testTable.create(test_file);
2020-06-06 08:22:32 +00:00
testing::internal::CaptureStderr();
logError({
.name = "error name",
.msg = HintFmt("this hint has %1% templated %2%!!",
2020-06-19 21:28:13 +00:00
"yellow",
"values"),
.errPos = Pos(foString, problem_file, 02, 13),
});
2020-06-06 08:22:32 +00:00
auto str = testing::internal::GetCapturedStderr();
ASSERT_STREQ(str.c_str(), "\x1B[31;1merror:\x1B[0m\x1B[34;1m --- error name --- error-unit-test\x1B[0m\n\x1B[34;1mat: \x1B[33;1m(2:13)\x1B[34;1m from string\x1B[0m\n\nerror with code lines\n\n 1| previous line of code\n 2| this is the problem line of code\n | \x1B[31;1m^\x1B[0m\n 3| next line of code\n\nthis hint has \x1B[33;1myellow\x1B[0m templated \x1B[33;1mvalues\x1B[0m!!\n");
2020-06-06 08:22:32 +00:00
}
TEST(logError, logErrorWithInvalidFile) {
2020-06-06 08:22:32 +00:00
SymbolTable testTable;
auto problem_file = testTable.create("invalid filename");
2020-06-06 08:22:32 +00:00
testing::internal::CaptureStderr();
logError({
.name = "error name",
.msg = HintFmt("this hint has %1% templated %2%!!",
2020-06-19 21:28:13 +00:00
"yellow",
"values"),
.errPos = Pos(foFile, problem_file, 02, 13)
});
2020-06-06 08:22:32 +00:00
auto str = testing::internal::GetCapturedStderr();
2020-12-22 15:23:57 +00:00
ASSERT_STREQ(str.c_str(), "\x1B[31;1merror:\x1B[0m\x1B[34;1m --- error name --- error-unit-test\x1B[0m\n\x1B[34;1mat: \x1B[33;1m(2:13)\x1B[34;1m in file: \x1B[0minvalid filename\n\nerror without any code lines.\n\nthis hint has \x1B[33;1myellow\x1B[0m templated \x1B[33;1mvalues\x1B[0m!!\n");
2020-06-06 08:22:32 +00:00
}
TEST(logError, logErrorWithOnlyHintAndName) {
testing::internal::CaptureStderr();
logError({
.name = "error name",
.msg = HintFmt("hint %1%", "only"),
});
2020-06-06 08:22:32 +00:00
auto str = testing::internal::GetCapturedStderr();
ASSERT_STREQ(str.c_str(), "\x1B[31;1merror:\x1B[0m\x1B[34;1m --- error name --- error-unit-test\x1B[0m\nhint \x1B[33;1monly\x1B[0m\n");
2020-06-06 08:22:32 +00:00
}
/* ----------------------------------------------------------------------------
* logWarning
* --------------------------------------------------------------------------*/
TEST(logWarning, logWarningWithNameDescriptionAndHint) {
testing::internal::CaptureStderr();
logWarning({
2020-06-19 21:28:13 +00:00
.name = "name",
.msg = HintFmt("there was a %1%", "warning"),
2020-06-19 21:28:13 +00:00
});
2020-06-06 08:22:32 +00:00
auto str = testing::internal::GetCapturedStderr();
ASSERT_STREQ(str.c_str(), "\x1B[33;1mwarning:\x1B[0m\x1B[34;1m --- name --- error-unit-test\x1B[0m\nwarning description\n\nthere was a \x1B[33;1mwarning\x1B[0m\n");
2020-06-06 08:22:32 +00:00
}
TEST(logWarning, logWarningWithFileLineNumAndCode) {
SymbolTable testTable;
auto problem_file = testTable.create(test_file);
2020-06-06 08:22:32 +00:00
testing::internal::CaptureStderr();
logWarning({
.name = "warning name",
.msg = HintFmt("this hint has %1% templated %2%!!",
2020-06-19 21:28:13 +00:00
"yellow",
"values"),
.errPos = Pos(foStdin, problem_file, 2, 13),
});
2020-06-06 08:22:32 +00:00
auto str = testing::internal::GetCapturedStderr();
ASSERT_STREQ(str.c_str(), "\x1B[33;1mwarning:\x1B[0m\x1B[34;1m --- warning name --- error-unit-test\x1B[0m\n\x1B[34;1mat: \x1B[33;1m(2:13)\x1B[34;1m from stdin\x1B[0m\n\nwarning description\n\n 1| previous line of code\n 2| this is the problem line of code\n | \x1B[31;1m^\x1B[0m\n 3| next line of code\n\nthis hint has \x1B[33;1myellow\x1B[0m templated \x1B[33;1mvalues\x1B[0m!!\n");
2020-06-06 08:22:32 +00:00
}
2020-06-19 20:54:41 +00:00
/* ----------------------------------------------------------------------------
* traces
* --------------------------------------------------------------------------*/
TEST(addTrace, showTracesWithShowTrace) {
SymbolTable testTable;
auto problem_file = testTable.create(test_file);
auto oneliner_file = testTable.create(one_liner);
2020-07-06 16:51:48 +00:00
auto invalidfilename = testTable.create("invalid filename");
auto e = AssertionError(ErrorInfo {
.name = "wat",
.msg = HintFmt("it has been %1% days since our last error", "zero"),
.errPos = Pos(foString, problem_file, 2, 13),
});
e.addTrace(Pos(foStdin, oneliner_file, 1, 19), "while trying to compute %1%", 42);
2020-07-01 16:37:31 +00:00
e.addTrace(std::nullopt, "while doing something without a %1%", "pos");
2020-07-06 16:51:48 +00:00
e.addTrace(Pos(foFile, invalidfilename, 100, 1), "missing %s", "nix file");
testing::internal::CaptureStderr();
2020-07-02 15:04:31 +00:00
loggerSettings.showTrace.assign(true);
logError(e.info());
auto str = testing::internal::GetCapturedStderr();
2020-12-22 15:23:57 +00:00
ASSERT_STREQ(str.c_str(), "\x1B[31;1merror:\x1B[0m\x1B[34;1m --- AssertionError --- error-unit-test\x1B[0m\n\x1B[34;1mat: \x1B[33;1m(2:13)\x1B[34;1m from string\x1B[0m\n\nshow-traces\n\n 1| previous line of code\n 2| this is the problem line of code\n | \x1B[31;1m^\x1B[0m\n 3| next line of code\n\nit has been \x1B[33;1mzero\x1B[0m days since our last error\n\x1B[34;1m---- show-trace ----\x1B[0m\n\x1B[34;1mtrace: \x1B[0mwhile trying to compute \x1B[33;1m42\x1B[0m\n\x1B[34;1mat: \x1B[33;1m(1:19)\x1B[34;1m from stdin\x1B[0m\n\n 1| this is the other problem line of code\n | \x1B[31;1m^\x1B[0m\n\n\x1B[34;1mtrace: \x1B[0mwhile doing something without a \x1B[33;1mpos\x1B[0m\n\x1B[34;1mtrace: \x1B[0mmissing \x1B[33;1mnix file\x1B[0m\n\x1B[34;1mat: \x1B[33;1m(100:1)\x1B[34;1m in file: \x1B[0minvalid filename\n");
}
TEST(addTrace, hideTracesWithoutShowTrace) {
SymbolTable testTable;
auto problem_file = testTable.create(test_file);
auto oneliner_file = testTable.create(one_liner);
2020-07-06 16:51:48 +00:00
auto invalidfilename = testTable.create("invalid filename");
auto e = AssertionError(ErrorInfo {
.name = "wat",
.msg = HintFmt("it has been %1% days since our last error", "zero"),
.errPos = Pos(foString, problem_file, 2, 13),
});
e.addTrace(Pos(foStdin, oneliner_file, 1, 19), "while trying to compute %1%", 42);
2020-07-01 16:37:31 +00:00
e.addTrace(std::nullopt, "while doing something without a %1%", "pos");
2020-07-06 16:51:48 +00:00
e.addTrace(Pos(foFile, invalidfilename, 100, 1), "missing %s", "nix file");
testing::internal::CaptureStderr();
2020-07-02 15:04:31 +00:00
loggerSettings.showTrace.assign(false);
logError(e.info());
auto str = testing::internal::GetCapturedStderr();
2020-07-06 16:51:48 +00:00
ASSERT_STREQ(str.c_str(), "\x1B[31;1merror:\x1B[0m\x1B[34;1m --- AssertionError --- error-unit-test\x1B[0m\n\x1B[34;1mat: \x1B[33;1m(2:13)\x1B[34;1m from string\x1B[0m\n\nhide traces\n\n 1| previous line of code\n 2| this is the problem line of code\n | \x1B[31;1m^\x1B[0m\n 3| next line of code\n\nit has been \x1B[33;1mzero\x1B[0m days since our last error\n");
}
2020-07-06 16:51:48 +00:00
/* ----------------------------------------------------------------------------
* HintFmt
2020-06-19 20:54:41 +00:00
* --------------------------------------------------------------------------*/
TEST(HintFmt, percentStringWithoutArgs) {
2020-06-19 20:54:41 +00:00
2020-06-19 21:28:13 +00:00
const char *teststr = "this is 100%s correct!";
2020-06-19 20:54:41 +00:00
2020-06-19 22:58:12 +00:00
ASSERT_STREQ(
HintFmt(teststr).str().c_str(),
2020-06-19 22:58:12 +00:00
teststr);
2020-06-19 20:54:41 +00:00
2020-06-19 21:28:13 +00:00
}
2020-06-19 20:54:41 +00:00
TEST(HintFmt, fmtToHintfmt) {
2020-06-19 22:46:49 +00:00
2020-06-19 22:58:12 +00:00
ASSERT_STREQ(
HintFmt(fmt("the color of this this text is %1%", "not yellow")).str().c_str(),
2020-06-19 22:58:12 +00:00
"the color of this this text is not yellow");
2020-06-19 22:46:49 +00:00
}
TEST(HintFmt, tooFewArguments) {
2020-06-19 20:54:41 +00:00
2020-06-19 21:28:13 +00:00
ASSERT_STREQ(
HintFmt("only one arg %1% %2%", "fulfilled").str().c_str(),
2021-09-14 08:38:10 +00:00
"only one arg " ANSI_WARNING "fulfilled" ANSI_NORMAL " ");
2020-06-19 21:28:13 +00:00
}
TEST(HintFmt, tooManyArguments) {
2020-06-19 21:28:13 +00:00
ASSERT_STREQ(
HintFmt("what about this %1% %2%", "%3%", "one", "two").str().c_str(),
2021-09-14 08:38:10 +00:00
"what about this " ANSI_WARNING "%3%" ANSI_NORMAL " " ANSI_YELLOW "one" ANSI_NORMAL);
2020-06-19 21:28:13 +00:00
}
2020-06-30 17:01:46 +00:00
/* ----------------------------------------------------------------------------
* ErrPos
* --------------------------------------------------------------------------*/
TEST(errpos, invalidPos) {
// contains an invalid symbol, which we should not dereference!
Pos invalid;
// constructing without access violation.
ErrPos ep(invalid);
2020-06-30 17:01:46 +00:00
// assignment without access violation.
ep = invalid;
}
2020-06-06 08:22:32 +00:00
}
Improve error formatting Changes: * The divider lines are gone. These were in practice a bit confusing, in particular with --show-trace or --keep-going, since then there were multiple lines, suggesting a start/end which wasn't the case. * Instead, multi-line error messages are now indented to align with the prefix (e.g. "error: "). * The 'description' field is gone since we weren't really using it. * 'hint' is renamed to 'msg' since it really wasn't a hint. * The error is now printed *before* the location info. * The 'name' field is no longer printed since most of the time it wasn't very useful since it was just the name of the exception (like EvalError). Ideally in the future this would be a unique, easily googleable error ID (like rustc). * "trace:" is now just "…". This assumes error contexts start with something like "while doing X". Example before: error: --- AssertionError ---------------------------------------------------------------------------------------- nix at: (7:7) in file: /home/eelco/Dev/nixpkgs/pkgs/applications/misc/hello/default.nix 6| 7| x = assert false; 1; | ^ 8| assertion 'false' failed ----------------------------------------------------- show-trace ----------------------------------------------------- trace: while evaluating the attribute 'x' of the derivation 'hello-2.10' at: (192:11) in file: /home/eelco/Dev/nixpkgs/pkgs/stdenv/generic/make-derivation.nix 191| // (lib.optionalAttrs (!(attrs ? name) && attrs ? pname && attrs ? version)) { 192| name = "${attrs.pname}-${attrs.version}"; | ^ 193| } // (lib.optionalAttrs (stdenv.hostPlatform != stdenv.buildPlatform && !dontAddHostSuffix && (attrs ? name || (attrs ? pname && attrs ? version)))) { Example after: error: assertion 'false' failed at: (7:7) in file: /home/eelco/Dev/nixpkgs/pkgs/applications/misc/hello/default.nix 6| 7| x = assert false; 1; | ^ 8| … while evaluating the attribute 'x' of the derivation 'hello-2.10' at: (192:11) in file: /home/eelco/Dev/nixpkgs/pkgs/stdenv/generic/make-derivation.nix 191| // (lib.optionalAttrs (!(attrs ? name) && attrs ? pname && attrs ? version)) { 192| name = "${attrs.pname}-${attrs.version}"; | ^ 193| } // (lib.optionalAttrs (stdenv.hostPlatform != stdenv.buildPlatform && !dontAddHostSuffix && (attrs ? name || (attrs ? pname && attrs ? version)))) {
2021-01-20 23:27:36 +00:00
#endif