Skip to content

Logger improvements #13

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.

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

Merged
merged 23 commits into from
Mar 27, 2025
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
23 commits
Select commit Hold shift + click to select a range
1212b1f
JSONLogger: Log to a file descriptor instead of another Logger
edolstra Feb 17, 2025
8ef94c1
Add a structured log message for FOD hash mismatches
edolstra Feb 17, 2025
1f702cd
Allow separate JSON logging
edolstra Feb 17, 2025
2972e73
Turn NIX_LOG_FILE into a setting
edolstra Mar 13, 2025
29a9e63
Remove "@nix" prefix from json-log-path output
edolstra Mar 13, 2025
1efccf3
JSONLogger: Acquire a lock to prevent log messages from clobbering ea…
edolstra Mar 13, 2025
d9730fc
Fix fd check
edolstra Mar 13, 2025
220000d
makeJSONLogger(): Support logging to a Unix domain socket
edolstra Mar 13, 2025
2a2af3f
Logger::result(): Support logging arbitrary JSON objects
edolstra Mar 13, 2025
c515bc6
Provide a structured JSON serialisation of hashes
edolstra Mar 13, 2025
762114b
Log BuildResult
edolstra Mar 13, 2025
fd0d824
Don't use DerivedPath::toJSON()
edolstra Mar 14, 2025
8674792
Make the JSON logger more robust
edolstra Mar 14, 2025
c32441f
Remove redundant quotes
edolstra Mar 20, 2025
bc3a847
BuildResult: Serialize builtOutputs
edolstra Mar 21, 2025
502f027
nix daemon: Respect json-log-path and re-open for every connection
edolstra Mar 26, 2025
c8692b3
Merge remote-tracking branch 'detsys/detsys-main' into logger-improve…
edolstra Mar 26, 2025
17d0810
Cleanup
edolstra Mar 26, 2025
eca002d
Don't segfault if we can't create the JSON logger
edolstra Mar 27, 2025
37f3b25
makeTeeLogger(): Distinguish between main and extra loggers
edolstra Mar 27, 2025
f80f7e0
Abort if we cannot create TeeLogger
edolstra Mar 27, 2025
9e6c999
Add release note
edolstra Mar 27, 2025
10f9b2f
Set release date
edolstra Mar 27, 2025
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
2 changes: 1 addition & 1 deletion doc/manual/source/SUMMARY.md.in
Original file line number Diff line number Diff line change
Expand Up @@ -129,7 +129,7 @@
- [Determinate Nix Release Notes](release-notes-determinate/index.md)
- [Changes between Nix and Determinate Nix](release-notes-determinate/changes.md)
- [Release 3.0.0 (2025-03-04)](release-notes-determinate/rl-3.0.0.md)
- [Release 3.1.0 (2025-??-??)](release-notes-determinate/rl-3.1.0.md)
- [Release 3.1.0 (2025-03-27)](release-notes-determinate/rl-3.1.0.md)
- [Nix Release Notes](release-notes/index.md)
{{#include ./SUMMARY-rl-next.md}}
- [Release 2.27 (2025-03-03)](release-notes/rl-2.27.md)
Expand Down
2 changes: 2 additions & 0 deletions doc/manual/source/release-notes-determinate/changes.md
Original file line number Diff line number Diff line change
Expand Up @@ -5,3 +5,5 @@ This section lists the differences between upstream Nix 2.24 and Determinate Nix
* In Determinate Nix, flakes are stable. You no longer need to enable the `flakes` experimental feature.

* In Determinate Nix, the new Nix CLI (i.e. the `nix` command) is stable. You no longer need to enable the `nix-command` experimental feature.

* Determinate Nix has a setting [`json-log-path`](@docroot@/command-ref/conf-file.md#conf-json-log-path) to send a copy of all Nix log messages (in JSON format) to a file or Unix domain socket.
2 changes: 2 additions & 0 deletions doc/manual/source/release-notes-determinate/rl-3.0.0.md
Original file line number Diff line number Diff line change
Expand Up @@ -3,3 +3,5 @@
* Initial release of Determinate Nix.

* Based on [upstream Nix 2.26.2](../release-notes/rl-2.26.md).

* New setting `json-log-path` that sends a copy of all Nix log messages (in JSON format) to a file or Unix domain socket.
2 changes: 1 addition & 1 deletion doc/manual/source/release-notes-determinate/rl-3.1.0.md
Original file line number Diff line number Diff line change
@@ -1,3 +1,3 @@
# Release 3.1.0 (2025-??-??)
# Release 3.1.0 (2025-03-27)

* Based on [upstream Nix 2.27.1](../release-notes/rl-2.27.md).
41 changes: 41 additions & 0 deletions src/libstore/build-result.cc
Original file line number Diff line number Diff line change
@@ -1,8 +1,49 @@
#include "build-result.hh"

#include <nlohmann/json.hpp>

namespace nix {

bool BuildResult::operator==(const BuildResult &) const noexcept = default;
std::strong_ordering BuildResult::operator<=>(const BuildResult &) const noexcept = default;

void to_json(nlohmann::json & json, const BuildResult & buildResult)
{
json = nlohmann::json::object();
json["status"] = BuildResult::statusToString(buildResult.status);
if (buildResult.errorMsg != "")
json["errorMsg"] = buildResult.errorMsg;
if (buildResult.timesBuilt)
json["timesBuilt"] = buildResult.timesBuilt;
if (buildResult.isNonDeterministic)
json["isNonDeterministic"] = buildResult.isNonDeterministic;
if (buildResult.startTime)
json["startTime"] = buildResult.startTime;
if (buildResult.stopTime)
json["stopTime"] = buildResult.stopTime;
}

void to_json(nlohmann::json & json, const KeyedBuildResult & buildResult)
{
to_json(json, (const BuildResult &) buildResult);
auto path = nlohmann::json::object();
std::visit(
overloaded{
[&](const DerivedPathOpaque & opaque) { path["opaque"] = opaque.path.to_string(); },
[&](const DerivedPathBuilt & drv) {
path["drvPath"] = drv.drvPath->getBaseStorePath().to_string();
path["outputs"] = drv.outputs;
auto outputs = nlohmann::json::object();
for (auto & [name, output] : buildResult.builtOutputs)
outputs[name] = {
{"path", output.outPath.to_string()},
{"signatures", output.signatures},
};
json["builtOutputs"] = std::move(outputs);
},
},
buildResult.path.raw());
json["path"] = std::move(path);
}

}
51 changes: 30 additions & 21 deletions src/libstore/build-result.hh
Original file line number Diff line number Diff line change
Expand Up @@ -8,6 +8,8 @@
#include <chrono>
#include <optional>

#include <nlohmann/json_fwd.hpp>

namespace nix {

struct BuildResult
Expand Down Expand Up @@ -46,28 +48,32 @@ struct BuildResult
*/
std::string errorMsg;

static std::string_view statusToString(Status status)
{
switch (status) {
case Built: return "Built";
case Substituted: return "Substituted";
case AlreadyValid: return "AlreadyValid";
case PermanentFailure: return "PermanentFailure";
case InputRejected: return "InputRejected";
case OutputRejected: return "OutputRejected";
case TransientFailure: return "TransientFailure";
case CachedFailure: return "CachedFailure";
case TimedOut: return "TimedOut";
case MiscFailure: return "MiscFailure";
case DependencyFailed: return "DependencyFailed";
case LogLimitExceeded: return "LogLimitExceeded";
case NotDeterministic: return "NotDeterministic";
case ResolvesToAlreadyValid: return "ResolvesToAlreadyValid";
case NoSubstituters: return "NoSubstituters";
default: return "Unknown";
};
}

std::string toString() const {
auto strStatus = [&]() {
switch (status) {
case Built: return "Built";
case Substituted: return "Substituted";
case AlreadyValid: return "AlreadyValid";
case PermanentFailure: return "PermanentFailure";
case InputRejected: return "InputRejected";
case OutputRejected: return "OutputRejected";
case TransientFailure: return "TransientFailure";
case CachedFailure: return "CachedFailure";
case TimedOut: return "TimedOut";
case MiscFailure: return "MiscFailure";
case DependencyFailed: return "DependencyFailed";
case LogLimitExceeded: return "LogLimitExceeded";
case NotDeterministic: return "NotDeterministic";
case ResolvesToAlreadyValid: return "ResolvesToAlreadyValid";
case NoSubstituters: return "NoSubstituters";
default: return "Unknown";
};
}();
return strStatus + ((errorMsg == "") ? "" : " : " + errorMsg);
return
std::string(statusToString(status))
+ ((errorMsg == "") ? "" : " : " + errorMsg);
}

/**
Expand Down Expand Up @@ -130,4 +136,7 @@ struct KeyedBuildResult : BuildResult
{ }
};

void to_json(nlohmann::json & json, const BuildResult & buildResult);
void to_json(nlohmann::json & json, const KeyedBuildResult & buildResult);

}
8 changes: 8 additions & 0 deletions src/libstore/build/derivation-goal.cc
Original file line number Diff line number Diff line change
Expand Up @@ -1540,6 +1540,14 @@ Goal::Done DerivationGoal::done(
fs << worker.store.printStorePath(drvPath) << "\t" << buildResult.toString() << std::endl;
}

logger->result(
act ? act->id : getCurActivity(),
resBuildResult,
nlohmann::json(
KeyedBuildResult(
buildResult,
DerivedPath::Built{.drvPath = makeConstantStorePathRef(drvPath), .outputs = wantedOutputs})));

return amDone(buildResult.success() ? ecSuccess : ecFailed, std::move(ex));
}

Expand Down
12 changes: 12 additions & 0 deletions src/libstore/build/substitution-goal.cc
Original file line number Diff line number Diff line change
Expand Up @@ -3,8 +3,11 @@
#include "nar-info.hh"
#include "finally.hh"
#include "signals.hh"

#include <coroutine>

#include <nlohmann/json.hpp>

namespace nix {

PathSubstitutionGoal::PathSubstitutionGoal(const StorePath & storePath, Worker & worker, RepairFlag repair, std::optional<ContentAddress> ca)
Expand Down Expand Up @@ -35,6 +38,15 @@ Goal::Done PathSubstitutionGoal::done(
debug(*errorMsg);
buildResult.errorMsg = *errorMsg;
}

logger->result(
getCurActivity(),
resBuildResult,
nlohmann::json(
KeyedBuildResult(
buildResult,
DerivedPath::Opaque{storePath})));

return amDone(result);
}

Expand Down
2 changes: 2 additions & 0 deletions src/libstore/daemon.cc
Original file line number Diff line number Diff line change
Expand Up @@ -15,6 +15,7 @@
#include "derivations.hh"
#include "args.hh"
#include "git.hh"
#include "logging.hh"

#ifndef _WIN32 // TODO need graceful async exit support on Windows?
# include "monitor-fd.hh"
Expand Down Expand Up @@ -1049,6 +1050,7 @@ void processConnection(
if (!recursive) {
prevLogger_ = std::move(logger);
logger = std::move(tunnelLogger_);
applyJSONLogger();
}

unsigned int opCount = 0;
Expand Down
4 changes: 1 addition & 3 deletions src/libstore/uds-remote-store.cc
Original file line number Diff line number Diff line change
Expand Up @@ -84,9 +84,7 @@ ref<RemoteStore::Connection> UDSRemoteStore::openConnection()
auto conn = make_ref<Connection>();

/* Connect to a daemon that does the privileged work for us. */
conn->fd = createUnixDomainSocket();

nix::connect(toSocket(conn->fd.get()), path);
conn->fd = nix::connect(path);

conn->from.fd = conn->fd.get();
conn->to.fd = conn->fd.get();
Expand Down
6 changes: 6 additions & 0 deletions src/libstore/unix/build/local-derivation-goal.cc
Original file line number Diff line number Diff line change
Expand Up @@ -2654,6 +2654,12 @@ SingleDrvOutputs LocalDerivationGoal::registerOutputs()
worker.store.printStorePath(drvPath),
wanted.to_string(HashFormat::SRI, true),
got.to_string(HashFormat::SRI, true)));
act->result(resHashMismatch,
{
{"storePath", worker.store.printStorePath(drvPath)},
{"wanted", wanted},
{"got", got},
});
}
if (!newInfo0.references.empty()) {
auto numViolations = newInfo.references.size();
Expand Down
11 changes: 11 additions & 0 deletions src/libutil/hash.cc
Original file line number Diff line number Diff line change
Expand Up @@ -16,6 +16,8 @@
#include <sys/stat.h>
#include <fcntl.h>

#include <nlohmann/json.hpp>

#include <sodium.h>

namespace nix {
Expand Down Expand Up @@ -467,4 +469,13 @@ std::string_view printHashAlgo(HashAlgorithm ha)
}
}

void to_json(nlohmann::json & json, const Hash & hash)
{
json = nlohmann::json::object(
{
{"algo", printHashAlgo(hash.algo)},
{"base16", hash.to_string(HashFormat::Base16, false)},
});
}

}
6 changes: 6 additions & 0 deletions src/libutil/hash.hh
Original file line number Diff line number Diff line change
Expand Up @@ -6,6 +6,8 @@
#include "serialise.hh"
#include "file-system.hh"

