Use separate streams for Runtime logging & logging pseudo-Node

[daviddrysdale]

There two logically distinct streams of log messages:

• Log messages from the Runtime itself. These are trigged via the log crate, and pop out via whatever crate implements that façade. At the moment, the implementation is the env_logger crate (but see Investigate use of slog crate for logging #1088), and this is only enabled in builds that have the oak_debug feature of the Runtime enabled (specifically, in the oak_loader crate).
• Log messages from Oak Applications running on the Oak platform. These are encoded as protobuf messages and sent to a logging pseudo-Node. As such, they are subject to the rules of IFC, and if so allowed, should be visible even in a non-oak_debug build of the Runtime.

However, at the moment the logging pseudo-Node emits the latter by calling log!, which means that:

• A non-oak_debug runtime drops all logging messages, rather than just dropping Runtime logs and emitting (IFC-allowed) application logs.
• The log messages from the application are intertwined with the Runtime logging messages, and are hard to separate.

So the logging pseudo-Node should emit app-driven messages with something other than log!.

[tiziano88]

This may or may not be made simpler by using slog or some other logging crate (see #1088).

I think in any case it may be worth making logging more explicit, so that for instance, instead of using log macros everywhere, we should have explicit safe_log and leak_log (or similar) wrappers, so that we can audit safe_log usages easily, and disable leak_log usages in production builds.

@daviddrysdale should we start with that?

[daviddrysdale]

The two logging streams occur in distinct contexts:

• The Runtime logs are in code written by the developers of Oak (1st-party), in code that compiles down to the normal host environment (say x86_64).
• The Oak Application logs are in code that will be written by developers using Oak (3rd-party), in code that compiles down to Wasm binaries with a very restricted set of available host functions.

To put it another way,

• Any log statement under oak/server/ is automatically a leak_log.
• Any log statement under sdk/rust/oak/ or examples/*/module*/ is automatically a safe_log.

That makes me wonder whether having/maintaining two sets of wrapper macros will be worth the effort – it's not a distinction that's going to be visible to external developers.

(Naming-wise, I guess safe_log actually means log_if_ifc_allows which in turn requires disjunction support (#1207) in the IFC system plus a mechanism for clients to agree to the "can be debugged" policy…)

[tiziano88]

I don't think they always appear in different context though, for instance (just a random one):

oak/oak/server/rust/oak_runtime/src/runtime/mod.rs

Line 197 in 56ee7fa

info!("spawning {} server on new thread", name);

is a "safe" log, in that it does not depend on anything sensitive (though admittedly not many more under oak/server/).

So in the log pseudo-node, the log statements would be "safe" because IFC constrains have already been checked by the node itself (or rather, by the runtime IFC mechanism, and by effectively fixing the label of the log node to "public").

Re: "can be debugged" policy, I think this just means that data must be public, in the current IFC model. With disjunctions, we may have a principal for debugging, but it still needs to be cryptographically bound to something (which may be the public key of who is expected to do the debugging, or a bearer token that the user grants them after the fact to allow the debugging after the fact).

[daviddrysdale]

Ah, I think you're talking about a slightly different division that what I was intending to cover in this issue. My aim here was to cover a split between:

• logging from the Runtime (1-p, x86_64, oak/server/*, gated by oak_debug)
• logging from an Application (3-p, Wasm, examples/* + sdk/*, IFC-gated)
  • (with the logging pseudo-Node altered to emit this via a different mechanism than just log so the oak_debug gate wouldn't apply)

It sounds like you're wanting to subdivide things differently, into:

• logging from the Runtime (1-p, x86_64, oak/server/*) may be either:
  • safe_log (always allowed)
  • leak_log (gated by oak_debug)
• logging from an Application (3-p, Wasm, examples/* + sdk/*, IFC-gated)
  • (where the logging pseudo-Node could continue to use the Runtime logging mechanism to emit things, via safe_log internally in the Runtime)

Is that roughly what you're suggesting?

[tiziano88]

Yes that's a good summary, thanks!

I think what I am suggesting should cover the use cases you described (if not, let me know, my intention was not to suggest something incompatible with yours, just more fine grained), plus allow us to have "allow-listed" safe log statements in the runtime that do not depend on data (for now manually checked, in the future perhaps with actual proofs, or at least with some tooling support?).

Though the safe naming I suggested may not be very intuitive in the context of Rust, where usually things that need to be manually checked are marked as unsafe. Perhaps we should make safe_log (or whatever we decide to call it) an unsafe fn, so that we would be forced to call it from an unsafe block? Not sure if that ends up being too noisy though.