diff --git a/doc/manual/rl-next/user-traces.md b/doc/manual/rl-next/user-traces.md new file mode 100644 index 000000000..97c8d50c4 --- /dev/null +++ b/doc/manual/rl-next/user-traces.md @@ -0,0 +1,23 @@ +--- +synopsis: "Always print frames from `addErrorContext` in error traces" +cls: [5847] +category: "Improvements" +credits: [blokyk] +issues: [] +--- + +The [`builtins.addErrorContext`](@docroot@/language/builtins.md#builtins-addErrorContext) +function allows an author to add artificial stack frames with custom messages to +help end-users understand the context of an error and the path the code took to +get there, without having to read and understand the original source code. A +particularly notable user of this is the Nixpkgs module system, which adds +custom frames detailing what option it's evaluating or which definition it's +looking at. + +However, previously, these frames would end up treated just as any other, +meaning they would most often not be visible without `--show-trace`; yet, using +`--show-trace`, they would be drowned out in the noise of the hundreds of other +frames, rendering them just as unusable. + +With this change, these frames are now unconditionally shown, even without +`--show-trace`, which makes basic error traces much more informative. diff --git a/lix/libexpr/builtins/addErrorContext.md b/lix/libexpr/builtins/addErrorContext.md index 6d99659bb..8a169aa67 100644 --- a/lix/libexpr/builtins/addErrorContext.md +++ b/lix/libexpr/builtins/addErrorContext.md @@ -23,70 +23,14 @@ countDown 2 Then, evaluating the file will give the following stack trace: ```console -$ nix-instantiate --show-trace err.nix +$ nix-instantiate err.nix error: - … from call site - at /home/plop/git.lix.systems/lix-project/lix/err.nix:9:1: - 8| in - 9| countDown 2 - | ^ - 10| - - … while calling 'countDown' - at /home/plop/git.lix.systems/lix-project/lix/err.nix:3:5: - 2| countDown = - 3| n: - | ^ - 4| if n == 0 then - - … while calling the 'addErrorContext' builtin - at /home/plop/git.lix.systems/lix-project/lix/err.nix:7:7: - 6| else - 7| builtins.addErrorContext "while counting down; n = ${toString n}" ("x" + countDown (n - 1)); - | ^ - 8| in - … while counting down; n = 2 - … from call site - at /home/plop/git.lix.systems/lix-project/lix/err.nix:7:80: - 6| else - 7| builtins.addErrorContext "while counting down; n = ${toString n}" ("x" + countDown (n - 1)); - | ^ - 8| in - - … while calling 'countDown' - at /home/plop/git.lix.systems/lix-project/lix/err.nix:3:5: - 2| countDown = - 3| n: - | ^ - 4| if n == 0 then - - … while calling the 'addErrorContext' builtin - at /home/plop/git.lix.systems/lix-project/lix/err.nix:7:7: - 6| else - 7| builtins.addErrorContext "while counting down; n = ${toString n}" ("x" + countDown (n - 1)); - | ^ - 8| in - … while counting down; n = 1 - … from call site - at /home/plop/git.lix.systems/lix-project/lix/err.nix:7:80: - 6| else - 7| builtins.addErrorContext "while counting down; n = ${toString n}" ("x" + countDown (n - 1)); - | ^ - 8| in - - … while calling 'countDown' - at /home/plop/git.lix.systems/lix-project/lix/err.nix:3:5: - 2| countDown = - 3| n: - | ^ - 4| if n == 0 then - … caused by explicit throw - at /home/plop/git.lix.systems/lix-project/lix/err.nix:5:7: + at err.nix:5:7: 4| if n == 0 then 5| throw "kaboom" | ^ diff --git a/lix/libexpr/eval.cc b/lix/libexpr/eval.cc index e9d24f941..7d24ed92d 100644 --- a/lix/libexpr/eval.cc +++ b/lix/libexpr/eval.cc @@ -1195,12 +1195,18 @@ Value EvalState::callFunction(Value & fun, std::span args, const PosIdx p // was being evaluated and an explicit thrown error. if (fn->name == "throw" && !e.hasTrace()) { e.addTrace(ctx.positions[pos], "caused by explicit %s", "throw"); - } else { + } + // otherwise, print a trace of this builtin, as long as it isn't + // a 'addErrorContext' call (which would just create noise) + else if (fn->name != "addErrorContext") + { e.addTrace(ctx.positions[pos], "while calling the '%s' builtin", fn->name); } throw; } catch (Error & e) { - e.addTrace(ctx.positions[pos], "while calling the '%1%' builtin", fn->name); + if (fn->name != "addErrorContext") { + e.addTrace(ctx.positions[pos], "while calling the '%1%' builtin", fn->name); + } throw; } @@ -1246,7 +1252,9 @@ Value EvalState::callFunction(Value & fun, std::span args, const PosIdx p // so the debugger allows to inspect the wrong parameters passed to the builtin. vCur = fn->fun(*this, vArgs.data()); } catch (Error & e) { - e.addTrace(ctx.positions[pos], "while calling the '%1%' builtin", fn->name); + if (fn->name != "addErrorContext") { + e.addTrace(ctx.positions[pos], "while calling the '%1%' builtin", fn->name); + } throw; } } diff --git a/lix/libexpr/primops.cc b/lix/libexpr/primops.cc index b12061c1c..000f6774d 100644 --- a/lix/libexpr/primops.cc +++ b/lix/libexpr/primops.cc @@ -1,3 +1,4 @@ +#include "libutil/error-trace.hh" #include "lix/libutil/archive.hh" #include "lix/libstore/derivations.hh" #include "lix/libexpr/eval.hh" @@ -699,7 +700,7 @@ static Value prim_addErrorContext(EvalState & state, Value ** args) auto message = state.coerceToString(noPos, *args[0], context, "while evaluating the error message passed to builtins.addErrorContext", StringCoercionMode::Strict, false).toOwned(); - e.addTrace(nullptr, HintFmt(message)); + e.addTrace(nullptr, HintFmt(message), TraceKind::UserTrace); throw; } } diff --git a/lix/libutil/error-trace.hh b/lix/libutil/error-trace.hh index de660b681..5168187dc 100644 --- a/lix/libutil/error-trace.hh +++ b/lix/libutil/error-trace.hh @@ -12,6 +12,15 @@ namespace nix { +/** @brief The kind/origin of a trace frame + * + * Right now, this is mainly used to prioritize certain traces above others. + */ +enum TraceKind { + UnknownTrace, + UserTrace, +}; + struct Pos; /** @brief Information for a @ref Trace that encountered a derivation. @@ -32,13 +41,12 @@ struct DrvTrace operator<=>(DrvTrace const & lhs, DrvTrace const & rhs) noexcept = default; }; -struct Trace; - struct Trace { std::shared_ptr pos; HintFmt hint; std::optional drvTrace; + TraceKind kind = UnknownTrace; /** Construct a Trace and canned format message assuming a derivation's * position and name. diff --git a/lix/libutil/error.cc b/lix/libutil/error.cc index b90573d74..3855a951f 100644 --- a/lix/libutil/error.cc +++ b/lix/libutil/error.cc @@ -18,9 +18,9 @@ namespace nix { -void BaseError::addTrace(std::shared_ptr && e, HintFmt hint) +void BaseError::addTrace(std::shared_ptr && e, HintFmt hint, TraceKind kind) { - err.traces.push_front(Trace { .pos = std::move(e), .hint = hint }); + err.traces.push_front(Trace{.pos = std::move(e), .hint = hint, .kind = kind}); } // c++ std::exception descendants must have a 'const char* what()' function. @@ -150,12 +150,13 @@ void printTrace( count++; } -void printSkippedTracesMaybe( +void printDuplicateTracesMaybe( std::ostream & output, const std::string_view & indent, size_t & count, std::vector & skippedTraces, - std::set tracesSeen) + std::set tracesSeen +) { if (skippedTraces.size() > 0) { // If we only skipped a few frames, print them out normally; @@ -371,31 +372,39 @@ std::ostream & showErrorInfo(std::ostream & out, const ErrorInfo & einfo, bool s // omitted`. std::set tracesSeen; // A consecutive sequence of stack traces that are all in `tracesSeen`. - std::vector skippedTraces; + std::vector duplicatedTraces; size_t count = 0; + bool didSkipTrace = false; + for (const auto & trace : einfo.traces) { if (trace.hint.str().empty()) continue; - if (!showTrace && count > 3) { - oss << "\n" << ANSI_WARNING "(stack trace truncated; use '--show-trace' to show the full trace)" ANSI_NORMAL << "\n"; - break; + if (!showTrace && count > 3 && trace.kind != TraceKind::UserTrace) { + didSkipTrace = true; + continue; // continue so that we still print later user traces } if (tracesSeen.count(trace)) { - skippedTraces.push_back(trace); + duplicatedTraces.push_back(trace); continue; } tracesSeen.insert(trace); - printSkippedTracesMaybe(oss, ellipsisIndent, count, skippedTraces, tracesSeen); + printDuplicateTracesMaybe(oss, ellipsisIndent, count, duplicatedTraces, tracesSeen); count++; printTrace(oss, ellipsisIndent, count, trace); } - printSkippedTracesMaybe(oss, ellipsisIndent, count, skippedTraces, tracesSeen); + printDuplicateTracesMaybe(oss, ellipsisIndent, count, duplicatedTraces, tracesSeen); + if (didSkipTrace) { + oss << "\n" + << ANSI_WARNING + "(stack trace truncated; use '--show-trace' to show the full trace)" ANSI_NORMAL + << "\n"; + } oss << "\n" << prefix; } diff --git a/lix/libutil/error.hh b/lix/libutil/error.hh index 2e1d8dfee..090bcf41d 100644 --- a/lix/libutil/error.hh +++ b/lix/libutil/error.hh @@ -199,7 +199,7 @@ public: addTrace(std::move(e), HintFmt(std::string(fs), args...)); } - void addTrace(std::shared_ptr && e, HintFmt hint); + void addTrace(std::shared_ptr && e, HintFmt hint, TraceKind kind = UnknownTrace); bool hasTrace() const { return !err.traces.empty(); } diff --git a/tests/functional2/lang/err_context/__init__.py b/tests/functional2/lang/err_context/__init__.py deleted file mode 100644 index e69de29bb..000000000 diff --git a/tests/functional2/lang/err_context/eval-fail-deep.err.exp b/tests/functional2/lang/err_context/eval-fail-deep.err.exp new file mode 100644 index 000000000..2a6d4b545 --- /dev/null +++ b/tests/functional2/lang/err_context/eval-fail-deep.err.exp @@ -0,0 +1,24 @@ +error: + … computing fib(4) + + … while calling the 'add' builtin + at /pwd/in.nix:7:8: + 6| # note: we use builtins.add explicitly because it creates more frames than (+) + 7| (builtins.add (fib (n - 1)) (fib (n - 2))); + | ^ + 8| in + + … computing fib(3) + + … computing fib(2) + + … computing fib(1) + + (stack trace truncated; use '--show-trace' to show the full trace) + + error: assertion failed + at /pwd/in.nix:3:5: + 2| fib = n: + 3| assert n > 0; + | ^ + 4| builtins.addErrorContext diff --git a/tests/functional2/lang/err_context/eval-fail.err.exp b/tests/functional2/lang/err_context/eval-fail.err.exp new file mode 100644 index 000000000..2680c9aed --- /dev/null +++ b/tests/functional2/lang/err_context/eval-fail.err.exp @@ -0,0 +1,10 @@ +error: + … Hello + + … caused by explicit throw + at /pwd/in.nix:1:35: + 1| builtins.addErrorContext "Hello" (throw "Foo") + | ^ + 2| + + error: Foo diff --git a/tests/functional2/lang/err_context/in-deep.nix b/tests/functional2/lang/err_context/in-deep.nix new file mode 100644 index 000000000..006cc4b90 --- /dev/null +++ b/tests/functional2/lang/err_context/in-deep.nix @@ -0,0 +1,9 @@ +let + fib = n: + assert n > 0; + builtins.addErrorContext + "computing fib(${toString n})" + # note: we use builtins.add explicitly because it creates more frames than (+) + (builtins.add (fib (n - 1)) (fib (n - 2))); +in + fib 4 diff --git a/tests/functional2/lang/err_context/in.nix b/tests/functional2/lang/err_context/in.nix new file mode 100644 index 000000000..b79f2daa4 --- /dev/null +++ b/tests/functional2/lang/err_context/in.nix @@ -0,0 +1 @@ +builtins.addErrorContext "Hello" (throw "Foo") diff --git a/tests/functional2/lang/err_context/test.toml b/tests/functional2/lang/err_context/test.toml new file mode 100644 index 000000000..5da654753 --- /dev/null +++ b/tests/functional2/lang/err_context/test.toml @@ -0,0 +1,8 @@ +[[test]] +runner = "eval-fail" +flags = ["--no-show-trace"] + +[[test]] +runner = "eval-fail" +in = "in-deep.nix" +flags = ["--no-show-trace"] diff --git a/tests/functional2/lang/err_context/test_err_context.py b/tests/functional2/lang/err_context/test_err_context.py deleted file mode 100644 index e3764deff..000000000 --- a/tests/functional2/lang/err_context/test_err_context.py +++ /dev/null @@ -1,14 +0,0 @@ -from testlib.fixtures.nix import Nix - -import pytest - -pytestmark = pytest.mark.no_daemon - - -def test_err_context(nix: Nix): - # the lang test framework doesn't check this folder, as there is a custom test in here - # it won't scream about missing an `in.nix` or .exp files - result = nix.nix_instantiate( - ["--show-trace", "--eval", "-E", 'builtins.addErrorContext "Hello" (throw "Foo")'] - ).run() - assert "Hello" in result.expect(1).stderr_s