#include <nlohmann/json_fwd.hpp>

namespace nix {


Expand Down Expand Up @@ -210,6 +212,10 @@ std::optional<HashAlgorithm> parseHashAlgoOpt(std::string_view s);
*/
std::string_view printHashAlgo(HashAlgorithm ha);

/**
* Write a JSON serialisation of the format `{"algo":"<sha1|...>","base16":"<hex>"}`.
*/
void to_json(nlohmann::json & json, const Hash & hash);

union Ctx;

Expand Down
88 changes: 84 additions & 4 deletions src/libutil/logging.cc
Original file line number Diff line number Diff line change
Expand Up @@ -6,6 +6,8 @@
#include "config-global.hh"
#include "source-path.hh"
#include "position.hh"
#include "sync.hh"
#include "unix-domain-socket.hh"

#include <atomic>
#include <sstream>
Expand Down Expand Up @@ -181,8 +183,12 @@ void to_json(nlohmann::json & json, std::shared_ptr<Pos> pos)

struct JSONLogger : Logger {
Descriptor fd;
bool includeNixPrefix;

JSONLogger(Descriptor fd) : fd(fd) { }
JSONLogger(Descriptor fd, bool includeNixPrefix)
: fd(fd)
, includeNixPrefix(includeNixPrefix)
{ }

bool isVerbose() override {
return true;
Expand All @@ -201,9 +207,33 @@ struct JSONLogger : Logger {
unreachable();
}

struct State
{
bool enabled = true;
};

Sync<State> _state;

void write(const nlohmann::json & json)
{
writeLine(fd, "@nix " + json.dump(-1, ' ', false, nlohmann::json::error_handler_t::replace));
auto line =
(includeNixPrefix ? "@nix " : "") +
json.dump(-1, ' ', false, nlohmann::json::error_handler_t::replace);

/* Acquire a lock to prevent log messages from clobbering each
other. */
try {
auto state(_state.lock());
if (state->enabled)
writeLine(fd, line);
} catch (...) {
bool enabled = false;
std::swap(_state.lock()->enabled, enabled);
if (enabled) {
ignoreExceptionExceptInterrupt();
logger->warn("disabling JSON logger due to write errors");
}
}
}

void log(Verbosity lvl, std::string_view s) override
Expand Down Expand Up @@ -273,11 +303,61 @@ struct JSONLogger : Logger {
addFields(json, fields);
write(json);
}

void result(ActivityId act, ResultType type, const nlohmann::json & j) override
{
nlohmann::json json;
json["action"] = "result";
json["id"] = act;
json["type"] = type;
json["payload"] = j;
write(json);
}
};

std::unique_ptr<Logger> makeJSONLogger(Descriptor fd)
std::unique_ptr<Logger> makeJSONLogger(Descriptor fd, bool includeNixPrefix)
{
return std::make_unique<JSONLogger>(fd, includeNixPrefix);
}

std::unique_ptr<Logger> makeJSONLogger(const std::filesystem::path & path, bool includeNixPrefix)
{
return std::make_unique<JSONLogger>(fd);
struct JSONFileLogger : JSONLogger {
AutoCloseFD fd;

JSONFileLogger(AutoCloseFD && fd, bool includeNixPrefix)
: JSONLogger(fd.get(), includeNixPrefix)
, fd(std::move(fd))
{ }
};

AutoCloseFD fd =
std::filesystem::is_socket(path)
? connect(path)
: toDescriptor(open(path.c_str(), O_CREAT | O_APPEND | O_WRONLY, 0644));
if (!fd)
throw SysError("opening log file %1%", path);

return std::make_unique<JSONFileLogger>(std::move(fd), includeNixPrefix);
}

void applyJSONLogger()
{
if (!loggerSettings.jsonLogPath.get().empty()) {
try {
std::vector<std::unique_ptr<Logger>> loggers;
loggers.push_back(makeJSONLogger(std::filesystem::path(loggerSettings.jsonLogPath.get()), false));
try {
logger = makeTeeLogger(std::move(logger), std::move(loggers));
} catch (...) {
// `logger` is now gone so give up.
abort();
}
} catch (...) {
ignoreExceptionExceptInterrupt();
}

}
}

static Logger::Fields getFields(nlohmann::json & json)
Expand Down
Loading