feat: add json log format as an option

[naseemkullah]

JSON logs can be easily parsed in logging sinks such as Elasticsearch.

resolves linkerd/linkerd2#2491

cc @hawkw

Please bare with me as this is my first PR in Rust, unless you count a message change. :)

Could you please break down the anatomy of the following line:

linkerd2-proxy/linkerd/app/core/src/trace.rs

Line 12 in 610309e

type Subscriber = Formatter<format::DefaultFields, format::Format<format::Full, Uptime>>;

[hawkw]

Could you please break down the anatomy of the following line:

@naseemkullah this is a type alias --- we are assigning a shorter name to a long, complicated type. Here's the section on type aliases in the Rust book.

In this case, the Formatter type consists of a formatter for fields (the key-value pairs included on spans and log messages), and a formatter for events that formats each logged event using that field formatter. Here, the event formatter is configured to use the "full" output format (including the fields of all spans in the context where each event occurred) and formats timestamps based on the time since the process started, rather than as date-times (the Uptime formatter).

This code will probably have to be changed up a bit if we want to allow conditionally using the Json field and event formatters. You may find this example useful as a starting point.

[naseemkullah]

Current status @hawkw :

• Replaced the aforementioned type alias with en enum consisting of Json and Plain Subscriber types.

• Now trying to decipher and deal with the following errors introduced by the change regarding mismatched types and unsatisfied trait bounds (tips, links, references are all most welcome):

pub fn reload_handle(&self) -> crate::reload::Handle<crate::EnvFilter, Formatter<N, E, W>>
Returns a Handle that may be used to reload the constructed subscriber's filter.

mismatched types

expected enum `trace::Subscriber`, found struct `tracing_subscriber::layer::Layered`

note: expected struct `tracing_subscriber::reload::Handle<_, trace::Subscriber>`
         found struct `tracing_subscriber::reload::Handle<_, tracing_subscriber::layer::Layered<tracing_subscriber::fmt::fmt_layer::Layer<tracing_subscriber::registry::sharded::Registry, tracing_subscriber::fmt::format::DefaultFields, tracing_subscriber::fmt::format::Format<tracing_subscriber::fmt::format::Full, trace::Uptime>>, tracing_subscriber::registry::sharded::Registry>>`rustc(E0308)
trace.rs(53, 16): expected enum `trace::Subscriber`, found struct `tracing_subscriber::layer::Layered`

pub fn reload(&self, new_layer: impl Into<L>) -> Result<(), Error>
Replace the current layer with the provided new_layer.

no method named `reload` found for struct `tracing_subscriber::reload::Handle<tracing_subscriber::filter::env::EnvFilter, trace::Subscriber>` in the current scope

method not found in `tracing_subscriber::reload::Handle<tracing_subscriber::filter::env::EnvFilter, trace::Subscriber>`

note: the method `reload` exists but the following trait bounds were not satisfied:
      `trace::Subscriber : tracing_core::subscriber::Subscriber`
      `tracing_subscriber::filter::env::EnvFilter : tracing_subscriber::layer::Layer<trace::Subscriber>`rustc(E0599)
trace.rs(84, 20): method not found in `tracing_subscriber::reload::Handle<tracing_subscriber::filter::env::EnvFilter, trace::Subscriber>`

pub fn with_current<T>(&self, f: impl FnOnce(&L) -> T) -> Result<T, Error>
Invokes a closure with a borrowed reference to the current layer, returning the result (or an error if the subscriber no longer exists).

no method named `with_current` found for struct `tracing_subscriber::reload::Handle<tracing_subscriber::filter::env::EnvFilter, trace::Subscriber>` in the current scope

method not found in `tracing_subscriber::reload::Handle<tracing_subscriber::filter::env::EnvFilter, trace::Subscriber>`

note: the method `with_current` exists but the following trait bounds were not satisfied:
      `trace::Subscriber : tracing_core::subscriber::Subscriber`
      `tracing_subscriber::filter::env::EnvFilter : tracing_subscriber::layer::Layer<trace::Subscriber>`rustc(E0599)
trace.rs(91, 14): method not found in `tracing_subscriber::reload::Handle<tracing_subscriber::filter::env::EnvFilter, trace::Subscriber>`

[hawkw]

Hi Naseem, sorry it took me a bit to reply to your comments, I've been quite busy.

The reason your approach of adding an enum isn't working is because the enum you've created doesn't inherit the trait implementations of its two variants. If you wanted to implement the feature this way, you would need to write an implementation of the Subscriber trait that forwards to each variant, like

impl tracing::Subscriber for Subscriber {
    fn new_span(&self, span: &tracing::span::Attributes<'_>) -> tracing::span::Id {
        match self {
            Subscriber::Json(s) => s.new_span(span),
            Subscriber::Plain(s) => s.new_span(span),
        }
    }

    // ... and do the same thing for all the other trait methods on
    // the `Subscriber` trait ...
}

