Adding logging to the nix-daemon

[catern]

It would be useful if the nix-daemon logged requests it receives and operations it performs. Among other things, this would be useful for:

• debugging issues when developing the client
• maintaining a fully detailed log of what Nix operations are performed (useful in both single-user and multi-user installations)
• performing analytics about Nix usage in a true multi-user installation

It would be straightforward to implement this at a basic level, but there are some questions to consider.

1. Should the nix-daemon log in plain text or in some structured format?
2. Should the logging be implemented by nix-daemon itself, or by a separate tool that snoops on nix-daemon communications and summarizes them?
3. If the nix-daemon logs in plain text to its stderr, how do we differentiate different users and connections which might be interleaved?
4. Should we include STDERR_NEXT etc messages which are sent to the client in the logs?

The easiest format would be having nix-daemon itself log each request and each response as a single line, and have each line contain information about the connection and user. Something like this, perhaps:

2018-01-31 16:22:47.139 [user:catern,conn:10923123] request: buildPaths bmNormal [ /nix/store/aaaaaaaaaaaaaaaaaaaaaa-things ]
2018-01-31 16:22:47.139 [user:catern,conn:10923123] response: OK

[lheckemann]

Could be related to, though much broader in scope, #1710

[lovasko]

I have created a basic version of such logging for all the operation performed by the nix-daemon: lovasko@60be099

Any opinions and/or suggestions? All are welcome! :)

[shlevy]

@lovasko Is there a reason to use syslog above just stderr?

[lovasko]

@shlevy my thinking was, that since this is a daemon, a fully daemonised process does not have open stdout/stderr streams. This way, syslog provides the ability to produce logs in a fully "stealth" mode. But, since there is the stdio mode, we can still output to the stderr facility by using the LOG_PERROR flag, as described here: http://man7.org/linux/man-pages/man3/syslog.3.html

Sadly, LOG_PERROR isn't fully standard, but is very commonplace.

[edolstra]

Systemd forwards stderr to the journal. Nix even emits severity levels for use by journald (see SimpleLogger). If syslog support is really desired, it would be better to implement it as a subclass of Logger, rather than putting syslog() calls everywhere.

[edolstra]

BTW I'm skeptical that logging every request is useful. A typical evaluation can issue thousands of requests, so this will cause some serious log spamming.

[jtrakk]

It will be informative if each message contains a uuid and the uuid of its parent task. That way the full task tree can be constructed from the logs. This idea is in OpenCensus, OpenTracing, and Eliot among others.

[stale]

I marked this as stale due to inactivity. → More info