fix: log all ifd

Co-authored-by: Dylan Green <dylan.green@obsidian.systems>

src/libexpr/eval.cc

@@ -1655,7 +1655,7 @@ void EvalState::callFunction(Value & fun, size_t nrArgs, Value * * args, Value &
                     // 1. Unify this and above code. Heavily redundant.
                     // 2. Create a fake env (arg1, arg2, etc.) and a fake expr (arg1: arg2: etc: builtins.name arg1 arg2 etc)
                     //    so the debugger allows to inspect the wrong parameters passed to the builtin.
-                    primOp->primOp->fun(*this, noPos, vArgs, vCur);
+                    primOp->primOp->fun(*this, pos, vArgs, vCur);
                 } catch (Error & e) {
                     addErrorTrace(e, pos, "while calling the '%1%' builtin", name);
                     throw;

src/libexpr/eval.hh

@@ -593,7 +593,7 @@ public:
      * Realise the given context, and return a mapping from the placeholders
      * used to construct the associated value to their final store path
      */
-    [[nodiscard]] StringMap realiseContext(const NixStringContext & context);
+    [[nodiscard]] StringMap realiseContext(const NixStringContext & context, const PosIdx pos, const std::string_view reason);
 
 private:
 
@@ -746,6 +746,9 @@ struct EvalSettings : Config
 
     Setting<bool> traceVerbose{this, false, "trace-verbose",
         "Whether `builtins.traceVerbose` should trace its first argument when evaluated."};
+
+    Setting<bool> logImportFromDerivation{this, false, "log-import-from-derivation",
+        "Emit log messages for all imports from derivations at the 'info' log level"};
 };
 
 extern EvalSettings evalSettings;

src/libexpr/primops.cc

@@ -11,6 +11,7 @@
 #include "value-to-json.hh"
 #include "value-to-xml.hh"
 #include "primops.hh"
+#include "build-result.hh"
 
 #include <boost/container/small_vector.hpp>
 #include <nlohmann/json.hpp>