However, I don't know if this is the best approach. Adding the enum introduces a layer of indirection to every subscriber method call, which is not ideal, and it requires writing a bunch of additional code to forward the Subscriber implementation. Instead, since the function ultimately returns a Dispatch, which erases the type of an underlying Subscriber, I would just have two separate branches that return either a JSON or plaintext subscriber, wrapped in a Dispatch.

The other error you're running into is due to the reload::Handle type being parameterized over a generic Subscriber variable. Since the subscriber may now be either a JSON subscriber or a plaintext subscriber, which are different types, we cannot write out the type of the reload::Handle here:

linkerd2-proxy/linkerd/app/core/src/trace.rs

Line 20 in 1d1eabd

inner: reload::Handle<EnvFilter, Subscriber>,

Here, I think changing the LevelHandle type to be an enum does make sense. Since reloading the filter is not in the hot path, it's okay to introduce the overhead of having to match on two enum variants, and there are only two places we would need to match on the enum:

linkerd2-proxy/linkerd/app/core/src/trace.rs

Lines 81 to 93 in 1d1eabd

	pub fn set_level(&self, level: impl AsRef<str>) -> Result<(), Error> {
	let level = level.as_ref();
	let filter = level.parse::<EnvFilter>()?;
	self.inner.reload(filter)?;
	tracing::info!(%level, "set new log level");
	Ok(())
	}
	pub fn current(&self) -> Result<String, Error> {
	self.inner
	.with_current(|f| format!("{}", f))
	.map_err(Into::into)
	}

I think the Subscriber type alias will probably now be unnecessary and should just be removed.

Does that all make sense? Let me know if you have any additional questions!

[naseemkullah]

Hi Naseem, sorry it took me a bit to reply to your comments, I've been quite busy.

Hi @hawkw ,not at all, I'm sorry for being somewhat of a burden as I am a little out of my depth!

Does that all make sense? Let me know if you have any additional questions!

Yes, thanks for thoroughly explaining all that! Stay tuned for my attempt at implementing this (or another question 😅 )!

[naseemkullah]

Hi @hawkw, there is probably room for stylistic improvement, refactoring and deduplicating so please let me know. But I think this is ready for a first review.

• Could you please advise as to what would be the most straightforward way to test this locally? I guess I build and run the proxy standalone locally?

• Where would the fallback/default value of PLAIN go for LINKERD2_LOG_FORMAT?

• Would --proxy-log-format CLI flag and config.linkerd.io/proxy-log-format annotation be implemented in the linkerd2 repo?

Also, sorry for the forced pushes, just wanted to clean the history.

[hawkw]

Hi @hawkw, there is probably room for stylistic improvement, refactoring and deduplicating so please let me know. But I think this is ready for a first review.

• Could you please advise as to what would be the most straightforward way to test this locally? I guess I build and run the proxy standalone locally?

The proxy integration tests use the same tracing configuration as the proxy binary:

linkerd2-proxy/linkerd/app/integration/src/lib.rs

Lines 40 to 51 in cb161a1

	pub fn trace_init() -> (Dispatch, app::core::trace::LevelHandle) {
	use std::env;
	let log = env::var("LINKERD2_PROXY_LOG")
	.or_else(|_| env::var("RUST_LOG"))
	.unwrap_or_else(|_| DEFAULT_LOG.to_owned());
	env::set_var("RUST_LOG", &log);
	env::set_var("LINKERD2_PROXY_LOG", &log);
	// This may fail, since the global log compat layer may have been
	// initialized by another test.
	let _ = app::core::trace::init_log_compat();
	app::core::trace::with_filter(&log)
	}

(note the call to app::core::trace::with_filter)

So, you should be able to run the integration tests with LINKERD2_PROXY_LOG=debug,LINKERD2_PROXY_LOG_FORMAT=json for a quick spot check. You can also run a proxy locally with cargo run, but you'll need to set all the required environment variables, so running the integration tests is probably quicker and easier.

• Where would the fallback/default value of PLAIN go for LINKERD2_LOG_FORMAT?

If you look in linkerd/app/src/env.rs, you'll see that that module is where we define constants for all the environment variables that configure the proxy, and their default values.

• Would --proxy-log-format CLI flag and config.linkerd.io/proxy-log-format annotation be implemented in the linkerd2 repo?

Yup, that's correct. I believe it would be necessary to add it to the proxy-injector control plane component, and to the CLI. Both of those live in the linkerd2 repo.

I'll take a closer look at the code changes here soon, but it's great that everything is working!

[hawkw]

The overall approach looks right to me! I had a couple suggestions.

[hawkw]

Take it or leave it: I might consider adding JsonFormatter and PlainFormatter type aliases for these, because this is a bit wordy; not a blocker though.

[naseemkullah]

💯 This would increase readability. I am confused as to wether these are Formatters or Subscribers, originally when there was only the Plain version it was type aliased as Subscriber. Going with the term Formatter now but please advise.

edit: Just too clarify, what was once:

type Subscriber = Formatter<format::DefaultFields, format::Format<format::Full, Uptime>>;

is now

