Add an option to print the logs in a machine-readable format #3073

thufschmitt · 2019-08-30T15:05:37Z

Add a --log-format option which can be used to print the logs in json (pretty similar to the json logger used internally) so that external tools can easily consume it.

This required moving things around a bit because nix 2.0-style commands where overriding the logging mechanism to display the status bar (which made the --log-format option unusable). As a nice side effect, nix 1.0-style commands can now use --log-format bar to get the status bar

edolstra · 2019-08-30T18:11:23Z

src/nix/main.cc

@@ -79,8 +78,8 @@ struct NixArgs : virtual MultiCommand, virtual MixCommonArgs
        mkFlag()
            .longName("print-build-logs")
            .shortName('L')
-            .description("print full build logs on stderr")
-            .set(&printBuildLogs, true);
+            .description("print full build logs on stderr. DEPRECATED, use '--log-format bar-with-logs' instead")


This message implies that -L is also deprecated, which should not be the case.

Indeed. I've removed it altogether. Tell me if you still want a depreciation warning on --print-build-logs

edolstra · 2019-08-30T18:12:20Z

src/libutil/logging.cc

+    logFormatJSON,
+    logFormatBar,
+    logFormatBarWithLogs,
+} LogFormat;


Can you move most of this to src/nix? That way src/libutil only contains the abstract Logger class and the implementations are in src/nix.

Or alternatively to src/libmain.

I've moved most of it to libmain. The implementation of SimpleLogger is still in that file, and JSONLogger is also still in libutil (because it's strongly tied to handleJSONLogMessage and that one is used in libstore). Does that look good?

edolstra · 2019-08-30T18:14:36Z

src/libutil/logging.cc

