Do not skip any stack frames when `--show-trace` is given #10066

9999years · 2024-02-23T01:54:34Z

Motivation

I experienced a very confusing error from this code path:

Lines 1554 to 1558 in 6a5210f

    
           error<TypeError>("function '%1%' called with unexpected argument '%2%'", 
        
                            (lambda.name ? std::string(symbols[lambda.name]) : "anonymous lambda"), 
        
                            symbols[i.name]) 
        
               .atPos(lambda.pos) 
        
               .withTrace(pos, "from call site")

Even with --show-trace, it wouldn't reveal the call site that included the unexpected argument. (Reproducer repository here.)

After this PR, the stack trace includes the relevant frame:

      … while calling a functor (an attribute set with a '__functor' attribute)
         at /nix/store/2sq3qdc86a5si4k0ddc1ffpz4ckfva8a-source/pkgs/development/ruby-modules/bundled-common/default.nix:50:10:
           49|     if hasBundler then gems.bundler
           50|     else defs.bundler.override (attrs: { inherit ruby; });
             |          ^
           51|

Context

Currently, there is a somewhat strange printing logic for stack frames:

nix/src/libutil/error.cc

Line 387 in 6a5210f

if (frameOnly && !trace.frame) continue;

When a stack frame with frame == true is seen, the following stack frames with frame == false are silently skipped, even with --show-trace.

Almost all traces have frame == false (see below), so this changes the behavior in subtle ways when one of the few frame == true frames is seen.

I also suspect that this was intended to work in the reverse order; the PR that added this concept of skipping frames was #6204, opened in March 2022, merged, reverted, and then re-applied in January 2023. Meanwhile, #7334 was opened in November 2022 and merged in December 2022, reversing the order stack frames are printed in. (See e.g. #9962 (comment) for more unintentional formatting changes as a result of this.)

EDIT: This suspicion is backed up by the comment here which implies that the internal builtins.derivationStrict frames are hidden (which is not true).

Closes libutil/libexpr: Remove frame trace distinction #9772

Notes

Only the first commit 9999years@040874e is necessary.

Priorities and Process

Add 👍 to pull requests you find important.

The Nix maintainer team uses a GitHub project board to schedule and track reviews.

9999years · 2024-02-23T01:57:04Z

Ping @layus.

9999years · 2024-02-23T02:17:01Z

Here's the diff of the stack traces, by the way:

              |         ^
           100|           ++ (derivationArgs.passAsFile or [ ]);
 