@@ -38,9 +39,9 @@ namespace nix {
 InvalidPathError::InvalidPathError(const Path & path) :
     EvalError("path '%s' is not valid", path), path(path) {}
 
-StringMap EvalState::realiseContext(const NixStringContext & context)
+StringMap EvalState::realiseContext(const NixStringContext & context, const PosIdx pos, const std::string_view reason)
 {
-    std::vector<DerivedPath::Built> drvs;
+    std::vector<NixStringContextElem::Built> drvs;
     StringMap res;
 
     for (auto & c : context) {
@@ -50,10 +51,8 @@ StringMap EvalState::realiseContext(const NixStringContext & context)
         };
         std::visit(overloaded {
             [&](const NixStringContextElem::Built & b) {
-                drvs.push_back(DerivedPath::Built {
-                    .drvPath = b.drvPath,
-                    .outputs = OutputsSpec::Names { b.output },
-                });
+                auto ctxS = store->printStorePath(b.drvPath);
+                drvs.push_back(b);
                 ensureValid(b.drvPath);
             },
             [&](const NixStringContextElem::Opaque & o) {
@@ -77,18 +76,38 @@ StringMap EvalState::realiseContext(const NixStringContext & context)
             "cannot build '%1%' during evaluation because the option 'allow-import-from-derivation' is disabled",
             store->printStorePath(drvs.begin()->drvPath)));
 
+    if (evalSettings.logImportFromDerivation) {
+         for (auto & drv : drvs) {
+              Activity act{
+                   *logger, lvlInfo, actFromDerivation,
+                   fmt("Derivation %s Output %s: importing from derivation %s via %s",
+                       store->printStorePath(drv.drvPath), drv.output, positions[pos], reason),
+              };
+         }
+    }
+
     /* Build/substitute the context. */
     std::vector<DerivedPath> buildReqs;
-    for (auto & d : drvs) buildReqs.emplace_back(DerivedPath { d });
-    store->buildPaths(buildReqs);
+    for (auto & d : drvs) buildReqs.emplace_back(DerivedPath {
+        DerivedPath::Built {
+            .drvPath = d.drvPath,
+            .outputs = OutputsSpec::Names { d.output },
+        }
+    });
+    auto results = store->buildPathsWithResults(buildReqs);
 
     /* Get all the output paths corresponding to the placeholders we had */
-    for (auto & drv : drvs) {
-        auto outputs = resolveDerivedPath(*store, drv);
-        for (auto & [outputName, outputPath] : outputs) {
+    for (auto & result : results) {
+        auto built = std::get<DerivedPath::Built>(result.path);
+        if (!result.success()) {
+            auto e = result.error();
+            e.addTrace(positions[pos], fmt("Derivation %s Output %s via %s", store->printStorePath(built.drvPath), built.outputs.to_string(), reason));
+            throw e;
+        }
+        for (auto & [outputName, realisation] : result.builtOutputs) {
             res.insert_or_assign(
-                downstreamPlaceholder(*store, drv.drvPath, outputName),
-                store->printStorePath(outputPath)
+                downstreamPlaceholder(*store, built.drvPath, outputName),
+                store->printStorePath(realisation.outPath)
             );
         }
     }
@@ -109,14 +128,14 @@ struct RealisePathFlags {
     bool checkForPureEval = true;
 };
 
-static SourcePath realisePath(EvalState & state, const PosIdx pos, Value & v, const RealisePathFlags flags = {})
+static SourcePath realisePath(EvalState & state, const PosIdx pos, Value & v, const std::string_view reason, const RealisePathFlags flags = {})
 {
     NixStringContext context;
 
-    auto path = state.coerceToPath(noPos, v, context, "while realising the context of a path");
+    auto path = state.coerceToPath(pos, v, context, "while realising the context of a path");
 
     try {
-        StringMap rewrites = state.realiseContext(context);
+        StringMap rewrites = state.realiseContext(context, pos, reason);
 
         auto realPath = state.rootPath(CanonPath(state.toRealPath(rewriteStrings(path.path.abs(), rewrites), context)));
 
@@ -169,7 +188,7 @@ static void mkOutputString(
    argument. */
 static void import(EvalState & state, const PosIdx pos, Value & vPath, Value * vScope, Value & v)
 {
-    auto path = realisePath(state, pos, vPath);
+    auto path = realisePath(state, pos, vPath, "scopedImport");
     auto path2 = path.path.abs();
 
     // FIXME
@@ -332,7 +351,7 @@ extern "C" typedef void (*ValueInitializer)(EvalState & state, Value & v);
 /* Load a ValueInitializer from a DSO and return whatever it initializes */
 void prim_importNative(EvalState & state, const PosIdx pos, Value * * args, Value & v)
 {
-    auto path = realisePath(state, pos, *args[0]);
+    auto path = realisePath(state, pos, *args[0], "importNative");
 
     std::string sym(state.forceStringNoCtx(*args[1], pos, "while evaluating the second argument passed to builtins.importNative"));
 
@@ -376,7 +395,7 @@ void prim_exec(EvalState & state, const PosIdx pos, Value * * args, Value & v)
                         false, false).toOwned());
     }
     try {
-        auto _ = state.realiseContext(context); // FIXME: Handle CA derivations
+        auto _ = state.realiseContext(context, pos, "exec"); // FIXME: Handle CA derivations
     } catch (InvalidPathError & e) {
         state.error("cannot execute '%1%', since path '%2%' is not valid", program, e.path).atPos(pos).debugThrow<EvalError>();
     }
@@ -1523,7 +1542,7 @@ static void prim_pathExists(EvalState & state, const PosIdx pos, Value * * args,
        can’t just catch the exception here because we still want to
        throw if something in the evaluation of `*args[0]` tries to
        access an unauthorized path). */
-    auto path = realisePath(state, pos, *args[0], { .checkForPureEval = false });
+    auto path = realisePath(state, pos, *args[0], "pathExists", { .checkForPureEval = false });
 
     try {
         v.mkBool(state.checkSourcePath(path).pathExists());
@@ -1600,7 +1619,7 @@ static RegisterPrimOp primop_dirOf({
 /* Return the contents of a file as a string. */
 static void prim_readFile(EvalState & state, const PosIdx pos, Value * * args, Value & v)
 {
-    auto path = realisePath(state, pos, *args[0]);
+    auto path = realisePath(state, pos, *args[0], "readFile");
     auto s = path.readFile();
     if (s.find((char) 0) != std::string::npos)
         state.debugThrowLastTrace(Error("the contents of the file '%1%' cannot be represented as a Nix string", path));
@@ -1657,7 +1676,7 @@ static void prim_findFile(EvalState & state, const PosIdx pos, Value * * args, V
                 false, false).toOwned();
 
         try {
-            auto rewrites = state.realiseContext(context);
+            auto rewrites = state.realiseContext(context, pos, "findFile");
             path = rewriteStrings(path, rewrites);
         } catch (InvalidPathError & e) {
             state.debugThrowLastTrace(EvalError({
@@ -1691,7 +1710,7 @@ static void prim_hashFile(EvalState & state, const PosIdx pos, Value * * args, V
             .errPos = state.positions[pos]
         }));
 
-    auto path = realisePath(state, pos, *args[1]);
+    auto path = realisePath(state, pos, *args[1], "hashFile");
 
     v.mkString(hashString(*ht, path.readFile()).to_string(Base16, false));
 }
@@ -1718,7 +1737,7 @@ static std::string_view fileTypeToString(InputAccessor::Type type)
 
 static void prim_readFileType(EvalState & state, const PosIdx pos, Value * * args, Value & v)
 {
-    auto path = realisePath(state, pos, *args[0]);
+    auto path = realisePath(state, pos, *args[0], "readFileType");
     /* Retrieve the directory entry type and stringize it. */
     v.mkString(fileTypeToString(path.lstat().type));
 }
@@ -1736,7 +1755,7 @@ static RegisterPrimOp primop_readFileType({
 /* Read a directory (without . or ..) */
 static void prim_readDir(EvalState & state, const PosIdx pos, Value * * args, Value & v)
 {
-    auto path = realisePath(state, pos, *args[0]);
+    auto path = realisePath(state, pos, *args[0], "readDir");
 
     // Retrieve directory entries for all nodes in a directory.
     // This is similar to `getFileType` but is optimized to reduce system calls
@@ -2082,7 +2101,7 @@ static void addPath(
     try {
         // FIXME: handle CA derivation outputs (where path needs to
         // be rewritten to the actual output).
-        auto rewrites = state.realiseContext(context);
+        auto rewrites = state.realiseContext(context, noPos, "addPath");
         path = state.toRealPath(rewriteStrings(path, rewrites), context);
 
         StorePathSet refs;

src/libstore/build-result.hh

@@ -105,9 +105,14 @@ struct BuildResult
         return status == Built || status == Substituted || status == AlreadyValid || status == ResolvesToAlreadyValid;
     }
 
-    void rethrow()
+    [[noreturn]] void rethrow()
     {
-        throw Error("%s", errorMsg);
+        throw error();
+    }
+
+    Error error()
+    {
+        return Error("%s", errorMsg);
     }
 };
 

src/libutil/logging.hh

@@ -23,6 +23,7 @@ typedef enum {
     actQueryPathInfo = 109,
     actPostBuildHook = 110,
     actBuildWaiting = 111,
+    actFromDerivation = 112,
 } ActivityType;
 
 typedef enum {

tests/import-from-derivation.nix

@@ -0,0 +1,10 @@
+with import ./config.nix;
+import (
+ mkDerivation {
+   name = "foo";
+   bla = import ./dependencies.nix;
+   buildCommand = "
+     echo \\\"hi\\\" > $out
+   ";
+ }
+)

tests/remote-store.sh

@@ -19,18 +19,7 @@ else
 fi
 
 # Test import-from-derivation through the daemon.
-[[ $(nix eval --impure --raw --expr '
-  with import ./config.nix;
-  import (
-    mkDerivation {
-      name = "foo";
-      bla = import ./dependencies.nix;
-      buildCommand = "
-        echo \\\"hi\\\" > $out
-      ";
-    }
-  )
-') = hi ]]
+[[ $(nix eval --option "log-import-from-derivation" true --impure --raw ./import-from-derivation.nix) = hi ]]
 
 storeCleared=1 NIX_REMOTE_=$NIX_REMOTE $SHELL ./user-envs.sh