+
+    nlohmann::json jsonActivityType(ActivityType type) override
+    {
+        switch (type) {


I think it's more maintainable to log the activity type and result type as a numerical value.

It's an annoying tradeoff to make because magic numbers are definitely not user-friendly, but I agree these custom-print functions will probably cause some issue at some point (unless there's a way to auto-generate it?).

I've removed the custom json logger in 1e893d4, so we're back to numerical values.

thufschmitt · 2019-09-03T07:16:43Z

I'm having some second-though on that PR: The internal json isn't really nice to work with from outside of Nix, so it would be nicer to first settle on a nicer format before being tied to a non-so-nice representation

zimbatm · 2019-09-03T09:59:35Z

What makes it not so nice to use?

thufschmitt · 2019-09-03T10:20:21Z

There's a number of small things which either make it non-intuitive or require some non-trivial logic to get some useful information from it. In particular I noted:

The format of the messages isn't really standardized between the different kind of messages (for instance most messages have a text field for storing some free-form message, except the msg message type which has a msg field for that. Also, most messages have a level field, but not all)
Some information is packed into the fields field which contains a list of free-form elements, and it's up to the user to guess what each element corresponds to
Amongst the most useful messages types are activityStart and activityStop which indicate when each phase of the internal pipeline (instantiation, substitution, hooks) start and stop. But the activityStop messages only contain an id which maps them to a previous activityStart, meaning that to make sense of it a client must keep internally a map of all the started activities to know which activity has ended, and retrieve from that the type of activity, its various parameters, etc…
The activity types are magic numerical constants (so quite hard to interpret), although this has been discussed in Add an option to print the logs in a machine-readable format #3073 (comment) and is likely to stay that way

(note that I'm not at all saying that it's a bad format per se, it seems to work quite well inside of Nix, but it's probably not a good format for an external consumption by a client which doesn't know the internals of Nix)

thufschmitt · 2019-09-19T07:26:04Z

I'm lacking of time to work on this right now. @edolstra What do you think of renaming the json log-format to internal-json merge this as it-is? That way we already have an (explicitely unstable and not user-friendly) machine-readable log, and we keep the possibility to add a nicer json log-format later.

edolstra · 2019-09-25T11:45:36Z

@regnat Yes, I think this looks good as-is.

edolstra · 2019-09-25T11:47:42Z

src/libmain/loggers.cc

+    logFormatRaw,
+    logFormatJSON,
+    logFormatBar,
+    logFormatBarWithLogs,


What is bar-with-logs? Is it the same as nix --print-build-logs / -L?

yes: https://github.com/tweag/nix/blob/5bc27445e686fdc1be849f4183a1ff6ada9a921c/src/nix/main.cc#L78-L82

edolstra · 2019-09-25T11:48:57Z

src/libmain/loggers.cc

+    case logFormatBarWithLogs:
+        return createProgressBar(true);
+    default:
+        throw Error(format("Invalid log format '%i'") % logFormat);


This should be written as

throw Error("invalid log format '%i'", logFormat);

Also note that exception messages are not capitalized.

fixed in 5bc2744

Fixes NixOS#3073 (comment)

zimbatm · 2019-09-26T16:56:56Z

and now with documentation. @edolstra is there anything else you would like to see happening for this PR?

thufschmitt · 2019-10-03T10:09:53Z

Just noticed that this somehow cause builtins:buildEnv to fail with "Bad file descriptor" when using the daemon unless we pass at least four -v flags to nix. I'll give it a look

zimbatm · 2019-10-09T11:44:11Z

@regnat I don't think the sandboxed builder should emit any logs, this is the real issue IMO.

zimbatm · 2019-10-09T11:45:01Z

stracing the nix-daemon:

[pid 12635] write(4, "gmlo\0\0\0\0P\0\0\0\0\0\0\0@nix {\"action\":\""..., 96) = -1 EBADF (Bad file descriptor)
[pid 12635] write(2, "error: writing to file: Bad file"..., 44) = 44
[pid 12630] read(10, "error: writing to file: Bad file"..., 4096) = 44
[pid 12630] write(4, "gmlo\0\0\0\0,\0\0\0\0\0\0\0error: writing t"..., 64) = 64
[pid 12630] write(4, "TLSR\0\0\0\0\t\0\0\0\37)\0\0e\0\0\0\0\0\0\0\1\0\0\0\0\0\0\0"..., 96) = 96
[pid 12630] select(11, [10], NULL, NULL, NULL <unfinished ...>
[pid 12635] +++ exited with 1 +++
(edited)

pid 12635 is a build sandbox

zimbatm · 2019-10-09T11:45:29Z

when the sandbox starts, it closes all the existing file descriptors except 1 and 2 (and 12 twice), so that's why writing to FD 4 is not possible.

[pid 12635] close(12)                   = 0
[pid 12635] close(3)                    = 0
[pid 12635] close(4)                    = 0
[pid 12635] close(5)                    = 0
[pid 12635] close(6)                    = 0
[pid 12635] close(7)                    = 0
[pid 12635] close(8)                    = 0
[pid 12635] close(9)                    = 0
[pid 12635] close(10)                   = 0
[pid 12635] close(11)                   = 0
[pid 12635] close(12)                   = -1 EBADF (Bad file descriptor)

edolstra · 2019-10-09T13:02:26Z

This is probably caused by logger not being reset in the child process. startProcess() does this:

        if (!options.allowVfork)
            logger = makeDefaultLogger();

which means that the child has the wrong logger if allowVfork = true.

Fixes NixOS#3073 (comment)

thufschmitt · 2019-12-17T12:22:20Z

@edolstra I've fixed the file descriptor issue (was apparently due to vfork indeed) and rebased on top of master − I've also found why the nix-env failure hadn't been caught in the tests.

edolstra · 2019-12-17T18:19:56Z

src/libmain/progress-bar.cc

@@ -153,7 +164,7 @@ class ProgressBar : public Logger
        state->activitiesByType[type].its.emplace(act, i);

        if (type == actBuild) {
-            auto name = storePathToName(getS(fields, 0));
+            auto name = getName(fields, 4);


This no longer abbreviates the name, i.e. the progress bar now looks like this:

[1/0/2 built, 16.7 MiB DL] building /nix/store/g29xgw3fy960ghskj45x4x1mjv6jv3l2-nix-tarball-2.4pre7196_d94cc07 (autoconfPhase): autoreconf: running: ...

Indeed, this was happening when using an older daemon (because the messages sent back by the daemon have been extended to include the (abbreviated) derivation name, but there's a fallback code for old daemons that don't do it, but it was missing a call to storePathToName).
Should be good now

Fix NixOS#3073 (comment)

edolstra · 2019-12-18T09:06:11Z

src/libmain/progress-bar.cc

@@ -17,20 +16,32 @@ static std::string getS(const std::vector<Logger::Field> & fields, size_t n)
    return fields[n].s;
 }

+static std::string storePathToName(std::string path)


Maybe use the original version? std::string_view is cheaper than std::string.

Profpatsch · 2020-01-17T19:34:56Z

Might I ping this? :)

Add a new `--log-format` cli argument to change the format of the logs. The possible values are - raw (the default one for old-style commands) - bar (the default one for new-style commands) - bar-with-logs (equivalent to `--print-build-logs`) - internal-json (the internal machine-readable json format)

Make the printing of the build logs systematically go through the logger, and replicate the behavior of `no-build-output` by having two different loggers (one that prints the build logs and one that doesn't)

thufschmitt · 2020-06-08T07:31:33Z

I've been reminded of this last week, so I rebased this on top of the latest master and simplified it as much as I could (well, nearly rewritten it from scratch actually 🤔 ), let me know what you think

edolstra · 2020-06-08T11:22:30Z

src/libmain/loggers.cc

@@ -0,0 +1,51 @@
+#include "loggers.hh"
+#include "../nix/progress-bar.hh"


This makes libmain depend on nix, which is a layering violation. It means you can't link against libmain anymore.

Mh that's annoying 🤔

I moved progress-bar to libmain to fix that, but it also required moving paths to libutil to prevent libmain from depending on libexpr. Not sure if that's a great idea

Needed so that we can include it as a logger in loggers.cc without adding a dependency on nix This also requires moving names.hh to libutil to prevent a circular dependency between libmain and libexpr

edolstra · 2020-06-11T13:45:25Z

Merged, thanks!

edolstra reviewed Aug 30, 2019

View reviewed changes

edolstra reviewed Sep 25, 2019

View reviewed changes

zimbatm added a commit to tweag/nix that referenced this pull request Sep 26, 2019

fixup! error without format

5bc2744

Fixes NixOS#3073 (comment)

zimbatm mentioned this pull request Oct 6, 2019

Scoped logs for Nix builds #3117

Open

thufschmitt pushed a commit to tweag/nix that referenced this pull request Dec 17, 2019

fixup! error without format

82ec8a4

Fixes NixOS#3073 (comment)

thufschmitt force-pushed the machine-logs branch from bd8a216 to 4a43d51 Compare December 17, 2019 12:20

edolstra reviewed Dec 17, 2019

View reviewed changes

thufschmitt added a commit to tweag/nix that referenced this pull request Dec 17, 2019

Fix the displayed names when using an old daemon

0846c9c

Fix NixOS#3073 (comment)

edolstra reviewed Dec 18, 2019

View reviewed changes

thufschmitt force-pushed the machine-logs branch 2 times, most recently from 73851d6 to aa251ad Compare June 8, 2020 07:30

thufschmitt and others added 3 commits June 8, 2020 09:31

add documentation

2c4de6a

Unify the printing of the logs between bar-with-logs and raw

4983401

Make the printing of the build logs systematically go through the logger, and replicate the behavior of `no-build-output` by having two different loggers (one that prints the build logs and one that doesn't)

thufschmitt force-pushed the machine-logs branch from aa251ad to 4983401 Compare June 8, 2020 07:31

edolstra reviewed Jun 8, 2020

View reviewed changes

edolstra and others added 5 commits June 8, 2020 13:24

Style fixes

c27f926

Move progress-bar.cc to libmain

801112d

Needed so that we can include it as a logger in loggers.cc without adding a dependency on nix This also requires moving names.hh to libutil to prevent a circular dependency between libmain and libexpr

Style fixes

8bd8921

Shut up warning

95eb064

Move names.{cc,hh} to libstore

dd9bb11

edolstra merged commit ac4d43a into NixOS:master Jun 11, 2020

edolstra deleted the machine-logs branch June 11, 2020 13:45

Profpatsch mentioned this pull request Jun 11, 2020

Use nix’s support of structured log output (--log-format) target/lorri#418

Open

This was referenced Jan 2, 2021

Fix #4234, send build logs to Nix 2.3 #4418

Closed

nixUnstable prints each log line twice when used against stable nix-daemon #4244

Open

Build logs are missing when using nixUnstable hercules-ci/hercules-ci-agent#261

Closed

ldesgoui mentioned this pull request Aug 1, 2021

Write Nix 2.4 release notes #4521

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Add an option to print the logs in a machine-readable format #3073

Add an option to print the logs in a machine-readable format #3073

thufschmitt commented Aug 30, 2019

edolstra Aug 30, 2019

thufschmitt Sep 2, 2019

edolstra Aug 30, 2019

edolstra Aug 30, 2019

thufschmitt Sep 2, 2019

edolstra Aug 30, 2019

thufschmitt Sep 2, 2019

thufschmitt commented Sep 3, 2019

zimbatm commented Sep 3, 2019

thufschmitt commented Sep 3, 2019

thufschmitt commented Sep 19, 2019

edolstra commented Sep 25, 2019

edolstra Sep 25, 2019

zimbatm Sep 26, 2019

edolstra Sep 25, 2019

zimbatm Sep 26, 2019

zimbatm commented Sep 26, 2019

thufschmitt commented Oct 3, 2019

zimbatm commented Oct 9, 2019

zimbatm commented Oct 9, 2019

zimbatm commented Oct 9, 2019 •

edited

edolstra commented Oct 9, 2019

thufschmitt commented Dec 17, 2019

edolstra Dec 17, 2019

thufschmitt Dec 17, 2019

edolstra Dec 18, 2019

Profpatsch commented Jan 17, 2020

thufschmitt commented Jun 8, 2020

edolstra Jun 8, 2020

thufschmitt Jun 8, 2020

edolstra commented Jun 11, 2020

		@@ -0,0 +1,51 @@
		#include "loggers.hh"
		#include "../nix/progress-bar.hh"

Add an option to print the logs in a machine-readable format #3073

Add an option to print the logs in a machine-readable format #3073

Conversation

thufschmitt commented Aug 30, 2019

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

thufschmitt commented Sep 3, 2019

zimbatm commented Sep 3, 2019

thufschmitt commented Sep 3, 2019

thufschmitt commented Sep 19, 2019

edolstra commented Sep 25, 2019

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

zimbatm commented Sep 26, 2019

thufschmitt commented Oct 3, 2019

zimbatm commented Oct 9, 2019

zimbatm commented Oct 9, 2019

zimbatm commented Oct 9, 2019 • edited

edolstra commented Oct 9, 2019

thufschmitt commented Dec 17, 2019

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Profpatsch commented Jan 17, 2020

thufschmitt commented Jun 8, 2020

Choose a reason for hiding this comment

Choose a reason for hiding this comment

edolstra commented Jun 11, 2020

zimbatm commented Oct 9, 2019 •

edited