+       … while evaluating the attribute 'passAsFile'
+         at /nix/store/mc6zz3405pw25x7h1xkhb2xx7a3a2kpm-source/pkgs/build-support/buildenv/default.nix:76:5:
+           75|     # XXX: The size is somewhat arbitrary
+           76|     passAsFile = if builtins.stringLength pkgs >= 128*1024 then [ "pkgs" ] else [ ];
+             |     ^
+           77|   }
+
+       … while evaluating a branch condition
+         at /nix/store/mc6zz3405pw25x7h1xkhb2xx7a3a2kpm-source/pkgs/build-support/buildenv/default.nix:76:18:
+           75|     # XXX: The size is somewhat arbitrary
+           76|     passAsFile = if builtins.stringLength pkgs >= 128*1024 then [ "pkgs" ] else [ ];
+             |                  ^
+           77|   }
+
+       … in the argument of the not operator
+         at /nix/store/mc6zz3405pw25x7h1xkhb2xx7a3a2kpm-source/pkgs/build-support/buildenv/default.nix:76:48:
+           75|     # XXX: The size is somewhat arbitrary
+           76|     passAsFile = if builtins.stringLength pkgs >= 128*1024 then [ "pkgs" ] else [ ];
+             |                                                ^
+           77|   }
+
+       … while calling the 'lessThan' builtin
+         at /nix/store/mc6zz3405pw25x7h1xkhb2xx7a3a2kpm-source/pkgs/build-support/buildenv/default.nix:76:48:
+           75|     # XXX: The size is somewhat arbitrary
+           76|     passAsFile = if builtins.stringLength pkgs >= 128*1024 then [ "pkgs" ] else [ ];
+             |                                                ^
+           77|   }
+
+       … while calling the 'stringLength' builtin
+         at /nix/store/mc6zz3405pw25x7h1xkhb2xx7a3a2kpm-source/pkgs/build-support/buildenv/default.nix:76:21:
+           75|     # XXX: The size is somewhat arbitrary
+           76|     passAsFile = if builtins.stringLength pkgs >= 128*1024 then [ "pkgs" ] else [ ];
+             |                     ^
+           77|   }
+
+       … while calling the 'toJSON' builtin
+         at /nix/store/mc6zz3405pw25x7h1xkhb2xx7a3a2kpm-source/pkgs/build-support/buildenv/default.nix:58:12:
+           57|             nativeBuildInputs buildInputs;
+           58|     pkgs = builtins.toJSON (map (drv: {
+             |            ^
+           59|       paths =
+
+       … while evaluating list element at index 0
+
+       … while evaluating attribute 'paths'
+         at /nix/store/mc6zz3405pw25x7h1xkhb2xx7a3a2kpm-source/pkgs/build-support/buildenv/default.nix:59:7:
+           58|     pkgs = builtins.toJSON (map (drv: {
+           59|       paths =
+             |       ^
+           60|         # First add the usual output(s): respect if user has chosen explicitly,
+
+       … while evaluating a branch condition
+         at /nix/store/mc6zz3405pw25x7h1xkhb2xx7a3a2kpm-source/pkgs/build-support/buildenv/default.nix:64:10:
+           63|         # aren't expected to have multiple outputs.
+           64|         (if (! drv ? outputSpecified || ! drv.outputSpecified)
+             |          ^
+           65|             && drv.meta.outputsToInstall or null != null
+
+       … in the left operand of the AND (&&) operator
+         at /nix/store/mc6zz3405pw25x7h1xkhb2xx7a3a2kpm-source/pkgs/build-support/buildenv/default.nix:65:13:
+           64|         (if (! drv ? outputSpecified || ! drv.outputSpecified)
+           65|             && drv.meta.outputsToInstall or null != null
+             |             ^
+           66|           then map (outName: drv.${outName}) drv.meta.outputsToInstall
+
+       … in the left operand of the OR (||) operator
+         at /nix/store/mc6zz3405pw25x7h1xkhb2xx7a3a2kpm-source/pkgs/build-support/buildenv/default.nix:64:38:
+           63|         # aren't expected to have multiple outputs.
+           64|         (if (! drv ? outputSpecified || ! drv.outputSpecified)
+             |                                      ^
+           65|             && drv.meta.outputsToInstall or null != null
+
+       … in the argument of the not operator
+         at /nix/store/mc6zz3405pw25x7h1xkhb2xx7a3a2kpm-source/pkgs/build-support/buildenv/default.nix:64:16:
+           63|         # aren't expected to have multiple outputs.
+           64|         (if (! drv ? outputSpecified || ! drv.outputSpecified)
+             |                ^
+           65|             && drv.meta.outputsToInstall or null != null
+
+       … while calling a functor (an attribute set with a '__functor' attribute)
+         at /nix/store/mc6zz3405pw25x7h1xkhb2xx7a3a2kpm-source/pkgs/development/ruby-modules/bundled-common/default.nix:50:10:
+           49|     if hasBundler then gems.bundler
+           50|     else defs.bundler.override (attrs: { inherit ruby; });
+             |          ^
+           51|
+
        … from call site
          at /nix/store/mc6zz3405pw25x7h1xkhb2xx7a3a2kpm-source/lib/trivial.nix:440:7:
           439|     { # TODO: Should we add call-time "type" checking like built in?
@@ -30,6 +116,13 @@
              |                                  ^
           105|       # Change the result of the function call by applying g to it
 
+       … while calling a functor (an attribute set with a '__functor' attribute)
+         at /nix/store/mc6zz3405pw25x7h1xkhb2xx7a3a2kpm-source/lib/customisation.nix:104:43:
+          103|       # Re-call the function but with different arguments
+          104|       overrideArgs = mirrorArgs (newArgs: makeOverridable f (overrideWith newArgs));
+             |                                           ^
+          105|       # Change the result of the function call by applying g to it
+
        … from call site
          at /nix/store/mc6zz3405pw25x7h1xkhb2xx7a3a2kpm-source/lib/trivial.nix:440:7:
           439|     { # TODO: Should we add call-time "type" checking like built in?
@@ -44,6 +137,27 @@
              |                 ^
            97|     let
 
+       … while evaluating a branch condition
+         at /nix/store/mc6zz3405pw25x7h1xkhb2xx7a3a2kpm-source/lib/customisation.nix:108:7:
+          107|     in
+          108|       if isAttrs result then
+             |       ^
+          109|         result // {
+
+       … while calling the 'isAttrs' builtin
+         at /nix/store/mc6zz3405pw25x7h1xkhb2xx7a3a2kpm-source/lib/customisation.nix:108:10:
+          107|     in
+          108|       if isAttrs result then
+             |          ^
+          109|         result // {
+
+       … from call site
+         at /nix/store/mc6zz3405pw25x7h1xkhb2xx7a3a2kpm-source/lib/customisation.nix:98:16:
+           97|     let
+           98|       result = f origArgs;
+             |                ^
+           99|
+
        error: function 'anonymous lambda' called with unexpected argument 'ruby'
        at /nix/store/zpd0gmaic148sqyjn9f0ymsdk52ak9z9-source/packages/myNamespace/bundler.nix:1:1:
             1| {

9999years · 2024-02-23T02:29:26Z

Which code paths set `frame = true`?

In all of Nix, there are six code paths that create a frame with frame == true, triggering this confusing behavior.

The first is here, for while calling lambda frames:

nix/src/libexpr/eval.cc

Lines 1584 to 1591 in 6a5210f

    
           addErrorTrace( 
        
               e, 
        
               lambda.pos, 
        
               "while calling %s", 
        
               lambda.name 
        
               ? concatStrings("'", symbols[lambda.name], "'") 
        
               : "anonymous lambda", 
        
               true);

The second is right below it, for from call site frames:

nix/src/libexpr/eval.cc

Line 1592 in 6a5210f

if (pos) addErrorTrace(e, pos, "from call site%s", "", true);

The fourth is from the builtins.addErrorContext primop:

nix/src/libexpr/primops.cc

Lines 811 to 814 in 6a5210f

    
           auto message = state.coerceToString(pos, *args[0], context, 
        
                   "while evaluating the error message passed to builtins.addErrorContext", 
        
                   false, false).toOwned(); 
        
           e.addTrace(nullptr, HintFmt(message), true);

The fifth is in builtins.derivationStrict:

nix/src/libexpr/primops.cc

Lines 1075 to 1078 in 6a5210f

    
           e.addTrace(nullptr, HintFmt( 
        
                   "while evaluating derivation '%s'\n" 
        
                   "  whose name attribute is located at %s", 
        
                   drvName, pos), true);

The sixth and final usage is also in builtins.derivationStrict, for while evaluating attribute '%1%' of derivation '%2%' frames:

nix/src/libexpr/primops.cc

Lines 1235 to 1237 in 6a5210f

    
           e.addTrace(state.positions[i->pos], 
        
               HintFmt("while evaluating attribute '%1%' of derivation '%2%'", key, drvName), 
        
               true);

roberth · 2024-02-23T10:34:23Z

I've previously suspected that this was broken, but hadn't encountered such a large difference yet.
Maybe it worked better when the trace was processed and printed in reverse order, but I hadn't found evidence for that yet.

I'm inclined to just go ahead with this. Your PR strengthens my belief from before.

roberth

Not sure about the variadic commit, but happy to merge the rest.

Perhaps the last commit could be fixupped into the first one?

roberth · 2024-02-23T10:43:42Z

src/libexpr/eval.cc

+template<typename... Args>
+void EvalState::addErrorTrace(Error & e, const Args & ... formatArgs) const
 {
-    e.addTrace(nullptr, s, s2);
+    e.addTrace(nullptr, HintFmt(formatArgs...));
 }

-void EvalState::addErrorTrace(Error & e, const PosIdx pos, const char * s, const std::string & s2, bool frame) const
+template<typename... Args>
+void EvalState::addErrorTrace(Error & e, const PosIdx pos, const Args & ... formatArgs) const
 {
-    e.addTrace(positions[pos], HintFmt(s, s2), frame);
+    e.addTrace(positions[pos], HintFmt(formatArgs...));
 }


This makes the addition of optional arguments more invasive.
I'm proposing to add one in

Stack trace improvements #8623

I think it's very clumsy to have a mandatory "formatting parameter" argument, and we pass in empty strings here. To add more optional arguments, let's add an overload that takes a HintFmt explicitly. (I can add one here as well.)

I agree s2 is very clumsy. We could revisit the varargs later if needed. Not even many call sites are affected anyway.

roberth · 2024-02-23T17:49:24Z

src/libexpr/eval.cc

+template<typename... Args>
+void EvalState::addErrorTrace(Error & e, const Args & ... formatArgs) const
 {
-    e.addTrace(nullptr, s, s2);
+    e.addTrace(nullptr, HintFmt(formatArgs...));
 }

-void EvalState::addErrorTrace(Error & e, const PosIdx pos, const char * s, const std::string & s2, bool frame) const
+template<typename... Args>
+void EvalState::addErrorTrace(Error & e, const PosIdx pos, const Args & ... formatArgs) const
 {
-    e.addTrace(positions[pos], HintFmt(s, s2), frame);
+    e.addTrace(positions[pos], HintFmt(formatArgs...));
 }


I agree s2 is very clumsy. We could revisit the varargs later if needed. Not even many call sites are affected anyway.

9999years added 3 commits February 22, 2024 17:14

Print all stack frames

040874e

Remove the concept of "skipped frames"

f05c13e

Make addErrorTrace variadic

91e8962

9999years requested review from roberth and edolstra as code owners February 23, 2024 01:54

Update snapshots

fe6408b

github-actions bot added the with-tests Issues related to testing. PRs with tests have some priority label Feb 23, 2024

roberth reviewed Feb 23, 2024

View reviewed changes

roberth self-assigned this Feb 23, 2024

roberth approved these changes Feb 23, 2024

View reviewed changes

roberth merged commit 0b47783 into NixOS:master Feb 23, 2024
12 checks passed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Do not skip any stack frames when `--show-trace` is given #10066

Do not skip any stack frames when `--show-trace` is given #10066

9999years commented Feb 23, 2024 •

edited by roberth

9999years commented Feb 23, 2024

9999years commented Feb 23, 2024

9999years commented Feb 23, 2024

roberth commented Feb 23, 2024 •

edited

roberth left a comment

roberth Feb 23, 2024

9999years Feb 23, 2024

roberth Feb 23, 2024

roberth Feb 23, 2024

	error<TypeError>("function '%1%' called with unexpected argument '%2%'",
	(lambda.name ? std::string(symbols[lambda.name]) : "anonymous lambda"),
	symbols[i.name])
	.atPos(lambda.pos)
	.withTrace(pos, "from call site")

Do not skip any stack frames when --show-trace is given #10066

Do not skip any stack frames when --show-trace is given #10066

Conversation

9999years commented Feb 23, 2024 • edited by roberth

Motivation

Context

Notes

Priorities and Process

9999years commented Feb 23, 2024

9999years commented Feb 23, 2024

9999years commented Feb 23, 2024

Which code paths set frame = true?

roberth commented Feb 23, 2024 • edited

roberth left a comment

Choose a reason for hiding this comment

roberth Feb 23, 2024

Choose a reason for hiding this comment

9999years Feb 23, 2024

Choose a reason for hiding this comment

roberth Feb 23, 2024

Choose a reason for hiding this comment

roberth Feb 23, 2024

Choose a reason for hiding this comment

Do not skip any stack frames when `--show-trace` is given #10066

Do not skip any stack frames when `--show-trace` is given #10066

9999years commented Feb 23, 2024 •

edited by roberth

Which code paths set `frame = true`?

roberth commented Feb 23, 2024 •

edited