Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Log all IFD #8094

Open
wants to merge 2 commits into
base: master
Choose a base branch
from
Open

Log all IFD #8094

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
2b2a1ff
fix: log all ifd
cleverca22 Mar 5, 2020
335a824
Fix passing pos
cidkidnix May 17, 2023
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
4 changes: 2 additions & 2 deletions src/libexpr/eval.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -1607,7 +1607,7 @@ void EvalState::callFunction(Value & fun, size_t nrArgs, Value * * args, Value &
if (countCalls) primOpCalls[name]++;

try {
vCur.primOp->fun(*this, noPos, args, vCur);
vCur.primOp->fun(*this, pos, args, vCur);
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@layus I am curious on your feedback about these noPos -> pos changes, I think some of the noPos dates to your big overhaul.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This indeed defeats my intent, as I wanted to have a given pos printed exactly once, and attached to the most relevant trace item. Before we used to reuse the same pos all over the place, so that it ended up being displayed multiple times in the error trace, and associated with trace items that were irrelevant.

In this particular case, the pos we have is the one of the AST node calling a function. That is why I pass noPos to primOp->fun (because that is irrelevant for errors inside said primop) and wrap any error thrown by the primop with an error trace (see right below this message, addErrorTrace(e, pos, "while calling the '%1%' builtin", name);)

I understand the need to access this value when logging (you have no context to understand where the error comes from), but that value should not be used in error traces. I am fairly confident this change will only have a small impact, if any, as most builtins should already have been rewritten to not use their pos argument in most cases. And in any case it is only redundant printing of positions in error traces.

Be wary that the position might not be very accurate or useful. It may not even contain the builtin name that is referenced, as in:

let
  doSomething = import;
  aStringFromSomewhere = "${some derivation generating a nix file}/nix-file.nix";
in
  doSomething aStringFromSomewhere # <- pos is HERE, no import, no context, nothing directly useful.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

What gets broken is the implicit invariant that when you use a pos, you then pass noPos to your children so that they know the pos has already been used in a more relevant context, and you only have to print your message.
With this change a pos that has already been used gets passed around, and might get printed some more times. Not ideal, but not a big deal, especially since I have little time to play with this pr and investigate.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

From my point of view, the position is not that useful, and thus does not need to be logged at all. But I also understand that a position, even an approximate one, can be better than no position at all.

What is the point of printing positions here BTW ? Because external tools will not be able to handle it correctly in all cases. So maybe not printing the position is an option after all 🤔

Will stop the fuss and get some sleep :-)

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yeah, I wouldn't want to undo your hard work making the trace sane. Fundamentally, the "nicest" logging would have the entire trace, but the trace is only built when the exceptions / stack is unwound. There is no passing in the context pre-made as an argument to the primop/realize context for constructing the Activity with the current architecture.

Perhaps we shouldn't log positions at all end, at least for the first version.

} catch (Error & e) {
addErrorTrace(e, pos, "while calling the '%1%' builtin", name);
throw;
Expand Down Expand Up @@ -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);
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

More noPos to pos.

} catch (Error & e) {
addErrorTrace(e, pos, "while calling the '%1%' builtin", name);
throw;
Expand Down
5 changes: 4 additions & 1 deletion src/libexpr/eval.hh
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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:

Expand Down Expand Up @@ -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;
Expand Down
88 changes: 62 additions & 26 deletions src/libexpr/primops.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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>
Expand Down Expand Up @@ -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) {
Expand All @@ -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) {
Expand All @@ -77,18 +76,55 @@ 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) {
auto pos2 = positions[pos];
std::ostringstream str;
((std::shared_ptr<AbstractPos>) pos2)->print(str);
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),
{
Logger::Field{store->printStorePath(drv.drvPath)},
Logger::Field{drv.output},
Logger::Field{
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Do we want this split out or do we want to construct the Field in a way where it's the same as positions[pos]?

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I got keep it this way, so maximum structure for the an external application. And pull out the AbstactPos -> Fields conversion to a separate function.

str.str()
},
Logger::Field{
pos2.line
},
Logger::Field {
pos2.column
},
Logger::Field{(std::string) 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)
);
}
}
Expand All @@ -109,14 +145,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");
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

More noPos to pos.


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)));

Expand Down Expand Up @@ -169,7 +205,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
Expand Down Expand Up @@ -332,7 +368,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"));

Expand Down Expand Up @@ -376,7 +412,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>();
}
Expand Down Expand Up @@ -1523,7 +1559,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());
Expand Down Expand Up @@ -1600,7 +1636,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));
Expand Down Expand Up @@ -1657,7 +1693,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({
Expand Down Expand Up @@ -1691,7 +1727,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));
}
Expand All @@ -1718,7 +1754,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));
}
Expand All @@ -1736,7 +1772,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
Expand Down Expand Up @@ -2082,7 +2118,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, pos, "addPath");
path = state.toRealPath(rewriteStrings(path, rewrites), context);

StorePathSet refs;
Expand Down
9 changes: 7 additions & 2 deletions src/libstore/build-result.hh
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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);
}
};

Expand Down
1 change: 1 addition & 0 deletions src/libutil/logging.hh
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -23,6 +23,7 @@ typedef enum {
actQueryPathInfo = 109,
actPostBuildHook = 110,
actBuildWaiting = 111,
actFromDerivation = 112,
} ActivityType;

typedef enum {
Expand Down
10 changes: 10 additions & 0 deletions tests/import-from-derivation.nix
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -0,0 +1,10 @@
with import ./config.nix;
import (
mkDerivation {
name = "foo";
bla = import ./dependencies.nix;
buildCommand = "
echo \\\"hi\\\" > $out
";
}
)
3 changes: 2 additions & 1 deletion tests/local.mk
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -134,7 +134,8 @@ nix_tests = \
flakes/show.sh \
impure-derivations.sh \
path-from-hash-part.sh \
toString-path.sh
toString-path.sh \
log-ifd.sh

ifeq ($(HAVE_LIBCPUID), 1)
nix_tests += compute-levels.sh
Expand Down
5 changes: 5 additions & 0 deletions tests/log-ifd.sh
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -0,0 +1,5 @@
#
source common.sh

# TODO: Now what
nix-build ./import-derivation.nix --option "log-import-from-derivation" true --no-out-link --log-format internal-json 2>&1 1>/dev/null | grep "^@nix" | sed 's/^@nix //g' | jq "select(.type == 112)"
Comment on lines +4 to +5
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Need to somehow check the resulting JSON here. Not sure now.

13 changes: 1 addition & 12 deletions tests/remote-store.sh
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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

Expand Down