Skip to content

Commit 5ab7428

Browse files
thomasjmTom McLaughlin
thomasjm
authored and
Tom McLaughlin
committed
New logger: JSON diffs
This is a new logger that outputs the build state in the form of a series of RFC 6902 JSON patches. The first line it outputs is an empty object, and then it periodically outputs diffs which transform the initial object until the build completes. This is used to efficiently support downstream tools which want to consume Nix build information and display it in a UI.
1 parent c396e24 commit 5ab7428

File tree

5 files changed

+298
-1
lines changed

5 files changed

+298
-1
lines changed

‎src/libmain/loggers.cc‎

Lines changed: 6 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1,5 +1,6 @@
1-
#include "loggers.hh"
21
#include "environment-variables.hh"
2+
#include "loggers.hh"
3+
#include "logging-diffs.hh"
34
#include "progress-bar.hh"
45

56
namespace nix {
@@ -13,6 +14,8 @@ LogFormat parseLogFormat(const std::string & logFormatStr) {
1314
return LogFormat::rawWithLogs;
1415
else if (logFormatStr == "internal-json")
1516
return LogFormat::internalJSON;
17+
else if (logFormatStr == "diffs")
18+
return LogFormat::diffs;
1619
else if (logFormatStr == "bar")
1720
return LogFormat::bar;
1821
else if (logFormatStr == "bar-with-logs")
@@ -28,6 +31,8 @@ Logger * makeDefaultLogger() {
2831
return makeSimpleLogger(true);
2932
case LogFormat::internalJSON:
3033
return makeJSONLogger(*makeSimpleLogger(true));
34+
case LogFormat::diffs:
35+
return makeDiffLogger(*makeSimpleLogger(true));
3136
case LogFormat::bar:
3237
return makeProgressBar();
3338
case LogFormat::barWithLogs: {

‎src/libmain/loggers.hh‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -9,6 +9,7 @@ enum class LogFormat {
99
raw,
1010
rawWithLogs,
1111
internalJSON,
12+
diffs,
1213
bar,
1314
barWithLogs,
1415
};

‎src/libutil/logging-diffs.cc‎

Lines changed: 238 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,238 @@
1+
2+
#include "config.hh"
3+
#include "logging.hh"
4+
#include "logging-diffs.hh"
5+
#include "position.hh"
6+
#include "sync.hh"
7+
#include "util.hh"
8+
9+
#include <atomic>
10+
#include <chrono>
11+
#include <iostream>
12+
#include <nlohmann/json.hpp>
13+
#include <thread>
14+
15+
using json = nlohmann::json;
16+
17+
namespace nix {
18+
19+
void addFields(json & json, const Logger::Fields & fields)
20+
{
21+
if (fields.empty()) return;
22+
auto & arr = json["fields"] = json::array();
23+
for (auto & f : fields)
24+
if (f.type == Logger::Field::tInt)
25+
arr.push_back(f.i);
26+
else if (f.type == Logger::Field::tString)
27+
arr.push_back(f.s);
28+
else
29+
abort();
30+
}
31+
32+
void to_json(json & j, const NixMessage & m)
33+
{
34+
j = json{ {"level", m.level} };
35+
36+
if (m.line.has_value()) j["line"] = m.line.value();
37+
if (m.column.has_value()) j["column"] = m.column.value();
38+
if (m.file.has_value()) j["file"] = m.file.value();
39+
40+
if (m.trace.has_value()) j["trace"] = m.trace.value();
41+
42+
if (!m.msg.empty()) j["msg"] = m.msg;
43+
if (!m.raw_msg.empty()) j["raw_msg"] = m.raw_msg;
44+
}
45+
46+
void to_json(json & j, const ActivityState & as)
47+
{
48+
j = json{ {"is_complete", as.isComplete}, {"type", as.type}, {"text", as.text} };
49+
addFields(j, as.fields);
50+
}
51+
52+
void to_json(json & j, const NixBuildState & s)
53+
{
54+
j = json{ {"messages", s.messages} };
55+
56+
j["activities"] = json(json::value_t::object);
57+
for (const auto& [key, value] : s.activities) {
58+
j["activities"][std::to_string(key)] = value;
59+
}
60+
}
61+
62+
static void addPosToMessage(NixMessage & msg, std::shared_ptr<Pos> pos)
63+
{
64+
if (pos) {
65+
msg.line = pos->line;
66+
msg.column = pos->column;
67+
std::ostringstream str;
68+
pos->print(str, true);
69+
msg.file = str.str();
70+
} else {
71+
msg.line = std::nullopt;
72+
msg.column = std::nullopt;
73+
msg.file = std::nullopt;
74+
}
75+
}
76+
77+
static void posToJson(json & json, std::shared_ptr<Pos> pos)
78+
{
79+
if (pos) {
80+
json["line"] = pos->line;
81+
json["column"] = pos->column;
82+
std::ostringstream str;
83+
pos->print(str, true);
84+
json["file"] = str.str();
85+
} else {
86+
json["line"] = nullptr;
87+
json["column"] = nullptr;
88+
json["file"] = nullptr;
89+
}
90+
}
91+
92+
struct DiffLogger : Logger {
93+
Logger & prevLogger;
94+
95+
Sync<NixBuildState> state;
96+
json last_sent;
97+
std::mutex lock;
98+
std::atomic_bool exitPeriodicAction;
99+
std::atomic_bool exited;
100+
std::thread printerThread;
101+
102+
DiffLogger(Logger & prevLogger)
103+
: prevLogger(prevLogger)
104+
, last_sent(nullptr)
105+
, exitPeriodicAction(false)
106+
, exited(false)
107+
, printerThread(std::thread(&DiffLogger::periodicAction, this))
108+
{ }
109+
110+
// Note: tried to move the contents of the stop() fn to ~DiffLogger, but couldn't get
111+
// it to run.
112+
113+
~DiffLogger() {
114+
this->stop();
115+
}
116+
117+
void stop() override {
118+
// Make stop() idempotent
119+
if (this->exitPeriodicAction) return;
120+
121+
this->exitPeriodicAction = true;
122+
this->printerThread.join();
123+
sendLatestIfNecessary();
124+
this->exited = true;
125+
}
126+
127+
void periodicAction() {
128+
// Send initial value as a normal value
129+
{
130+
auto state_(state.lock());
131+
write(*state_);
132+
this->last_sent = *state_;
133+
}
134+
135+
while (true) {
136+
if (this->exitPeriodicAction) break;
137+
138+
sendLatestIfNecessary();
139+
140+
std::this_thread::sleep_for(std::chrono::milliseconds(300));
141+
}
142+
}
143+
144+
void sendLatestIfNecessary() {
145+
auto state_(state.lock());
146+
this->sendLatestIfNecessaryUnlocked(state_);
147+
}
148+
149+
void sendLatestIfNecessaryUnlocked(Sync<NixBuildState>::WriteLock & _state) {
150+
if (this->last_sent == *_state) return;
151+
152+
write(json::diff(this->last_sent, *_state));
153+
this->last_sent = *_state;
154+
}
155+
156+
bool isVerbose() override {
157+
return true;
158+
}
159+
160+
void write(const json & json)
161+
{
162+
prevLogger.log(lvlError, json.dump(-1, ' ', false, json::error_handler_t::replace));
163+
}
164+
165+
void log(Verbosity lvl, std::string_view s) override
166+
{
167+
auto state_(state.lock());
168+
NixMessage msg;
169+
msg.msg = s;
170+
state_->messages.push_back(msg);
171+
172+
// Not sure why, but sometimes log messages happen after stop() is called
173+
if (this->exited) sendLatestIfNecessaryUnlocked(state_);
174+
}
175+
176+
void logEI(const ErrorInfo & ei) override
177+
{
178+
NixMessage msg;
179+
180+
std::ostringstream oss;
181+
showErrorInfo(oss, ei, loggerSettings.showTrace.get());
182+
183+
msg.level = ei.level;
184+
msg.msg = oss.str();
185+
msg.raw_msg = ei.msg.str();
186+
187+
addPosToMessage(msg, ei.pos);
188+
189+
if (loggerSettings.showTrace.get() && !ei.traces.empty()) {
190+
json traces = json::array();
191+
for (auto iter = ei.traces.rbegin(); iter != ei.traces.rend(); ++iter) {
192+
json stackFrame;
193+
stackFrame["raw_msg"] = iter->hint.str();
194+
posToJson(stackFrame, iter->pos);
195+
traces.push_back(stackFrame);
196+
}
197+
198+
msg.trace = traces;
199+
}
200+
201+
auto state_(state.lock());
202+
state_->messages.push_back(msg);
203+
204+
// Not sure why, but sometimes log messages happen after stop() is called
205+
if (this->exited) sendLatestIfNecessaryUnlocked(state_);
206+
}
207+
208+
void startActivity(ActivityId act, Verbosity lvl, ActivityType type,
209+
const std::string & s, const Fields & fields, ActivityId parent) override
210+
{
211+
ActivityState as(type, s, fields, parent);
212+
auto state_(state.lock());
213+
state_->activities.insert(std::pair<ActivityId, ActivityState>(act, as));
214+
}
215+
216+
void stopActivity(ActivityId act) override
217+
{
218+
auto state_(state.lock());
219+
try { state_->activities.at(act).isComplete = true; }
220+
catch (const std::out_of_range& oor) { }
221+
}
222+
223+
void result(ActivityId act, ResultType type, const Fields & fields) override
224+
{
225+
auto state_(state.lock());
226+
try { state_->activities.at(act).fields = fields; }
227+
catch (const std::out_of_range& oor) {
228+
Logger::writeToStdout("Failed to look up result of type " + std::to_string(static_cast<int>(type)));
229+
}
230+
}
231+
};
232+
233+
Logger * makeDiffLogger(Logger & prevLogger)
234+
{
235+
return new DiffLogger(prevLogger);
236+
}
237+
238+
}

‎src/libutil/logging-diffs.hh‎

Lines changed: 51 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,51 @@
1+
#pragma once
2+
3+
#include "types.hh"
4+
#include "error.hh"
5+
#include "config.hh"
6+
#include "logging.hh"
7+
8+
#include <nlohmann/json.hpp>
9+
10+
#include <list>
11+
#include <map>
12+
#include <optional>
13+
14+
namespace nix {
15+
16+
Logger * makeDiffLogger(Logger & prevLogger);
17+
18+
struct ActivityState {
19+
bool isComplete;
20+
ActivityType type;
21+
std::string text;
22+
Logger::Fields fields;
23+
ActivityId parent;
24+
25+
ActivityState(ActivityType _type, const std::string _text, const Logger::Fields &_fields, ActivityId _parent):
26+
isComplete(false),
27+
type(_type),
28+
text(_text),
29+
fields(_fields),
30+
parent(_parent) { }
31+
};
32+
33+
struct NixMessage {
34+
int level;
35+
36+
std::optional<int> line;
37+
std::optional<int> column;
38+
std::optional<std::string> file;
39+
40+
std::optional<nlohmann::json> trace;
41+
42+
std::string msg;
43+
std::string raw_msg;
44+
};
45+
46+
struct NixBuildState {
47+
std::map<ActivityId, ActivityState> activities;
48+
std::list<NixMessage> messages;
49+
};
50+
51+
}

‎src/libutil/meson.build‎

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -147,6 +147,7 @@ sources = files(
147147
'hilite.cc',
148148
'json-utils.cc',
149149
'logging.cc',
150+
'logging-diffs.cc',
150151
'memory-source-accessor.cc',
151152
'position.cc',
152153
'posix-source-accessor.cc',
@@ -209,6 +210,7 @@ headers = [config_h] + files(
209210
'json-impls.hh',
210211
'json-utils.hh',
211212
'logging.hh',
213+
'logging-diffs.cc',
212214
'lru-cache.hh',
213215
'memory-source-accessor.hh',
214216
'muxable-pipe.hh',

0 commit comments

Comments
 (0)