Add structured logging

When logging information, we don't specifically show where it happens (which remote connection, which thread, etc...).

This would help a lot in debugging the application.

changed milestone to %V0.2.0

added Improvement Liborchestra labels

mentioned in issue #14 (closed)

changed milestone to %V0.3.0

removed milestone

I thought that logging was an improvement, but it is actually an important feature that would allow simpler debugging of profiles and so on. For this reason, a logging refactoring should be shipped with 0.3.0

added Feature Runaway labels and removed Improvement label

changed milestone to %V0.3.0

added To Do label

Why slog won't fit

For structured logging I first thought about using slog-rs, which basically uses logger structures Logger to emit messages. Those loggers carry a context with them (a dictionary basically), which allows to add more semantics to the logging. Those loggers can be cloned with let child = root.new(o!("key" => "value")), to produce a child that will carry the same context as the parent, complemented of some (key,value)s . This allows to structure your logging as a tree, whose structure can be used when formatting messages for instance. The github page shows a nice example of a terminal formatting that uses tabs to represent the tree dependency in log messages.

Since the nesting of code scopes actually forms a tree, it is highly relevant to adopt this structure for logging. Problem is, in order to be useful for debugging, we would prefer function calls to be nested as a tree, rather than arbitrary code structures. To do that we would need to pass the logger with every function call, which requires modifying every function signature to include the logging strategy. For this reason, this solution requires a full commitment, and a huge refactoring of the code base, which is not advisable given the constraints of the project.

Also while my first thoughts on the topic were that logging messages would be enough for debug, I now feel that I need to have a more in depth vision of the program sequencing induced by the asynchrony. Something like 'chrome;//tracing` graphs would be invaluable for debugging:

Why tracing feels better suited

Thing is, to be created, such a graph needs information not only about point-in-time events, but also spans of the different pieces of code. While reading on this topic, I came across the tracing project, which is actually about developing useful tools for developers of async applications. In particular they provide ways to log both:

• spans: which represent code time-spans and can carry an arbitrary context (message, structure, whatever). Aside from this context, spans are structured automatically to form a tree that represents the code nesting structure. Spans have the flexibility of slog to encapsulate any type of context, but also automatically derive the tree structure we seek to represent code.
• events: which represent points in time and can also carry context. Those are special cases of spans that have the same beginning and end. Events can be wrapped in log-like macro calls like info!(...). They can basically represent our usual log messages.

The great thing with tracing is that they provide an #[instrument] procedural macro, that allows to attach spans to functions, making it fast and lightweight to structure the code, while avoiding a massive refactoring. Moreover, I can start by replacing the log macros by tracing events, and then move along with spans.

For this reason, the fact that tracing seem to be backed by the tokio people, it seem reasonable to use it to implement structured logging.

Final note

A tracing subscriber exporting to chrome:tracing is not yet available, but someone seem to have started working on that (see the gitter). If I have enough time, I may start to spin my own chrome://tracing subscriber.

Logging policy

Until now, I haven't been able to keep a consistent and useful logging policy. I'll try to follow those rules for the refactoring:

• All the messages from the program to the user will use the logging interface, even in runaway. The use of println! and eprintln will be reserved to the executions output.
• Error level messages will be used to report errors. Those will be shown to the user whatever happens.
• Info level messages will be used to report high-level semantic information to the user. Those will probably only be emitted in runaway and not in liborchestra. Those messages will be shown unless the user ask to silent it through a '--silent' option for instance.
• Debug and Warning level messages will be used to help the user in debugging the application. It should report on the possible points of failure of the code in production, such as ssh connections, profile related things, etc ... Those will be accessed through a --verbose argument
• Trace level messages will targeted at the developer, and will be activated by a --trace option.
• All log messages at the beginning and end of scopes or functions will be replaced by tracing instrumentation. Those were meant to represent spans anyway.

created merge request !11 (merged) to address this issue

mentioned in merge request !11 (merged)

Also, since I added a fair amount of spans and logs to the code base, we should support only leaving trace in the binary for the debug compiles.

Closed by !11 (merged)

closed