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
This commit is contained in:
+23
-11
@@ -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<Field> & fields)
|
||||
Logger::BufferState
|
||||
ProgressBar::resultImpl(ActivityId act, ResultType type, const std::vector<Field> & 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)
|
||||
|
||||
@@ -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<Field> & fields) override;
|
||||
BufferState
|
||||
resultImpl(ActivityId act, ResultType type, const std::vector<Field> & fields) override;
|
||||
|
||||
void update(State & state);
|
||||
|
||||
|
||||
@@ -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<Result<std::optional<Goal::WorkResult>>> 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;
|
||||
}
|
||||
|
||||
|
||||
|
||||
@@ -325,7 +325,7 @@ protected:
|
||||
kj::Promise<Result<std::optional<WorkResult>>> handleHookOutput(AsyncInputStream & in) noexcept;
|
||||
kj::Promise<Result<std::optional<WorkResult>>> monitorForSilence() noexcept;
|
||||
WorkResult tooMuchLogs();
|
||||
void flushLine();
|
||||
Logger::BufferState flushLine();
|
||||
|
||||
virtual std::string buildErrorContents(const std::string & exitMsg, bool diskFull);
|
||||
|
||||
|
||||
+18
-13
@@ -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);
|
||||
}
|
||||
};
|
||||
|
||||
|
||||
@@ -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();
|
||||
|
||||
@@ -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();
|
||||
}
|
||||
|
||||
+58
-33
@@ -11,6 +11,7 @@
|
||||
#include <algorithm>
|
||||
#include <atomic>
|
||||
#include <mutex>
|
||||
#include <optional>
|
||||
#include <sstream>
|
||||
#include <syslog.h>
|
||||
|
||||
@@ -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<JSON> parseJSONMessage(const std::string & msg, std::string_view s
|
||||
return std::nullopt;
|
||||
}
|
||||
|
||||
bool handleJSONLogMessage(JSON & json,
|
||||
const Activity & act, std::map<ActivityId, Activity> & activities,
|
||||
std::string_view source, bool trusted)
|
||||
std::optional<Logger::BufferState> handleJSONLogMessage(
|
||||
JSON & json,
|
||||
const Activity & act,
|
||||
std::map<ActivityId, Activity> & 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<ActivityId, Activity> & activities, std::string_view source, bool trusted)
|
||||
std::optional<Logger::BufferState> handleJSONLogMessage(
|
||||
const std::string & msg,
|
||||
const Activity & act,
|
||||
std::map<ActivityId, Activity> & 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();
|
||||
}
|
||||
|
||||
+124
-53
@@ -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 <kj/async.h>
|
||||
#include <optional>
|
||||
|
||||
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<Result<void>> 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<typename... Args>
|
||||
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 = []<size_t N>(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<JSON> 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<ActivityId, Activity> & activities,
|
||||
[[nodiscard]]
|
||||
std::optional<Logger::BufferState> handleJSONLogMessage(
|
||||
JSON & json,
|
||||
const Activity & act,
|
||||
std::map<ActivityId, Activity> & 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<ActivityId, Activity> & activities,
|
||||
[[nodiscard]]
|
||||
std::optional<Logger::BufferState> handleJSONLogMessage(
|
||||
const std::string & msg,
|
||||
const Activity & act,
|
||||
std::map<ActivityId, Activity> & activities,
|
||||
std::string_view source,
|
||||
bool trusted);
|
||||
|
||||
bool trusted
|
||||
);
|
||||
}
|
||||
|
||||
@@ -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;
|
||||
}
|
||||
};
|
||||
|
||||
|
||||
@@ -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);
|
||||
|
||||
|
||||
@@ -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;
|
||||
}
|
||||
};
|
||||
|
||||
|
||||
Reference in New Issue
Block a user