From f29dfb3d3cb8fd4d1053eeca2da2a25495a2cee4 Mon Sep 17 00:00:00 2001 From: eldritch horrors Date: Sat, 11 Oct 2025 21:59:56 +0200 Subject: [PATCH] libutil: add buffer state management to loggers currently all loggers can always accept messages and never suggest flushing buffers. in the future this may change, and at that point we're already fully set up for it. local loggers should never keep asynchronous (i.e. network-backed) buffers, disk buffers are fine. networked loggers will require buffers and periodic flushes later. Change-Id: Ide2114f5bc17f4a1d289c92ed4f9381a1d59dacf --- lix/libmain/progress-bar.cc | 34 +++-- lix/libmain/progress-bar.hh | 13 +- lix/libstore/build/derivation-goal.cc | 39 +++--- lix/libstore/build/derivation-goal.hh | 2 +- lix/libstore/daemon.cc | 31 +++-- lix/libstore/filetransfer.cc | 9 +- lix/libstore/store-api.cc | 6 + lix/libutil/logging.cc | 91 ++++++++----- lix/libutil/logging.hh | 177 ++++++++++++++++++-------- tests/unit/libexpr/primops.cc | 9 +- tests/unit/libmain/progress-bar.cc | 2 +- tests/unit/libstore/filetransfer.cc | 6 +- 12 files changed, 279 insertions(+), 140 deletions(-) diff --git a/lix/libmain/progress-bar.cc b/lix/libmain/progress-bar.cc index 841b8b24b..378ffacd3 100644 --- a/lix/libmain/progress-bar.cc +++ b/lix/libmain/progress-bar.cc @@ -104,31 +104,34 @@ bool ProgressBar::isVerbose() return printBuildLogs; } -void ProgressBar::log(Verbosity lvl, std::string_view s) +Logger::BufferState ProgressBar::log(Verbosity lvl, std::string_view s) { - if (lvl > verbosity) return; + if (lvl > verbosity) { + return BufferState::HasSpace; + } auto state(state_.lock()); - log(*state, lvl, s); + return log(*state, lvl, s); } -void ProgressBar::logEI(const ErrorInfo & ei) +Logger::BufferState ProgressBar::logEI(const ErrorInfo & ei) { auto state(state_.lock()); std::stringstream oss; showErrorInfo(oss, ei, loggerSettings.showTrace.get()); - log(*state, ei.level, oss.str()); + return log(*state, ei.level, oss.str()); } -void ProgressBar::log(State & state, Verbosity lvl, std::string_view s) +Logger::BufferState ProgressBar::log(State & state, Verbosity lvl, std::string_view s) { if (state.paused == 0) eraseProgressDisplay(state); writeLogsToStderr(filterANSIEscapes(s + ANSI_NORMAL "\n", !isTTY)); restoreProgressDisplay(state); + return BufferState::HasSpace; } -void ProgressBar::startActivityImpl( +Logger::BufferState ProgressBar::startActivityImpl( ActivityId act, Verbosity lvl, ActivityType type, @@ -140,7 +143,7 @@ void ProgressBar::startActivityImpl( auto state(state_.lock()); if (lvl <= verbosity && !s.empty() && type != actBuildWaiting) - log(*state, lvl, s + "..."); + (void) log(*state, lvl, s + "..."); state->activities.emplace_back(ActInfo { .s = s, @@ -198,6 +201,7 @@ void ProgressBar::startActivityImpl( i->visible = false; update(*state); + return BufferState::HasSpace; } /* Check whether an activity has an ancestore with the specified @@ -213,7 +217,7 @@ bool ProgressBar::hasAncestor(State & state, ActivityType type, ActivityId act) return false; } -void ProgressBar::stopActivityImpl(ActivityId act) +Logger::BufferState ProgressBar::stopActivityImpl(ActivityId act) { auto state(state_.lock()); @@ -233,9 +237,11 @@ void ProgressBar::stopActivityImpl(ActivityId act) } update(*state); + return BufferState::HasSpace; } -void ProgressBar::resultImpl(ActivityId act, ResultType type, const std::vector & fields) +Logger::BufferState +ProgressBar::resultImpl(ActivityId act, ResultType type, const std::vector & fields) { auto state(state_.lock()); @@ -256,7 +262,11 @@ void ProgressBar::resultImpl(ActivityId act, ResultType type, const std::vector< if (type == resPostBuildLogLine) { suffix = " (post)> "; } - log(*state, lvlInfo, ANSI_FAINT + info.name.value_or("unnamed") + suffix + ANSI_NORMAL + lastLine); + (void) log( + *state, + lvlInfo, + ANSI_FAINT + info.name.value_or("unnamed") + suffix + ANSI_NORMAL + lastLine + ); } else { if (!printMultiline) { state->activities.erase(i->second); @@ -310,6 +320,8 @@ void ProgressBar::resultImpl(ActivityId act, ResultType type, const std::vector< state->activitiesByType[type].expected += j; update(*state); } + + return BufferState::HasSpace; } void ProgressBar::update(State & state) diff --git a/lix/libmain/progress-bar.hh b/lix/libmain/progress-bar.hh index 0fc6f005e..a3f2b580d 100644 --- a/lix/libmain/progress-bar.hh +++ b/lix/libmain/progress-bar.hh @@ -75,13 +75,13 @@ struct ProgressBar : public Logger bool isVerbose() override; - void log(Verbosity lvl, std::string_view s) override; + BufferState log(Verbosity lvl, std::string_view s) override; - void logEI(const ErrorInfo & ei) override; + BufferState logEI(const ErrorInfo & ei) override; - void log(State & state, Verbosity lvl, std::string_view s); + BufferState log(State & state, Verbosity lvl, std::string_view s); - void startActivityImpl( + BufferState startActivityImpl( ActivityId act, Verbosity lvl, ActivityType type, @@ -92,9 +92,10 @@ struct ProgressBar : public Logger bool hasAncestor(State & state, ActivityType type, ActivityId act); - void stopActivityImpl(ActivityId act) override; + BufferState stopActivityImpl(ActivityId act) override; - void resultImpl(ActivityId act, ResultType type, const std::vector & fields) override; + BufferState + resultImpl(ActivityId act, ResultType type, const std::vector & fields) override; void update(State & state); diff --git a/lix/libstore/build/derivation-goal.cc b/lix/libstore/build/derivation-goal.cc index e043c6525..0c7cf27b0 100644 --- a/lix/libstore/build/derivation-goal.cc +++ b/lix/libstore/build/derivation-goal.cc @@ -1261,9 +1261,11 @@ try { for (auto c : data) if (c == '\r') currentLogLinePos = 0; - else if (c == '\n') - flushLine(); - else { + else if (c == '\n') { + if (flushLine() == Logger::BufferState::NeedsFlush) { + TRY_AWAIT(act->getLogger().flush()); + } + } else { if (currentLogLinePos >= currentLogLine.size()) currentLogLine.resize(currentLogLinePos + 1); currentLogLine[currentLogLinePos++] = c; @@ -1357,12 +1359,13 @@ try { ); } - return handlers.then([this](auto r) { - if (!currentLogLine.empty()) flushLine(); - return r; - }); + const auto r = TRY_AWAIT(handlers); + if (!currentLogLine.empty() && flushLine() == Logger::BufferState::NeedsFlush) { + TRY_AWAIT(act->getLogger().flush()); + } + co_return r; } catch (...) { - return {result::current_exception()}; + co_return result::current_exception(); } kj::Promise>> DerivationGoal::monitorForSilence() noexcept @@ -1413,20 +1416,24 @@ DerivationGoal::handleChildStreams(AsyncInputStream * builderIn, AsyncInputStrea co_return std::nullopt; } -void DerivationGoal::flushLine() +Logger::BufferState DerivationGoal::flushLine() { - if (handleJSONLogMessage(currentLogLine, *act, builderActivities, "the derivation builder", false)) - ; + KJ_DEFER({ + currentLogLine = ""; + currentLogLinePos = 0; + }); - else { + if (const auto state = handleJSONLogMessage( + currentLogLine, *act, builderActivities, "the derivation builder", false + )) + { + return *state; + } else { logTail.push_back(currentLogLine); if (logTail.size() > settings.logLines) logTail.pop_front(); - act->result(resBuildLogLine, currentLogLine); + return act->result(resBuildLogLine, currentLogLine); } - - currentLogLine = ""; - currentLogLinePos = 0; } diff --git a/lix/libstore/build/derivation-goal.hh b/lix/libstore/build/derivation-goal.hh index 3389a0f1a..2df3adf42 100644 --- a/lix/libstore/build/derivation-goal.hh +++ b/lix/libstore/build/derivation-goal.hh @@ -325,7 +325,7 @@ protected: kj::Promise>> handleHookOutput(AsyncInputStream & in) noexcept; kj::Promise>> monitorForSilence() noexcept; WorkResult tooMuchLogs(); - void flushLine(); + Logger::BufferState flushLine(); virtual std::string buildErrorContents(const std::string & exitMsg, bool diskFull); diff --git a/lix/libstore/daemon.cc b/lix/libstore/daemon.cc index 75e156a77..e129f552e 100644 --- a/lix/libstore/daemon.cc +++ b/lix/libstore/daemon.cc @@ -64,7 +64,7 @@ struct TunnelLogger : public Logger assert(clientVersion >= MIN_SUPPORTED_WORKER_PROTO_VERSION); } - void enqueueMsg(const std::string & s) + BufferState enqueueMsg(const std::string & s) { auto state(state_.lock()); @@ -81,27 +81,32 @@ struct TunnelLogger : public Logger } } else state->pendingMsgs.push_back(s); + return BufferState::HasSpace; } - void log(Verbosity lvl, std::string_view s) override + BufferState log(Verbosity lvl, std::string_view s) override { - if (lvl > verbosity) return; + if (lvl > verbosity) { + return BufferState::HasSpace; + } StringSink buf; buf << STDERR_NEXT << (s + "\n"); - enqueueMsg(buf.s); + return enqueueMsg(buf.s); } - void logEI(const ErrorInfo & ei) override + BufferState logEI(const ErrorInfo & ei) override { - if (ei.level > verbosity) return; + if (ei.level > verbosity) { + return BufferState::HasSpace; + } std::stringstream oss; showErrorInfo(oss, ei, false); StringSink buf; buf << STDERR_NEXT << oss.str(); - enqueueMsg(buf.s); + return enqueueMsg(buf.s); } /* startWork() means that we're starting an operation for which we @@ -134,7 +139,7 @@ struct TunnelLogger : public Logger } } - void startActivityImpl( + BufferState startActivityImpl( ActivityId act, Verbosity lvl, ActivityType type, @@ -145,21 +150,21 @@ struct TunnelLogger : public Logger { StringSink buf; buf << STDERR_START_ACTIVITY << act << lvl << type << s << fields << parent; - enqueueMsg(buf.s); + return enqueueMsg(buf.s); } - void stopActivityImpl(ActivityId act) override + BufferState stopActivityImpl(ActivityId act) override { StringSink buf; buf << STDERR_STOP_ACTIVITY << act; - enqueueMsg(buf.s); + return enqueueMsg(buf.s); } - void resultImpl(ActivityId act, ResultType type, const Fields & fields) override + BufferState resultImpl(ActivityId act, ResultType type, const Fields & fields) override { StringSink buf; buf << STDERR_RESULT << act << type << fields; - enqueueMsg(buf.s); + return enqueueMsg(buf.s); } }; diff --git a/lix/libstore/filetransfer.cc b/lix/libstore/filetransfer.cc index a8087b1da..37b2f48cb 100644 --- a/lix/libstore/filetransfer.cc +++ b/lix/libstore/filetransfer.cc @@ -3,6 +3,7 @@ #include "lix/libutil/async.hh" #include "lix/libutil/c-calls.hh" #include "lix/libutil/error.hh" +#include "lix/libutil/logging.hh" #include "lix/libutil/namespaces.hh" #include "lix/libstore/globals.hh" #include "lix/libstore/store-api.hh" @@ -373,7 +374,9 @@ struct curlFileTransfer : public FileTransfer int progressCallback(curl_off_t dltotal, curl_off_t dlnow) { try { - act.progress(dlnow, dltotal); + if (act.progress(dlnow, dltotal) == Logger::BufferState::NeedsFlush) { + act.getLogger().waitForSpace(); + } } catch (nix::Interrupted &) { } return isInterrupted(); @@ -405,7 +408,9 @@ struct curlFileTransfer : public FileTransfer else if (code == CURLE_OK && successfulStatuses.count(httpStatus)) { - act.progress(bodySize, bodySize); + if (act.progress(bodySize, bodySize) == Logger::BufferState::NeedsFlush) { + act.getLogger().waitForSpace(); + } auto state = downloadState.lock(); state->done = true; state->signal(); diff --git a/lix/libstore/store-api.cc b/lix/libstore/store-api.cc index 3472dc66f..328de248c 100644 --- a/lix/libstore/store-api.cc +++ b/lix/libstore/store-api.cc @@ -383,6 +383,12 @@ try { if (!settings.keepGoing) throw e; printMsg(lvlError, "could not copy %s: %s", printStorePath(path), e.what()); + goto failed; + } + + // can't co_await in catch, so we need this monstrosity + if (false) { + failed: SHOW_PROGRESS(); co_return result::success(); } diff --git a/lix/libutil/logging.cc b/lix/libutil/logging.cc index c451b52b1..d189f4119 100644 --- a/lix/libutil/logging.cc +++ b/lix/libutil/logging.cc @@ -11,6 +11,7 @@ #include #include #include +#include #include #include @@ -31,7 +32,9 @@ Activity Logger::startActivity( ) { Activity result{*this}; - startActivityImpl(result.id, lvl, type, s, fields, parent ? parent->id : 0); + // NOTE we assume that activities aren't started in monstrous numbers, so the inevitable + // state updates (via progress, result, or setExpected) should be enough to flush stuff. + (void) startActivityImpl(result.id, lvl, type, s, fields, parent ? parent->id : 0); return result; } @@ -72,9 +75,11 @@ public: return printBuildLogs; } - void log(Verbosity lvl, std::string_view s) override + BufferState log(Verbosity lvl, std::string_view s) override { - if (lvl > verbosity) return; + if (lvl > verbosity) { + return BufferState::HasSpace; + } std::string prefix; @@ -92,17 +97,18 @@ public: } writeLogsToStderr(prefix + filterANSIEscapes(s, !tty) + "\n"); + return BufferState::HasSpace; } - void logEI(const ErrorInfo & ei) override + BufferState logEI(const ErrorInfo & ei) override { std::stringstream oss; showErrorInfo(oss, ei, loggerSettings.showTrace.get()); - log(ei.level, oss.str()); + return log(ei.level, oss.str()); } - void startActivityImpl( + BufferState startActivityImpl( ActivityId act, Verbosity lvl, ActivityType type, @@ -111,11 +117,13 @@ public: ActivityId parent ) override { - if (lvl <= verbosity && !s.empty()) - log(lvl, s + "..."); + if (lvl <= verbosity && !s.empty()) { + return log(lvl, s + "..."); + } + return BufferState::HasSpace; } - void resultImpl(ActivityId act, ResultType type, const Fields & fields) override + BufferState resultImpl(ActivityId act, ResultType type, const Fields & fields) override { if (type == resBuildLogLine && printBuildLogs) { auto lastLine = fields[0].s; @@ -125,6 +133,7 @@ public: auto lastLine = fields[0].s; printError("post-build-hook: %1%", Uncolored(lastLine)); } + return BufferState::HasSpace; } }; @@ -184,21 +193,23 @@ struct JSONLogger : Logger { abort(); } - void write(const JSON & json) + BufferState write(const JSON & json) { - prevLogger.log(lvlError, "@nix " + json.dump(-1, ' ', false, JSON::error_handler_t::replace)); + return prevLogger.log( + lvlError, "@nix " + json.dump(-1, ' ', false, JSON::error_handler_t::replace) + ); } - void log(Verbosity lvl, std::string_view s) override + BufferState log(Verbosity lvl, std::string_view s) override { JSON json; json["action"] = "msg"; json["level"] = lvl; json["msg"] = s; - write(json); + return write(json); } - void logEI(const ErrorInfo & ei) override + BufferState logEI(const ErrorInfo & ei) override { std::ostringstream oss; showErrorInfo(oss, ei, loggerSettings.showTrace.get()); @@ -222,10 +233,10 @@ struct JSONLogger : Logger { json["trace"] = traces; } - write(json); + return write(json); } - void startActivityImpl( + BufferState startActivityImpl( ActivityId act, Verbosity lvl, ActivityType type, @@ -242,25 +253,25 @@ struct JSONLogger : Logger { json["text"] = s; json["parent"] = parent; addFields(json, fields); - write(json); + return write(json); } - void stopActivityImpl(ActivityId act) override + BufferState stopActivityImpl(ActivityId act) override { JSON json; json["action"] = "stop"; json["id"] = act; - write(json); + return write(json); } - void resultImpl(ActivityId act, ResultType type, const Fields & fields) override + BufferState resultImpl(ActivityId act, ResultType type, const Fields & fields) override { JSON json; json["action"] = "result"; json["id"] = act; json["type"] = type; addFields(json, fields); - write(json); + return write(json); } }; @@ -295,9 +306,13 @@ std::optional parseJSONMessage(const std::string & msg, std::string_view s return std::nullopt; } -bool handleJSONLogMessage(JSON & json, - const Activity & act, std::map & activities, - std::string_view source, bool trusted) +std::optional handleJSONLogMessage( + JSON & json, + const Activity & act, + std::map & activities, + std::string_view source, + bool trusted +) { try { std::string action = json["action"]; @@ -319,33 +334,40 @@ bool handleJSONLogMessage(JSON & json, else if (action == "result") { auto i = activities.find((ActivityId) json["id"]); if (i != activities.end()) - i->second.result((ResultType) json["type"], getFields(json["fields"])); + return i->second.result((ResultType) json["type"], getFields(json["fields"])); } else if (action == "setPhase") { std::string phase = json["phase"]; - act.result(resSetPhase, phase); + return act.result(resSetPhase, phase); } else if (action == "msg") { std::string msg = json["msg"]; - logger->log((Verbosity) json["level"], msg); + return logger->log((Verbosity) json["level"], msg); } - return true; + return Logger::BufferState::HasSpace; } catch (JSON::exception &e) { // NOLINT(lix-foreign-exceptions) printTaggedWarning( "Unable to handle a JSON message from %s: %s", Uncolored(source), e.what() ); - return false; + return std::nullopt; } } -bool handleJSONLogMessage(const std::string & msg, - const Activity & act, std::map & activities, std::string_view source, bool trusted) +std::optional handleJSONLogMessage( + const std::string & msg, + const Activity & act, + std::map & activities, + std::string_view source, + bool trusted +) { auto json = parseJSONMessage(msg, source); - if (!json) return false; + if (!json) { + return std::nullopt; + } return handleJSONLogMessage(*json, act, activities, source, trusted); } @@ -356,7 +378,10 @@ Activity::~Activity() return; } try { - logger->stopActivityImpl(id); + // NOTE we can't flush here, and async destruction of activities is bound to fail + // at some point. eventually something will flush the buffer for us (see also the + // startActivity comment, we also don't flush buffers there even when they fill.) + (void) logger->stopActivityImpl(id); } catch (...) { ignoreExceptionInDestructor(); } diff --git a/lix/libutil/logging.hh b/lix/libutil/logging.hh index 9aab120b6..e95d315b2 100644 --- a/lix/libutil/logging.hh +++ b/lix/libutil/logging.hh @@ -4,6 +4,10 @@ #include "lix/libutil/types.hh" #include "lix/libutil/error.hh" #include "lix/libutil/config.hh" +#include "result.hh" +#include "serialise.hh" +#include +#include namespace nix { @@ -105,6 +109,11 @@ class Logger public: + enum class [[nodiscard]] BufferState { + HasSpace, + NeedsFlush, + }; + struct Field { // FIXME: use std::variant. @@ -127,14 +136,19 @@ public: // Whether the logger prints the whole build log virtual bool isVerbose() { return false; } - virtual void log(Verbosity lvl, std::string_view s) = 0; + virtual BufferState bufferState() const + { + return BufferState::HasSpace; + } - virtual void logEI(const ErrorInfo & ei) = 0; + virtual BufferState log(Verbosity lvl, std::string_view s) = 0; - void logEI(Verbosity lvl, ErrorInfo ei) + virtual BufferState logEI(const ErrorInfo & ei) = 0; + + BufferState logEI(Verbosity lvl, ErrorInfo ei) { ei.level = lvl; - logEI(ei); + return logEI(ei); } Activity startActivity( @@ -148,19 +162,35 @@ public: Activity startActivity(ActivityType type, const Fields & fields = {}, const Activity * parent = nullptr); + virtual kj::Promise> flush() + { + return {result::success()}; + } + + virtual void waitForSpace() {} + protected: - virtual void startActivityImpl( + virtual BufferState startActivityImpl( ActivityId act, Verbosity lvl, ActivityType type, const std::string & s, const Fields & fields, ActivityId parent - ) {}; + ) + { + return BufferState::HasSpace; + } - virtual void stopActivityImpl(ActivityId act) {}; + virtual BufferState stopActivityImpl(ActivityId act) + { + return BufferState::HasSpace; + } - virtual void resultImpl(ActivityId act, ResultType type, const Fields & fields) {}; + virtual BufferState resultImpl(ActivityId act, ResultType type, const Fields & fields) + { + return BufferState::HasSpace; + } public: virtual void writeToStdout(std::string_view s); @@ -216,6 +246,11 @@ public: ~Activity(); + Logger & getLogger() const + { + return *logger; + } + void swap(Activity & other) { std::swap(logger, other.logger); @@ -232,23 +267,29 @@ public: return logger->startActivity(level, type, s, fields, this); } - void progress(uint64_t done = 0, uint64_t expected = 0, uint64_t running = 0, uint64_t failed = 0) const - { result(resProgress, done, expected, running, failed); } + Logger::BufferState progress( + uint64_t done = 0, uint64_t expected = 0, uint64_t running = 0, uint64_t failed = 0 + ) const + { + return result(resProgress, done, expected, running, failed); + } - void setExpected(ActivityType type2, uint64_t expected) const - { result(resSetExpected, type2, expected); } + Logger::BufferState setExpected(ActivityType type2, uint64_t expected) const + { + return result(resSetExpected, type2, expected); + } template - void result(ResultType type, const Args & ... args) const + Logger::BufferState result(ResultType type, const Args &... args) const { Logger::Fields fields; nop{(fields.emplace_back(Logger::Field(args)), 1)...}; - result(type, fields); + return result(type, fields); } - void result(ResultType type, const Logger::Fields & fields) const + Logger::BufferState result(ResultType type, const Logger::Fields & fields) const { - logger->resultImpl(id, type, fields); + return logger->resultImpl(id, type, fields); } friend class Logger; @@ -265,49 +306,71 @@ Logger * makeJSONLogger(Logger & prevLogger); */ extern Verbosity verbosity; -#define ACTIVITY_PROGRESS(act, ...) \ - do { \ - auto && _lix_act = (act); \ - _lix_act.progress(__VA_ARGS__); \ +#define ACTIVITY_PROGRESS(act, ...) \ + do { \ + auto && _lix_act = (act); \ + if (_lix_act.progress(__VA_ARGS__) == ::nix::Logger::BufferState::NeedsFlush) { \ + LIX_TRY_AWAIT(_lix_act.getLogger().flush()); \ + } \ } while (0) -#define ACTIVITY_RESULT(act, ...) \ - do { \ - auto && _lix_act = (act); \ - _lix_act.result(__VA_ARGS__); \ +#define ACTIVITY_RESULT(act, ...) \ + do { \ + auto && _lix_act = (act); \ + if (_lix_act.result(__VA_ARGS__) == ::nix::Logger::BufferState::NeedsFlush) { \ + LIX_TRY_AWAIT(_lix_act.getLogger().flush()); \ + } \ } while (0) -#define ACTIVITY_SET_EXPECTED(act, ...) \ - do { \ - auto && _lix_act = (act); \ - _lix_act.setExpected(__VA_ARGS__); \ +#define ACTIVITY_SET_EXPECTED(act, ...) \ + do { \ + auto && _lix_act = (act); \ + if (_lix_act.setExpected(__VA_ARGS__) == ::nix::Logger::BufferState::NeedsFlush) { \ + LIX_TRY_AWAIT(_lix_act.getLogger().flush()); \ + } \ } while (0) -#define ACTIVITY_PROGRESS_SYNC(aio, act, ...) \ - do { \ - auto && _lix_act = (act); \ - _lix_act.progress(__VA_ARGS__); \ +#define ACTIVITY_PROGRESS_SYNC(aio, act, ...) \ + do { \ + auto && _lix_act = (act); \ + if (_lix_act.progress(__VA_ARGS__) == ::nix::Logger::BufferState::NeedsFlush) { \ + (aio).blockOn(_lix_act.getLogger().flush()); \ + } \ } while (0) -#define ACTIVITY_RESULT_SYNC(aio, act, ...) \ - do { \ - auto && _lix_act = (act); \ - _lix_act.result(__VA_ARGS__); \ +#define ACTIVITY_RESULT_SYNC(aio, act, ...) \ + do { \ + auto && _lix_act = (act); \ + if (_lix_act.result(__VA_ARGS__) == ::nix::Logger::BufferState::NeedsFlush) { \ + (aio).blockOn(_lix_act.getLogger().flush()); \ + } \ } while (0) -#define ACTIVITY_SET_EXPECTED_SYNC(aio, act, ...) \ - do { \ - auto && _lix_act = (act); \ - _lix_act.setExpected(__VA_ARGS__); \ +#define ACTIVITY_SET_EXPECTED_SYNC(aio, act, ...) \ + do { \ + auto && _lix_act = (act); \ + if (_lix_act.setExpected(__VA_ARGS__) == ::nix::Logger::BufferState::NeedsFlush) { \ + (aio).blockOn(_lix_act.getLogger().flush()); \ + } \ } while (0) +// NOTE: unlike activity progress updates we *do not* flush buffers for "normal" +// messages. the largest producers or log items are builds (which report logs as +// activity results), the curl thread (which can only wait after we have reached +// a buffer watermark, not actually flush it due to kj limitations), debug level +// log messages (which are not latency-sensitive), and interactive use (which we +// only ever run with a logger that writes directly to stderr). we have tried to +// add buffer flushing to these log macros, but it turned out to be *incredibly* +// invasive in many places to outright impossible in some, such as logError in a +// catch block (because c++ doesn't allow awaits in catch blocks). fucking mess. + /** * Print a message with the standard ErrorInfo format. * In general, use these 'log' macros for reporting problems that may require user * intervention or that need more explanation. Use the 'print' macros for more * lightweight status messages. */ -#define logErrorInfo(level, errorInfo...) \ - do { \ - if ((level) <= ::nix::verbosity) { \ - ::nix::logger->logEI((level), errorInfo); \ - } \ +#define logErrorInfo(level, errorInfo...) \ + do { \ + if ((level) <= ::nix::verbosity) { \ + (void) ::nix::logger->logEI((level), errorInfo); \ + } \ } while (0) #define logError(errorInfo...) logErrorInfo(::nix::lvlError, errorInfo) @@ -323,7 +386,8 @@ extern Verbosity verbosity; auto _lix_logger_print_lvl = level; \ const char * _lix_format = [](const char(&_lix_fs)[N]) { return _lix_fs; }(fs); \ if (_lix_logger_print_lvl <= ::nix::verbosity) { \ - loggerParam->log(_lix_logger_print_lvl, ::nix::HintFmt(_lix_format, ##args).str()); \ + (void \ + ) loggerParam->log(_lix_logger_print_lvl, ::nix::HintFmt(_lix_format, ##args).str()); \ } \ } while (0) #define printMsg(level, fs, args...) printMsgUsing(::nix::logger, level, fs, ##args) @@ -353,17 +417,24 @@ std::optional parseJSONMessage(const std::string & msg, std::string_view s /** * @param source A noun phrase describing the source of the message, e.g. "the builder". */ -bool handleJSONLogMessage(JSON & json, - const Activity & act, std::map & activities, +[[nodiscard]] +std::optional handleJSONLogMessage( + JSON & json, + const Activity & act, + std::map & activities, std::string_view source, - bool trusted); + bool trusted +); /** * @param source A noun phrase describing the source of the message, e.g. "the builder". */ -bool handleJSONLogMessage(const std::string & msg, - const Activity & act, std::map & activities, +[[nodiscard]] +std::optional handleJSONLogMessage( + const std::string & msg, + const Activity & act, + std::map & activities, std::string_view source, - bool trusted); - + bool trusted +); } diff --git a/tests/unit/libexpr/primops.cc b/tests/unit/libexpr/primops.cc index 6669d1cf1..4e3c4072a 100644 --- a/tests/unit/libexpr/primops.cc +++ b/tests/unit/libexpr/primops.cc @@ -3,6 +3,7 @@ #include "lix/libexpr/eval-settings.hh" +#include "lix/libutil/logging.hh" #include "tests/libexpr.hh" namespace nix { @@ -17,12 +18,16 @@ namespace nix { return oss.str(); } - void log(Verbosity lvl, std::string_view s) override { + BufferState log(Verbosity lvl, std::string_view s) override + { oss << s << std::endl; + return BufferState::HasSpace; } - void logEI(const ErrorInfo & ei) override { + BufferState logEI(const ErrorInfo & ei) override + { showErrorInfo(oss, ei, loggerSettings.showTrace.get()); + return BufferState::HasSpace; } }; diff --git a/tests/unit/libmain/progress-bar.cc b/tests/unit/libmain/progress-bar.cc index eb4a2acbb..1187bee28 100644 --- a/tests/unit/libmain/progress-bar.cc +++ b/tests/unit/libmain/progress-bar.cc @@ -34,7 +34,7 @@ namespace nix fmt("downloading '%s'", TEST_URL), {"https://github.com/NixOS/nixpkgs/archive/master.tar.gz"} ); - act.progress(TEST_DONE, TEST_EXPECTED); + (void) act.progress(TEST_DONE, TEST_EXPECTED); auto state = progressBar.state_.lock(); std::string const renderedStatus = progressBar.getStatus(*state); diff --git a/tests/unit/libstore/filetransfer.cc b/tests/unit/libstore/filetransfer.cc index a1d584cd3..7d4f227a8 100644 --- a/tests/unit/libstore/filetransfer.cc +++ b/tests/unit/libstore/filetransfer.cc @@ -431,15 +431,17 @@ TEST(FileTransfer, DISABLED_interrupt) { struct InterruptingLogger : Logger { - void log(Verbosity lvl, std::string_view s) override + BufferState log(Verbosity lvl, std::string_view s) override { if (s.starts_with("finished") && s.ends_with("body = 10 bytes")) { triggerInterrupt(); checkInterrupt(); } + return BufferState::HasSpace; } - void logEI(const ErrorInfo & ei) override + BufferState logEI(const ErrorInfo & ei) override { + return BufferState::HasSpace; } };