journald: add tracing-journald crate implementing a simple journald layer

[Ralith]

Motivation

Support for writing tracing-based logs directly to their standard destination while preserving both standard and custom metadata on Linux systems. Improves usability of Linux services and for Linux applications executing outside of a terminal.

Solution

It turns out journald's native protocol is very simple and spoken over a Unix datagram socket at a fixed location (see discussion of stability of these interfaces), allowing high quality native support with ~100LoC.

I'm particularly interested in feedback on a few of the compromises made in this draft:

• The documentation for the upstream API dictates:

  [field names] must be in uppercase and consist only of characters, numbers and underscores, and may not begin with an underscore. (All assignments that do not follow this syntax will be ignored.)

  Experimentation suggests that this is enforced on the journald side, which means that typical tracing applications with field names like "foo.bar" won't get very far. In the spirit of composability, I've therefore opted to sanitize field names with the following procedure:

  1. Replacing . with _
  2. Stripping leading _s
  3. Stripping non-ascii-alphanumeric characters other than _
  4. Upcasing whatever's left

  This is pretty lossy, though it should do the intuitive thing 99.9% of the time. I'm redoing this sanitization on every event; maybe it should be precomputed in register_callsite and stored in an internal RwLock<HashMap>?

• journald's standard priority encoding (docs) is copied from syslog, which doesn't match that of tracing: there is no "trace" level, there are three levels more severe than "error", and there's an extra "notice" level between "info" and "warn". I opted to translate based on closest semantics, which is lossy despite the large number of options: error/warn/info/debug map to the corresponding levels, and trace is also mapped to debug.

• A fresh Vec<u8> is allocated to serialize every event. Is this avoidable?

Other open questions:

• What, if any, configuration is necessary? Should field name sanitization be configurable?
• What, if anything, should be done with span information? Should we encode this in a set of synthetic fields somehow?
• How should the risk of collision between internally-generated and user-defined field names be handled? Perhaps by applying a prefix to user-defined fields other than message?
• One of the standard journald fields is a UID "for recognizing certain message types, if this is desirable". Should we automatically generate a unique one for each callsite?

[Ralith]

Also, journald supports fields with binary data in them, which can be handy. Is this something tracing is interested in exposing? It might be a fairly natural extension of trait Visit.

[Ralith]

CI failure is spurious due to preexisting issues in tracing-log.

[Ralith]

Another concern is that journald treats the message field as the entirety of what should be shown to users by default, which might make things very terse for applications designed based on the behavior of tracing_subscriber::fmt. #83 would make this more graceful.

[hawkw]

Thanks, this is really cool! Here are some thoughts on your questions:

I'm particularly interested in feedback on a few of the compromises made in this draft:

• The documentation for the upstream API dictates:

  [field names] must be in uppercase and consist only of characters, numbers and underscores, and may not begin with an underscore. (All assignments that do not follow this syntax will be ignored.)

  Experimentation suggests that this is enforced on the journald side, which means that typical tracing applications with field names like "foo.bar" won't get very far. In the spirit of composability, I've therefore opted to sanitize field names with the following procedure:

  1. Replacing . with _
  2. Stripping leading _s
  3. Stripping non-ascii-alphanumeric characters other than _
  4. Upcasing whatever's left

  This is pretty lossy, though it should do the intuitive thing 99.9% of the time.

At first blush, this seems reasonable to me. Of course, we want to be sure to explain the sanitization procedure in the docs for the journald subscriber. Based on a brief reading of the docs, it looks like journald's format does not have a notion of nesting fields? If it did, we might want to converting any .s to a nested field; but since it seems like that isn't the case, I think this seems correct.

I'm redoing this sanitization on every event; maybe it should be precomputed in register_callsite and stored in an internal RwLock<HashMap>?

Probably good to do this eventually, but I think it's probably fine to save it as a follow-up optimization.

• journald's standard priority encoding (docs) is copied from syslog, which doesn't match that of tracing: there is no "trace" level, there are three levels more severe than "error", and there's an extra "notice" level between "info" and "warn". I opted to translate based on closest semantics, which is lossy despite the large number of options: error/warn/info/debug map to the corresponding levels, and trace is also mapped to debug.

I'm a little on the fence about the right way to do this --- I think, given the usage patterns I've seen in code using tracing, our "info" concept might be closer to "notice" (and then tracing's "debug" would be mapped to journald's "info", and tracing's "warn" to journald's "debug"), which might be a little closer to the intended semantics. In particular, I've often seen very significant differences in verbosity between what people tend to log at "debug" and what they tend to log at "trace", so I think keeping these separate could be valuable. But, on the other hand, it seems a little surprising for levels to not map to the equivalently-named level in journald, so I'm not sure.

• A fresh Vec<u8> is allocated to serialize every event. Is this avoidable?

tracing-subscriber's fmt uses a thread local buffer to reuse an existing String allocation when it's large enough to contain each formatted event; you could probably do something similar (though I would advise saving it for a follow up and focus on API/behavior in this initial branch). We could also probably consider factoring that out into a reusable component in the future.