type PlainFormatter = Formatter<format::DefaultFields, format::Format<format::Full, Uptime>>;

hence the confusion around if it is a Subscriber or a Formatter.

[naseemkullah]

So, you should be able to run the integration tests with LINKERD2_PROXY_LOG=debug,LINKERD2_PROXY_LOG_FORMAT=json for a quick spot check. You can also run a proxy locally with cargo run, but you'll need to set all the required environment variables, so running the integration tests is probably quicker and easier.

Seems like locally the following integration tests fail with or without the added env vars:

test transport::inbound_http_accept ... FAILED
...
test transport::inbound_tcp_accept ... FAILED
...
test transport::outbound_tcp_accept ... FAILED
test transport::outbound_tcp_open_connections ... FAILED
test transport::outbound_http_accept ... FAILED

did not contain:
tcp_close_total{direction="inbound",peer="src",tls="disabled",errno="ENOTCONN"} 1', linkerd/app/integration/tests/telemetry.rs:762:9
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
server Listening dropped; addr=127.0.0.1:64482

did not contain:
tcp_close_total{direction="inbound",peer="src",tls="disabled",errno=""} 1', linkerd/app/integration/tests/telemetry.rs:968:9
server Listening dropped; addr=127.0.0.1:64509

did not contain:
tcp_close_total{direction="outbound",peer="src",tls="no_identity",no_tls_reason="loopback",errno=""} 1', linkerd/app/integration/tests/telemetry.rs:1123:9
server Listening dropped; addr=127.0.0.1:64571

did not contain:
tcp_open_connections{direction="outbound",peer="src",tls="no_identity",no_tls_reason="loopback"} 1', linkerd/app/integration/tests/telemetry.rs:1249:9
server Listening dropped; addr=127.0.0.1:64573

did not contain:
tcp_close_total{direction="outbound",peer="src",tls="no_identity",no_tls_reason="loopback",errno="ENOTCONN"} 1', linkerd/app/integration/tests/telemetry.rs:829:9
server Listening dropped; addr=127.0.0.1:64541

[naseemkullah]

Seems like locally the following integration tests fail with or without the added env vars:

These same tests fail when I try make test-integration against the master branch 🤷‍♂️

[hawkw]

Sorry I haven't had a chance to give this another review yet, I've been quite busy. I'll try to take a look today.

[hawkw]

Seems like locally the following integration tests fail with or without the added env vars:

These same tests fail when I try make test-integration against the master branch man_shrugging

What operating system are you running the tests on? I believe the error you're seeing may be due to those tests expecting Unix error code names in the metrics.

[naseemkullah]

Sorry I haven't had a chance to give this another review yet, I've been quite busy. I'll try to take a look today.

As have I! No worries nor rush @hawkw but thanks!

[naseemkullah]

Seems like locally the following integration tests fail with or without the added env vars:

These same tests fail when I try make test-integration against the master branch man_shrugging

What operating system are you running the tests on? I believe the error you're seeing may be due to those tests expecting Unix error code names in the metrics.

Ah that could explain it, I am running these on MacOS.

[hawkw]

Overall, this looks good to me. I had a few minor suggestions, but nothing blocking.

We'll need a second approval from someone else in the @linkerd/proxy-maintainers team before we can merge this.

@naseemkullah, thanks again for working on this, and for your patience waiting for a review!

[hawkw]

We could also do this using the str::eq_ignore_ascii_case method in an if-statement.

[hawkw]

Seems like locally the following integration tests fail with or without the added env vars:

These same tests fail when I try make test-integration against the master branch man_shrugging

What operating system are you running the tests on? I believe the error you're seeing may be due to those tests expecting Unix error code names in the metrics.

Ah that could explain it, I am running these on MacOS.

Try running them in a Linux docker container? IIRC there were some issues in the past where BSD (macOS) returned a different error code than Linux in some socket operations, but I thought we had configured it to skip tests effected by this on Macs? Could've been accidentally re-enabled.

[naseemkullah]

Overall, this looks good to me. I had a few minor suggestions, but nothing blocking.

We'll need a second approval from someone else in the @linkerd/proxy-maintainers team before we can merge this.

@naseemkullah, thanks again for working on this, and for your patience waiting for a review!

Thanks so much for your patience and guidance @hawkw , I may have broke it trying to implement code review: fd21ce6 could please take a look 😅 I did weird things to get it to compile.

[hawkw]

Thanks so much for your patience and guidance @hawkw , I may have broke it trying to implement code review: fd21ce6 could please take a look sweat_smile I did weird things to get it to compile.

I don't see anything weird here --- it looks like you're using the tuple-like enum correctly :) This still looks good to me!

[naseemkullah]

Thanks so much for your patience and guidance @hawkw , I may have broke it trying to implement code review: fd21ce6 could please take a look sweat_smile I did weird things to get it to compile.

I don't see anything weird here --- it looks like you're using the tuple-like enum correctly :) This still looks good to me!

Alright thanks, really was not sure (it looks a lot better with the renamed inner values to handle)... wow rust really is fool proof!