Structured logging with ClientLogger

[lmolkova]

Description: https://gist.github.com/lmolkova/04f6484595fdd7edded9f4d82619291f

Inspired by SLF4J v2 API

Usage

// todo: overloads for atInfo, etc
logger.atLevel(LogLevel.WARNING)
                .addKeyValue("connectionId", "foo")
                .addKeyValue("linkName", "bar")
                .log("hello, argument = {}", arg)

Outcome:
2021-11-08 15:04:42.407 [ForkJoinPool-1-worker-3] [WARN] com.azure.core.util.logging.ClientLoggerTests - hello, argument = 1, az.sdk.context={"connectionId":"foo", "linkName":"bar"}

Micro-benchmarks:

Benchmark                                           Mode  Cnt     Score     Error  Units
LoggingBenchmark.loggingAtDisabledLevel             avgt   15     1.268 ±   0.153  ns/op
LoggingBenchmark.loggingAtDisabledLevelWithContext  avgt   15     1.524 ±   0.092  ns/op
LoggingBenchmark.loggingAtDisabledLevelWithMDC      avgt   15     1.588 ±   0.252  ns/op
LoggingBenchmark.loggingAtEnabledLevel              avgt   15  2501.731 ± 549.315  ns/op
LoggingBenchmark.loggingAtEnabledLevelWithContext   avgt   15  2711.800 ± 259.968  ns/op
LoggingBenchmark.loggingAtEnabledLevelWithMDC       avgt   15  3624.982 ± 193.837  ns/op

Fluent pattern (loggingAtEnabledLevelWithContext) vs explicit context (loggingAtEnabledLevelWithContext2) don't show significant difference in perf:

Benchmark                                           Mode  Cnt     Score     Error  Units
LoggingBenchmark.loggingAtEnabledLevel              avgt   15  1847.670 ± 128.052  ns/op
LoggingBenchmark.loggingAtEnabledLevelWithContext   avgt   15  2115.740 ± 134.049  ns/op
LoggingBenchmark.loggingAtEnabledLevelWithContext2  avgt   15  2106.112 ±  79.263  ns/op

[azure-sdk]

API changes have been detected in com.azure:azure-core. You can review API changes here

[azure-sdk]

API changes have been detected in com.azure:azure-core. You can review API changes here

[azure-sdk]

API changes have been detected in com.azure:azure-core. You can review API changes here

[azure-sdk]

API changes have been detected in com.azure:azure-core. You can review API changes here

[pallavit]

With this change we now support 2 ways to log (Fluent vs non-fluent) - should we long term consolidate to only one style?

[JonathanGiles]

With this change we now support 2 ways to log (Fluent vs non-fluent) - should we long term consolidate to only one style?

It's possible we could do this, but in terms of backwards compatibility, I wouldn't worry too much. This is exactly the pattern SLF4J is taking in its 2.0.0 release.

[JonathanGiles]

Looking really promising!

[pallavit]

With this change we now support 2 ways to log (Fluent vs non-fluent) - should we long term consolidate to only one style?

It's possible we could do this, but in terms of backwards compatibility, I wouldn't worry too much. This is exactly the pattern SLF4J is taking in its 2.0.0 release.

I meant should we think of only exposing Fluent way of doing things moving forward (whenever we think it is the right time) ? I understand our ecosystem supports multiple ways of doing the same thing but shouldn't our SDKs have a single way of doing everything.

[pallavit]

@lmolkova this is pretty cool. I love how you are adding benchmarks to the PRs.

[lmolkova]

I meant should we think of only exposing Fluent way of doing things moving forward (whenever we think it is the right time) ?

Fluent way is a bit less performant (you have to allocate the builder), a bit more verbose (log.atInfo().log("foo") vs log.info("foo")) and it feels like it should only be used when we'd want to add context. I also believe ClientLogger, even though it's public, is only used by our own SDKs and de-facto is an internal API. It's used widely (e.g. there are ~6k calls to it in our repo).
So, I didn't have plans to ever remove flat APIs.

[lmolkova]

Fresh benchmark, ~same results

Benchmark                                           Mode  Cnt     Score     Error  Units
LoggingBenchmark.loggingAtDisabledLevel             avgt    6     1.511 ±   0.311  ns/op
LoggingBenchmark.loggingAtDisabledLevelWithContext  avgt    6     1.693 ±   0.433  ns/op
LoggingBenchmark.loggingAtEnabledLevel              avgt    6  1309.170 ± 414.924  ns/op
LoggingBenchmark.loggingAtEnabledLevelWithContext   avgt    6  1546.085 ± 890.383  ns/op