Other open questions:

• What, if any, configuration is necessary? Should field name sanitization be configurable?

Given that the journald field name rules are pretty strict, I'm not sure how much we'd want to configure. If we generate prefixes for tracing fields, though, we would definitely want to make that configurable.

• What, if anything, should be done with span information? Should we encode this in a set of synthetic fields somehow?

I would probably encode at least the current span's fields when serializing an event; possibly the entire trace tree (the current span + all its parents). We might also want to serialize the span's name as a field as well.

• How should the risk of collision between internally-generated and user-defined field names be handled? Perhaps by applying a prefix to user-defined fields other than message?

I think a prefix is probably a good idea, though I think we would definitely want to make it configurable. IMO, if we include span fields as well, they should probably have a separate prefix. Default values might be TRACING_EVENT_ and TRACING_SPAN_?

• One of the standard journald fields is a UID "for recognizing certain message types, if this is desirable". Should we automatically generate a unique one for each callsite?

Hmm, that depends a bit on the expected semantics of that field — is it unique for each instance of an event or unique for each type of event? If it's the second, it definitely makes sense to generate one for each callsite.

[Ralith]

I've added support for recording all spans, whose fields are prefixed with Sn_ where n is the depth of the span counting from the root. User fields are prefixed with F_, or SnF_ in spans. F can be replaced with any string or prefixing can be disabled, but if there is a prefix it is always delimited with _. I did not make the S configurable. Considering how heavily duplicated and low-information-content these prefixes are, I'm inclined to favor concision for them.

I'm not sure how much metadata should be recorded for spans. For now, I'm including everything except for level, including span name. I'm leaning towards including level so tooling can filter less-important spans on display if desired, but should we use syslog priority numbers, tracing level numbers, or tracing level names? Using syslog conventions for a field syslog tools don't care about seems weird, but inconsistency with the scheme used for event levels would also be weird.

In particular, I've often seen very significant differences in verbosity between what people tend to log at "debug" and what they tend to log at "trace", so I think keeping these separate could be valuable. But, on the other hand, it seems a little surprising for levels to not map to the equivalently-named level in journald, so I'm not sure.

For an intuitive sense of weight, journalctl displays "notice" messages in bold face, and "info" messages as normal text. I'm not too concerned about matching names, but I also feel somewhat like trace will almost never be enabled, so treating it specially might be overkill. Still, if tracing info is similar to syslog/journald "notice", then we might as well spread things out. Switched things over to that.

Hmm, that depends a bit on the expected semantics of that field — is it unique for each instance of an event or unique for each type of event? If it's the second, it definitely makes sense to generate one for each callsite.

Fairly certain it's meant to identify an event in abstract, not a specific occurrence, but on review I don't think we can generate them; the whole point is for it to be stable across updates/refactorings, after all. Maybe we could expose this through a magic field name that's exempted from prefixing just like message has to be?

[hawkw]

@Ralith oh, whoops, I didn't realize that this was marked as ready for review, my bad. Taking a look now!

[hawkw]

The implementation looks great! I checked out this branch locally, ran the example, and verified that the output does in fact show up in the system journal:

The one question this brings up is that, since journald's textual output format doesn't include any of the structured data, just the message field, do we want to format at least some of it into the message as well?

Since everything emitted via this subscriber will be written to the system journal by journald, if multiple unrelated processes are using this crate, all their output will appear to come from the journald unit in the textual journalctl output. So, at the very least, we may want to include the target as part of the message so that journal entries from unrelated processes can be distinguished. I noticed that the entries in the journal from other systems, such as xsession, tend to follow a convention where the message is prefixed with where in particular it came from:

This is pretty similar to the way fmt outputs event targets, so I think it would be okay for the journald layer to emit targets in this manner as well.

I'm willing to be convinced either way as to whether we should also format the event's fields into the message.

What do you think?

[Ralith]

The one question this brings up is that, since journald's textual output format doesn't include any of the structured data, just the message field, do we want to format at least some of it into the message as well?

I'm not a big fan of duplicating large amounts of data in logs just to promote tracing's current, IMO somewhat awkward, idioms here. I'd much rather see #83 fixed so that sensible human-readable messages can be constructed conveniently in parallel with the structured data.

Since everything emitted via this subscriber will be written to the system journal by journald, if multiple unrelated processes are using this crate, all their output will appear to come from the journald unit in the textual journalctl output.

I think there's some confusion here. journald is the system journal. The messages from the example are attributed to "journald" because that's the name of the example. In general, logs from any process will by default be attributed to the name of the process. This is sensible behavior.

[hawkw]

The messages from the example are attributed to "journald" because that's the name of the example. In general, logs from any process will by default be attributed to the name of the process. This is sensible behavior.

Oh, my bad --- that's obvious in retrospect. Never mind about that, then. I've only been using a distro with journald for a month or so now, so I'm not super familiar with how it works. Carry on.

[Ralith]

I think I've addressed all the outstanding issues.

[hawkw]

Great, looks good to me!

[hawkw]

👍