diff --git a/src/libstore/build/build-log.cc b/src/libstore/build/build-log.cc new file mode 100644 index 00000000000..a8fb64fc68b --- /dev/null +++ b/src/libstore/build/build-log.cc @@ -0,0 +1,48 @@ +#include "nix/store/build/build-log.hh" + +namespace nix { + +BuildLog::BuildLog(size_t maxTailLines, std::unique_ptr act) + : maxTailLines(maxTailLines) + , act(std::move(act)) +{ +} + +void BuildLog::operator()(std::string_view data) +{ + for (auto c : data) + if (c == '\r') + currentLogLinePos = 0; + else if (c == '\n') + flushLine(); + else { + if (currentLogLinePos >= currentLogLine.size()) + currentLogLine.resize(currentLogLinePos + 1); + currentLogLine[currentLogLinePos++] = c; + } +} + +void BuildLog::flush() +{ + if (!currentLogLine.empty()) + flushLine(); +} + +void BuildLog::flushLine() +{ + // Truncate to actual content (currentLogLinePos may be less than size due to \r) + currentLogLine.resize(currentLogLinePos); + + if (!handleJSONLogMessage(currentLogLine, *act, builderActivities, "the derivation builder", false)) { + // Line was not handled as JSON, emit and add to tail + act->result(resBuildLogLine, currentLogLine); + logTail.push_back(currentLogLine); + if (logTail.size() > maxTailLines) + logTail.pop_front(); + } + + currentLogLine.clear(); + currentLogLinePos = 0; +} + +} // namespace nix diff --git a/src/libstore/build/derivation-building-goal.cc b/src/libstore/build/derivation-building-goal.cc index a86a01fd8bb..f3b2d61fb14 100644 --- a/src/libstore/build/derivation-building-goal.cc +++ b/src/libstore/build/derivation-building-goal.cc @@ -40,37 +40,13 @@ DerivationBuildingGoal::DerivationBuildingGoal( worker.store.addTempRoot(this->drvPath); } -DerivationBuildingGoal::~DerivationBuildingGoal() -{ - /* Careful: we should never ever throw an exception from a - destructor. */ -#ifndef _WIN32 // TODO enable `DerivationBuilder` on Windows - if (builder) - builder.reset(); -#endif - try { - closeLogFile(); - } catch (...) { - ignoreExceptionInDestructor(); - } -} +DerivationBuildingGoal::~DerivationBuildingGoal() = default; std::string DerivationBuildingGoal::key() { return "dd$" + std::string(drvPath.name()) + "$" + worker.store.printStorePath(drvPath); } -void DerivationBuildingGoal::killChild() -{ -#ifndef _WIN32 // TODO enable build hook on Windows - hook.reset(); -#endif -#ifndef _WIN32 // TODO enable `DerivationBuilder` on Windows - if (builder && builder->killChild()) - worker.childTerminated(this); -#endif -} - std::string showKnownOutputs(const StoreDirConfig & store, const Derivation & drv) { std::string msg; @@ -146,6 +122,8 @@ Goal::Co DerivationBuildingGoal::gaveUpOnSubstitution(bool storeDerivation) writeDerivation(worker.store, *drv); } + StorePathSet inputPaths; + { /* If we get this far, we know no dynamic drvs inputs */ @@ -185,10 +163,23 @@ Goal::Co DerivationBuildingGoal::gaveUpOnSubstitution(bool storeDerivation) slot to become available, since we don't need one if there is a build hook. */ co_await yield(); - co_return tryToBuild(); + co_return tryToBuild(std::move(inputPaths)); } -Goal::Co DerivationBuildingGoal::tryToBuild() +/** + * RAII wrapper for build log file. + * Constructor opens the log file, destructor closes it. + */ +struct LogFile +{ + AutoCloseFD fd; + std::shared_ptr fileSink, sink; + + LogFile(Store & store, const StorePath & drvPath); + ~LogFile(); +}; + +Goal::Co DerivationBuildingGoal::tryToBuild(StorePathSet inputPaths) { auto drvOptions = [&] { DerivationOptions temp; @@ -249,33 +240,6 @@ Goal::Co DerivationBuildingGoal::tryToBuild() } checkPathValidity(initialOutputs); - auto started = [&]() { - auto msg = - fmt(buildMode == bmRepair ? "repairing outputs of '%s'" - : buildMode == bmCheck ? "checking outputs of '%s'" - : "building '%s'", - worker.store.printStorePath(drvPath)); -#ifndef _WIN32 // TODO enable build hook on Windows - if (hook) - msg += fmt(" on '%s'", hook->machineName); -#endif - act = std::make_unique( - *logger, - lvlInfo, - actBuild, - msg, - Logger::Fields{ - worker.store.printStorePath(drvPath), -#ifndef _WIN32 // TODO enable build hook on Windows - hook ? hook->machineName : -#endif - "", - 1, - 1}); - mcRunningBuilds = std::make_unique>(worker.runningBuilds); - worker.updateProgress(); - }; - /** * Activity that denotes waiting for a lock. */ @@ -366,7 +330,7 @@ Goal::Co DerivationBuildingGoal::tryToBuild() if (buildLocally) { useHook = false; } else { - switch (tryBuildHook(initialOutputs, drvOptions)) { + switch (tryBuildHook(drvOptions)) { case rpAccept: /* Yes, it has started doing so. Wait until we get EOF from the hook. */ @@ -416,9 +380,6 @@ Goal::Co DerivationBuildingGoal::tryToBuild() Magenta( "/usr/sbin/softwareupdate --install-rosetta && launchctl stop org.nixos.nix-daemon")); -#ifndef _WIN32 // TODO enable `DerivationBuilder` on Windows - builder.reset(); -#endif outputLocks.unlock(); worker.permanentFailure = true; co_return doneFailure({BuildResult::Failure::InputRejected, std::move(msg)}); @@ -433,103 +394,225 @@ Goal::Co DerivationBuildingGoal::tryToBuild() actLock.reset(); if (useHook) { - buildResult.startTime = time(0); // inexact - started(); - - while (true) { - auto event = co_await WaitForChildEvent{}; - if (auto * output = std::get_if(&event)) { - co_await processChildOutput(output->fd, output->data); - } else if (std::get_if(&event)) { - if (!currentLogLine.empty()) - flushLine(); - break; - } else if (auto * timeout = std::get_if(&event)) { - killChild(); - co_return doneFailure(std::move(*timeout)); - } - } + co_return buildWithHook( + std::move(inputPaths), std::move(initialOutputs), std::move(drvOptions), std::move(outputLocks)); + } else { + co_return buildLocally( + std::move(inputPaths), + std::move(initialOutputs), + std::move(drvOptions), + std::move(outputLocks), + externalBuilder); + } +} -#ifndef _WIN32 - assert(hook); -#endif +Goal::Co DerivationBuildingGoal::buildWithHook( + StorePathSet inputPaths, + std::map initialOutputs, + DerivationOptions drvOptions, + PathLocks outputLocks) +{ +#ifdef _WIN32 // TODO enable build hook on Windows + unreachable(); +#else + std::unique_ptr hook = std::move(worker.hook); - trace("hook build done"); + try { + hook->machineName = readLine(hook->fromHook.readSide.get()); + } catch (Error & e) { + e.addTrace({}, "while reading the machine name from the build hook"); + throw; + } - /* Since we got an EOF on the logger pipe, the builder is presumed - to have terminated. In fact, the builder could also have - simply have closed its end of the pipe, so just to be sure, - kill it. */ - int status = -#ifndef _WIN32 // TODO enable build hook on Windows - hook->pid.kill(); -#else - 0; -#endif + CommonProto::WriteConn conn{hook->sink}; - debug("build hook for '%s' finished", worker.store.printStorePath(drvPath)); + /* Tell the hook all the inputs that have to be copied to the + remote system. */ + CommonProto::write(worker.store, conn, inputPaths); - buildResult.timesBuilt++; - buildResult.stopTime = time(0); + /* Tell the hooks the missing outputs that have to be copied back + from the remote system. */ + { + StringSet missingOutputs; + for (auto & [outputName, status] : initialOutputs) { + // XXX: Does this include known CA outputs? + if (buildMode != bmCheck && status.known && status.known->isValid()) + continue; + missingOutputs.insert(outputName); + } + CommonProto::write(worker.store, conn, missingOutputs); + } - /* So the child is gone now. */ - worker.childTerminated(this); + hook->sink = FdSink(); + hook->toHook.writeSide.close(); - /* Close the read side of the logger pipe. */ -#ifndef _WIN32 // TODO enable build hook on Windows - hook->builderOut.readSide.close(); - hook->fromHook.readSide.close(); -#endif + /* Create the log file and pipe. */ + std::unique_ptr logFile = std::make_unique(worker.store, drvPath); - /* Close the log file. */ - closeLogFile(); + std::set fds; + fds.insert(hook->fromHook.readSide.get()); + fds.insert(hook->builderOut.readSide.get()); + worker.childStarted(shared_from_this(), fds, false, false); - /* Check the exit status. */ - if (!statusOk(status)) { - auto e = fixupBuilderFailureErrorMessage({BuildResult::Failure::MiscFailure, status, ""}); + buildResult.startTime = time(0); // inexact - outputLocks.unlock(); + auto msg = + fmt(buildMode == bmRepair ? "repairing outputs of '%s'" + : buildMode == bmCheck ? "checking outputs of '%s'" + : "building '%s'", + worker.store.printStorePath(drvPath)); + msg += fmt(" on '%s'", hook->machineName); + + std::unique_ptr buildLog = std::make_unique( + settings.logLines, + std::make_unique( + *logger, + lvlInfo, + actBuild, + msg, + Logger::Fields{worker.store.printStorePath(drvPath), hook->machineName, 1, 1})); + mcRunningBuilds = std::make_unique>(worker.runningBuilds); + worker.updateProgress(); - /* TODO (once again) support fine-grained error codes, see issue #12641. */ + std::string currentHookLine; + uint64_t logSize = 0; - co_return doneFailure(std::move(e)); + while (true) { + auto event = co_await WaitForChildEvent{}; + if (auto * output = std::get_if(&event)) { + auto & fd = output->fd; + auto & data = output->data; + if (fd == hook->builderOut.readSide.get()) { + logSize += data.size(); + if (settings.maxLogSize && logSize > settings.maxLogSize) { + hook.reset(); + co_return doneFailureLogTooLong(*buildLog); + } + (*buildLog)(data); + if (logFile->sink) + (*logFile->sink)(data); + } else if (fd == hook->fromHook.readSide.get()) { + for (auto c : data) + if (c == '\n') { + auto json = parseJSONMessage(currentHookLine, "the derivation builder"); + if (json) { + auto s = handleJSONLogMessage( + *json, worker.act, hook->activities, "the derivation builder", true); + // ensure that logs from a builder using `ssh-ng://` as protocol + // are also available to `nix log`. + if (s && logFile->sink) { + const auto type = (*json)["type"]; + const auto fields = (*json)["fields"]; + if (type == resBuildLogLine) { + (*logFile->sink)((fields.size() > 0 ? fields[0].get() : "") + "\n"); + } else if (type == resSetPhase && !fields.is_null()) { + const auto phase = fields[0]; + if (!phase.is_null()) { + // nixpkgs' stdenv produces lines in the log to signal + // phase changes. + // We want to get the same lines in case of remote builds. + // The format is: + // @nix { "action": "setPhase", "phase": "$curPhase" } + const auto logLine = + nlohmann::json::object({{"action", "setPhase"}, {"phase", phase}}); + (*logFile->sink)( + "@nix " + + logLine.dump(-1, ' ', false, nlohmann::json::error_handler_t::replace) + + "\n"); + } + } + } + } + currentHookLine.clear(); + } else + currentHookLine += c; + } + } else if (std::get_if(&event)) { + buildLog->flush(); + break; + } else if (auto * timeout = std::get_if(&event)) { + hook.reset(); + co_return doneFailure(std::move(*timeout)); } + } - /* Compute the FS closure of the outputs and register them as - being valid. */ - auto builtOutputs = - /* When using a build hook, the build hook can register the output - as valid (by doing `nix-store --import'). If so we don't have - to do anything here. + trace("hook build done"); - We can only early return when the outputs are known a priori. For - floating content-addressing derivations this isn't the case. + /* Since we got an EOF on the logger pipe, the builder is presumed + to have terminated. In fact, the builder could also have + simply have closed its end of the pipe, so just to be sure, + kill it. */ + int status = hook->pid.kill(); - Aborts if any output is not valid or corrupt, and otherwise - returns a 'SingleDrvOutputs' structure containing all outputs. - */ - [&] { - auto [allValid, validOutputs] = checkPathValidity(initialOutputs); - if (!allValid) - throw Error("some outputs are unexpectedly invalid"); - return validOutputs; - }(); + debug("build hook for '%s' finished", worker.store.printStorePath(drvPath)); - StorePathSet outputPaths; - for (auto & [_, output] : builtOutputs) - outputPaths.insert(output.outPath); - runPostBuildHook(worker.store, *logger, drvPath, outputPaths); + buildResult.timesBuilt++; + buildResult.stopTime = time(0); + + /* So the child is gone now. */ + worker.childTerminated(this); + + /* Close the read side of the logger pipe. */ + hook->builderOut.readSide.close(); + hook->fromHook.readSide.close(); + + /* Close the log file. */ + logFile.reset(); + + /* Check the exit status. */ + if (!statusOk(status)) { + auto e = fixupBuilderFailureErrorMessage({BuildResult::Failure::MiscFailure, status, ""}, *buildLog); - /* It is now safe to delete the lock files, since all future - lockers will see that the output paths are valid; they will - not create new lock files with the same names as the old - (unlinked) lock files. */ - outputLocks.setDeletion(true); outputLocks.unlock(); - co_return doneSuccess(BuildResult::Success::Built, std::move(builtOutputs)); + /* TODO (once again) support fine-grained error codes, see issue #12641. */ + + co_return doneFailure(std::move(e)); } + /* Compute the FS closure of the outputs and register them as + being valid. */ + auto builtOutputs = + /* When using a build hook, the build hook can register the output + as valid (by doing `nix-store --import'). If so we don't have + to do anything here. + + We can only early return when the outputs are known a priori. For + floating content-addressing derivations this isn't the case. + + Aborts if any output is not valid or corrupt, and otherwise + returns a 'SingleDrvOutputs' structure containing all outputs. + */ + [&] { + auto [allValid, validOutputs] = checkPathValidity(initialOutputs); + if (!allValid) + throw Error("some outputs are unexpectedly invalid"); + return validOutputs; + }(); + + StorePathSet outputPaths; + for (auto & [_, output] : builtOutputs) + outputPaths.insert(output.outPath); + runPostBuildHook(worker.store, *logger, drvPath, outputPaths); + + /* It is now safe to delete the lock files, since all future + lockers will see that the output paths are valid; they will + not create new lock files with the same names as the old + (unlinked) lock files. */ + outputLocks.setDeletion(true); + outputLocks.unlock(); + + co_return doneSuccess(BuildResult::Success::Built, std::move(builtOutputs)); +#endif +} + +Goal::Co DerivationBuildingGoal::buildLocally( + StorePathSet inputPaths, + std::map initialOutputs, + DerivationOptions drvOptions, + PathLocks outputLocks, + const ExternalBuilder * externalBuilder) +{ co_await yield(); if (!dynamic_cast(&worker.store)) { @@ -545,8 +628,29 @@ Goal::Co DerivationBuildingGoal::tryToBuild() #ifdef _WIN32 // TODO enable `DerivationBuilder` on Windows throw UnimplementedError("building derivations is not yet implemented on Windows"); #else - assert(!hook); + std::unique_ptr buildLog; + std::unique_ptr logFile; + auto openLogFile = [&]() { logFile = std::make_unique(worker.store, drvPath); }; + + auto closeLogFile = [&]() { logFile.reset(); }; + + auto started = [&]() { + auto msg = + fmt(buildMode == bmRepair ? "repairing outputs of '%s'" + : buildMode == bmCheck ? "checking outputs of '%s'" + : "building '%s'", + worker.store.printStorePath(drvPath)); + buildLog = std::make_unique( + settings.logLines, + std::make_unique( + *logger, lvlInfo, actBuild, msg, Logger::Fields{worker.store.printStorePath(drvPath), "", 1, 1})); + mcRunningBuilds = std::make_unique>(worker.runningBuilds); + worker.updateProgress(); + }; + + std::unique_ptr actLock; + std::unique_ptr builder; Descriptor builderOut; // Will continue here while waiting for a build user below @@ -556,7 +660,7 @@ Goal::Co DerivationBuildingGoal::tryToBuild() if (curBuilds >= settings.maxBuildJobs) { outputLocks.unlock(); co_await waitForBuildSlot(); - co_return tryToBuild(); + co_return tryToBuild(std::move(inputPaths)); } if (!builder) { @@ -567,10 +671,16 @@ Goal::Co DerivationBuildingGoal::tryToBuild() struct DerivationBuildingGoalCallbacks : DerivationBuilderCallbacks { DerivationBuildingGoal & goal; + std::function openLogFileFn; + std::function closeLogFileFn; DerivationBuildingGoalCallbacks( - DerivationBuildingGoal & goal, std::unique_ptr & builder) + DerivationBuildingGoal & goal, + std::function openLogFileFn, + std::function closeLogFileFn) : goal{goal} + , openLogFileFn{std::move(openLogFileFn)} + , closeLogFileFn{std::move(closeLogFileFn)} { } @@ -581,14 +691,14 @@ Goal::Co DerivationBuildingGoal::tryToBuild() goal.worker.childTerminated(&goal); } - std::filesystem::path openLogFile() override + void openLogFile() override { - return goal.openLogFile(); + openLogFileFn(); } void closeLogFile() override { - goal.closeLogFile(); + closeLogFileFn(); } }; @@ -638,15 +748,16 @@ Goal::Co DerivationBuildingGoal::tryToBuild() /* If we have to wait and retry (see below), then `builder` will already be created, so we don't need to create it again. */ - builder = externalBuilder ? makeExternalDerivationBuilder( - *localStoreP, - std::make_unique(*this, builder), - std::move(params), - *externalBuilder) - : makeDerivationBuilder( - *localStoreP, - std::make_unique(*this, builder), - std::move(params)); + builder = externalBuilder + ? makeExternalDerivationBuilder( + *localStoreP, + std::make_unique(*this, openLogFile, closeLogFile), + std::move(params), + *externalBuilder) + : makeDerivationBuilder( + *localStoreP, + std::make_unique(*this, openLogFile, closeLogFile), + std::move(params)); } if (auto builderOutOpt = builder->startBuild()) { @@ -671,16 +782,28 @@ Goal::Co DerivationBuildingGoal::tryToBuild() started(); + uint64_t logSize = 0; + while (true) { auto event = co_await WaitForChildEvent{}; if (auto * output = std::get_if(&event)) { - co_await processChildOutput(output->fd, output->data); + if (output->fd == builder->builderOut.get()) { + logSize += output->data.size(); + if (settings.maxLogSize && logSize > settings.maxLogSize) { + if (builder->killChild()) + worker.childTerminated(this); + co_return doneFailureLogTooLong(*buildLog); + } + (*buildLog)(output->data); + if (logFile->sink) + (*logFile->sink)(output->data); + } } else if (std::get_if(&event)) { - if (!currentLogLine.empty()) - flushLine(); + buildLog->flush(); break; } else if (auto * timeout = std::get_if(&event)) { - killChild(); + if (builder->killChild()) + worker.childTerminated(this); co_return doneFailure(std::move(*timeout)); } } @@ -693,7 +816,7 @@ Goal::Co DerivationBuildingGoal::tryToBuild() } catch (BuilderFailureError & e) { builder.reset(); outputLocks.unlock(); - co_return doneFailure(fixupBuilderFailureErrorMessage(std::move(e))); + co_return doneFailure(fixupBuilderFailureErrorMessage(std::move(e), *buildLog)); } catch (BuildError & e) { builder.reset(); outputLocks.unlock(); @@ -814,7 +937,7 @@ static void runPostBuildHook( }); } -BuildError DerivationBuildingGoal::fixupBuilderFailureErrorMessage(BuilderFailureError e) +BuildError DerivationBuildingGoal::fixupBuilderFailureErrorMessage(BuilderFailureError e, BuildLog & buildLog) { auto msg = fmt("Cannot build '%s'.\n" @@ -824,6 +947,7 @@ BuildError DerivationBuildingGoal::fixupBuilderFailureErrorMessage(BuilderFailur msg += showKnownOutputs(worker.store, *drv); + auto & logTail = buildLog.getTail(); if (!logger->isVerbose() && !logTail.empty()) { msg += fmt("\nLast %d log lines:\n", logTail.size()); for (auto & line : logTail) { @@ -846,8 +970,7 @@ BuildError DerivationBuildingGoal::fixupBuilderFailureErrorMessage(BuilderFailur return BuildError{e.status, msg}; } -HookReply DerivationBuildingGoal::tryBuildHook( - const std::map & initialOutputs, const DerivationOptions & drvOptions) +HookReply DerivationBuildingGoal::tryBuildHook(const DerivationOptions & drvOptions) { #ifdef _WIN32 // TODO enable build hook on Windows return rpDecline; @@ -912,61 +1035,19 @@ HookReply DerivationBuildingGoal::tryBuildHook( throw; } - hook = std::move(worker.hook); - - try { - hook->machineName = readLine(hook->fromHook.readSide.get()); - } catch (Error & e) { - e.addTrace({}, "while reading the machine name from the build hook"); - throw; - } - - CommonProto::WriteConn conn{hook->sink}; - - /* Tell the hook all the inputs that have to be copied to the - remote system. */ - CommonProto::write(worker.store, conn, inputPaths); - - /* Tell the hooks the missing outputs that have to be copied back - from the remote system. */ - { - StringSet missingOutputs; - for (auto & [outputName, status] : initialOutputs) { - // XXX: Does this include known CA outputs? - if (buildMode != bmCheck && status.known && status.known->isValid()) - continue; - missingOutputs.insert(outputName); - } - CommonProto::write(worker.store, conn, missingOutputs); - } - - hook->sink = FdSink(); - hook->toHook.writeSide.close(); - - /* Create the log file and pipe. */ - [[maybe_unused]] Path logFile = openLogFile(); - - std::set fds; - fds.insert(hook->fromHook.readSide.get()); - fds.insert(hook->builderOut.readSide.get()); - worker.childStarted(shared_from_this(), fds, false, false); - return rpAccept; #endif } -Path DerivationBuildingGoal::openLogFile() +LogFile::LogFile(Store & store, const StorePath & drvPath) { - logSize = 0; - if (!settings.keepLog) - return ""; + return; - auto baseName = std::string(baseNameOf(worker.store.printStorePath(drvPath))); + auto baseName = std::string(baseNameOf(store.printStorePath(drvPath))); - /* Create a log file. */ Path logDir; - if (auto localStore = dynamic_cast(&worker.store)) + if (auto localStore = dynamic_cast(&store)) logDir = localStore->config->logDir; else logDir = settings.nixLogDir; @@ -975,7 +1056,7 @@ Path DerivationBuildingGoal::openLogFile() Path logFileName = fmt("%s/%s%s", dir, baseName.substr(2), settings.compressLog ? ".bz2" : ""); - fdLogFile = toDescriptor(open( + fd = toDescriptor(open( logFileName.c_str(), O_CREAT | O_WRONLY | O_TRUNC #ifndef _WIN32 @@ -983,122 +1064,37 @@ Path DerivationBuildingGoal::openLogFile() #endif , 0666)); - if (!fdLogFile) + if (!fd) throw SysError("creating log file '%1%'", logFileName); - logFileSink = std::make_shared(fdLogFile.get()); + fileSink = std::make_shared(fd.get()); if (settings.compressLog) - logSink = std::shared_ptr(makeCompressionSink(CompressionAlgo::bzip2, *logFileSink)); + sink = std::shared_ptr(makeCompressionSink(CompressionAlgo::bzip2, *fileSink)); else - logSink = logFileSink; - - return logFileName; + sink = fileSink; } -void DerivationBuildingGoal::closeLogFile() +LogFile::~LogFile() { - auto logSink2 = std::dynamic_pointer_cast(logSink); - if (logSink2) - logSink2->finish(); - if (logFileSink) - logFileSink->flush(); - logSink = logFileSink = 0; - fdLogFile.close(); -} - -bool DerivationBuildingGoal::isReadDesc(Descriptor fd) -{ -#ifdef _WIN32 // TODO enable build hook on Windows - return false; -#else - return (hook && fd == hook->builderOut.readSide.get()) || (builder && fd == builder->builderOut.get()); -#endif -} - -Goal::Co DerivationBuildingGoal::processChildOutput(Descriptor fd, std::string_view data) -{ - // local & `ssh://`-builds are dealt with here. - auto isWrittenToLog = isReadDesc(fd); - if (isWrittenToLog) { - logSize += data.size(); - if (settings.maxLogSize && logSize > settings.maxLogSize) { - killChild(); - co_return doneFailure(BuildError( - BuildResult::Failure::LogLimitExceeded, - "%s killed after writing more than %d bytes of log output", - getName(), - settings.maxLogSize)); - } - - for (auto c : data) - if (c == '\r') - currentLogLinePos = 0; - else if (c == '\n') - flushLine(); - else { - if (currentLogLinePos >= currentLogLine.size()) - currentLogLine.resize(currentLogLinePos + 1); - currentLogLine[currentLogLinePos++] = c; - } - - if (logSink) - (*logSink)(data); - } - -#ifndef _WIN32 // TODO enable build hook on Windows - if (hook && fd == hook->fromHook.readSide.get()) { - for (auto c : data) - if (c == '\n') { - auto json = parseJSONMessage(currentHookLine, "the derivation builder"); - if (json) { - auto s = handleJSONLogMessage(*json, worker.act, hook->activities, "the derivation builder", true); - // ensure that logs from a builder using `ssh-ng://` as protocol - // are also available to `nix log`. - if (s && !isWrittenToLog && logSink) { - const auto type = (*json)["type"]; - const auto fields = (*json)["fields"]; - if (type == resBuildLogLine) { - (*logSink)((fields.size() > 0 ? fields[0].get() : "") + "\n"); - } else if (type == resSetPhase && !fields.is_null()) { - const auto phase = fields[0]; - if (!phase.is_null()) { - // nixpkgs' stdenv produces lines in the log to signal - // phase changes. - // We want to get the same lines in case of remote builds. - // The format is: - // @nix { "action": "setPhase", "phase": "$curPhase" } - const auto logLine = nlohmann::json::object({{"action", "setPhase"}, {"phase", phase}}); - (*logSink)( - "@nix " + logLine.dump(-1, ' ', false, nlohmann::json::error_handler_t::replace) - + "\n"); - } - } - } - } - currentHookLine.clear(); - } else - currentHookLine += c; + try { + auto sink2 = std::dynamic_pointer_cast(sink); + if (sink2) + sink2->finish(); + if (fileSink) + fileSink->flush(); + } catch (...) { + ignoreExceptionInDestructor(); } -#endif - co_return Return{}; } -void DerivationBuildingGoal::flushLine() +Goal::Done DerivationBuildingGoal::doneFailureLogTooLong(BuildLog & buildLog) { - if (handleJSONLogMessage(currentLogLine, *act, builderActivities, "the derivation builder", false)) - ; - - else { - logTail.push_back(currentLogLine); - if (logTail.size() > settings.logLines) - logTail.pop_front(); - - act->result(resBuildLogLine, currentLogLine); - } - - currentLogLine = ""; - currentLogLinePos = 0; + return doneFailure(BuildError( + BuildResult::Failure::LogLimitExceeded, + "%s killed after writing more than %d bytes of log output", + getName(), + settings.maxLogSize)); } std::map> DerivationBuildingGoal::queryPartialDerivationOutputMap() diff --git a/src/libstore/include/nix/store/build/build-log.hh b/src/libstore/include/nix/store/build/build-log.hh new file mode 100644 index 00000000000..cdc9125734d --- /dev/null +++ b/src/libstore/include/nix/store/build/build-log.hh @@ -0,0 +1,84 @@ +#pragma once +///@file + +#include "nix/util/logging.hh" +#include "nix/util/serialise.hh" + +#include +#include +#include + +namespace nix { + +/** + * Line buffering and log tracking for build output. + * + * This class handles: + * - Owning the build Activity for logging + * - Buffering partial lines (handling \r and \n) + * - Maintaining a tail of recent log lines (for error messages) + * - Processing JSON log messages via handleJSONLogMessage + * + * Implements Sink so it can be used as a data destination. + * I/O is handled separately by the caller. + */ +struct BuildLog : Sink +{ +private: + size_t maxTailLines; + + std::list logTail; + std::string currentLogLine; + size_t currentLogLinePos = 0; // to handle carriage return + + void flushLine(); + +public: + /** + * The build activity. Owned by BuildLog. + */ + std::unique_ptr act; + + /** + * Map for tracking nested activities from JSON messages. + */ + std::map builderActivities; + + /** + * @param maxTailLines Maximum number of tail lines to keep + * @param act Activity for this build + */ + BuildLog(size_t maxTailLines, std::unique_ptr act); + + /** + * Process output data from child process. + * Handles JSON log messages and emits regular lines to activity. + * @param data Raw output data from child + */ + void operator()(std::string_view data) override; + + /** + * Flush any remaining partial line. + * Call this when the child process exits. + */ + void flush(); + + /** + * Get the most recent log lines. + * Used for including in error messages. + */ + const std::list & getTail() const + { + return logTail; + } + + /** + * Check if there's an incomplete line buffered. + */ + bool hasPartialLine() const + { + return !currentLogLine.empty(); + } +}; + +} // namespace nix diff --git a/src/libstore/include/nix/store/build/derivation-builder.hh b/src/libstore/include/nix/store/build/derivation-builder.hh index 29011ee5b55..f19b7002f15 100644 --- a/src/libstore/include/nix/store/build/derivation-builder.hh +++ b/src/libstore/include/nix/store/build/derivation-builder.hh @@ -111,7 +111,7 @@ struct DerivationBuilderCallbacks /** * Open a log file and a pipe to it. */ - virtual std::filesystem::path openLogFile() = 0; + virtual void openLogFile() = 0; /** * Close the log file. diff --git a/src/libstore/include/nix/store/build/derivation-building-goal.hh b/src/libstore/include/nix/store/build/derivation-building-goal.hh index eb94df88bcd..d8fb967aedf 100644 --- a/src/libstore/include/nix/store/build/derivation-building-goal.hh +++ b/src/libstore/include/nix/store/build/derivation-building-goal.hh @@ -9,12 +9,14 @@ #include "nix/store/store-api.hh" #include "nix/store/pathlocks.hh" #include "nix/store/build/goal.hh" +#include "nix/store/build/build-log.hh" namespace nix { using std::map; struct BuilderFailureError; +struct ExternalBuilder; #ifndef _WIN32 // TODO enable build hook on Windows struct HookInstance; struct DerivationBuilder; @@ -45,93 +47,46 @@ struct DerivationBuildingGoal : public Goal private: /** The path of the derivation. */ - StorePath drvPath; + const StorePath drvPath; /** * The derivation stored at drvPath. */ - std::unique_ptr drv; + const std::unique_ptr drv; /** * The remainder is state held during the build. */ - /** - * All input paths (that is, the union of FS closures of the - * immediate input paths). - */ - StorePathSet inputPaths; - - /** - * File descriptor for the log file. - */ - AutoCloseFD fdLogFile; - std::shared_ptr logFileSink, logSink; - - /** - * Number of bytes received from the builder's stdout/stderr. - */ - unsigned long logSize; - - /** - * The most recent log lines. - */ - std::list logTail; - - std::string currentLogLine; - size_t currentLogLinePos = 0; // to handle carriage return - - std::string currentHookLine; - -#ifndef _WIN32 // TODO enable build hook on Windows - /** - * The build hook. - */ - std::unique_ptr hook; - - std::unique_ptr builder; -#endif - - BuildMode buildMode; + const BuildMode buildMode; std::unique_ptr> mcRunningBuilds; - std::unique_ptr act; - - std::map builderActivities; - std::string key() override; /** * The states. */ Co gaveUpOnSubstitution(bool storeDerivation); - Co tryToBuild(); + Co tryToBuild(StorePathSet inputPaths); + Co buildWithHook( + StorePathSet inputPaths, + std::map initialOutputs, + DerivationOptions drvOptions, + PathLocks outputLocks); + Co buildLocally( + StorePathSet inputPaths, + std::map initialOutputs, + DerivationOptions drvOptions, + PathLocks outputLocks, + const ExternalBuilder * externalBuilder); /** * Is the build hook willing to perform the build? */ - HookReply tryBuildHook( - const std::map & initialOutputs, const DerivationOptions & drvOptions); + HookReply tryBuildHook(const DerivationOptions & drvOptions); - /** - * Open a log file and a pipe to it. - */ - Path openLogFile(); - - /** - * Close the log file. - */ - void closeLogFile(); - - bool isReadDesc(Descriptor fd); - - /** - * Process output from a child process. - */ - Co processChildOutput(Descriptor fd, std::string_view data); - - void flushLine(); + Done doneFailureLogTooLong(BuildLog & buildLog); /** * Wrappers around the corresponding Store methods that first consult the @@ -148,16 +103,11 @@ private: */ std::pair checkPathValidity(std::map & initialOutputs); - /** - * Forcibly kill the child process, if any. - */ - void killChild(); - Done doneSuccess(BuildResult::Success::Status status, SingleDrvOutputs builtOutputs); Done doneFailure(BuildError ex); - BuildError fixupBuilderFailureErrorMessage(BuilderFailureError msg); + BuildError fixupBuilderFailureErrorMessage(BuilderFailureError msg, BuildLog & buildLog); JobCategory jobCategory() const override { diff --git a/src/libstore/include/nix/store/meson.build b/src/libstore/include/nix/store/meson.build index c17d6a9cb5a..c7026818ea7 100644 --- a/src/libstore/include/nix/store/meson.build +++ b/src/libstore/include/nix/store/meson.build @@ -13,6 +13,7 @@ headers = [ config_pub_h ] + files( 'aws-creds.hh', 'binary-cache-store.hh', 'build-result.hh', + 'build/build-log.hh', 'build/derivation-builder.hh', 'build/derivation-building-goal.hh', 'build/derivation-building-misc.hh', diff --git a/src/libstore/meson.build b/src/libstore/meson.build index 6d570229966..0e5a9cb7bb4 100644 --- a/src/libstore/meson.build +++ b/src/libstore/meson.build @@ -275,6 +275,7 @@ subdir('nix-meson-build-support/common') sources = files( 'binary-cache-store.cc', 'build-result.cc', + 'build/build-log.cc', 'build/derivation-builder.cc', 'build/derivation-building-goal.cc', 'build/derivation-check.cc',