Conversation
jeremycline
left a comment
There was a problem hiding this comment.
I think we can shuffle things around a bit and configure the initial layers slightly differently, but after that I'd advocate for merging this and adding additional instrumentation and tracing layers to export to KVP in follow-up PRs.
|
|
||
| // Create a `tracing` subscriber | ||
| let subscriber = Registry::default() | ||
| .with(otel_layer); |
There was a problem hiding this comment.
The tracing subscriber lets you register multiple layers, and each layer can be configured with its own filters and formatters and so on. It takes a little digging in the tracing_subscriber docs and I forever forget how to do it properly, but here's an example that would let us avoid needing to duplicate the file descriptor:
| // Create a `tracing` subscriber | |
| let subscriber = Registry::default() | |
| .with(otel_layer); | |
| // Create a tracing layer for logging to stdout | |
| let log_file = Arc::new(File::create("example.log").unwrap()); | |
| let stderr_layer = tracing_subscriber::fmt::layer() | |
| .with_writer(std::io::stderr.and(log_file)) | |
| .with_filter(tracing_subscriber::EnvFilter::from_env("AZURE_INIT_LOG")); | |
| // Create a `tracing` subscriber | |
| let subscriber = Registry::default() | |
| .with(stderr_layer) | |
| .with(otel_layer); |
This adds a second layer which writes to stderr as well as a file, and applies a filter you can define (requires env-filter feature on the tracing-subscriber crate) in the AZURE_INIT_LOG environment variable. We don't necessarily need to use EnvFilter, but I tend to start with it because it's easy to get started with. I tend to abandon it if I start using a configuration file for the application.
If you run with this diff, you'll get logs written to stderr and "example.log" for that layer, and then separately to "spans.log". I don't think we want this literal suggestion, but I think this is the general approach we want to take when setting things up.
We can also apply a global filter that applies to all layers instead (or in addition to) filters on each layer.
| use tracing_subscriber::{Registry, layer::SubscriberExt}; | ||
|
|
||
|
|
||
| pub static TRACER: Lazy<()> = Lazy::new(|| { |
There was a problem hiding this comment.
I would recommend that we move the code within this block into the binary in the azure-init crate. Each application tends to want to configure its logging in its own way - different file names, different environment variables for configuration, different filtering rules, etc.
What would be good in a library is any custom Layers we end up making, if any. These can be consumed (and configured) by applications in their tracing-subscriber setup.
| } | ||
|
|
||
| #[tokio::main] | ||
| async fn main() -> ExitCode { |
There was a problem hiding this comment.
The tracing-subscriber setup should probably live here, then we add a root span and instrument the provision call in that span, something like:
let subscriber = Registry::default().with(layers);
tracing::subscriber::set_global_default(subscriber).expect("...")
let root_span = tracing::info_span!("root");
match provision().instrument(root_span).await {
While debugging what turned into Azure#103, I added some minimal log configuration to figure out what was happening. Note that this only logs to stderr and is only configurable via the `AZURE_INIT_LOG` environment variable. The most minimal usage is like this: AZURE_INIT_LOG=info azure-init Which emits anything at info level or high. Refer to the tracing documentation[0] for more complex examples. This doesn't try to integrate with OpenTelemetry or pipe logs to KVP; those are being wired up in Azure#83. [0] https://docs.rs/tracing-subscriber/0.3.18/tracing_subscriber/filter/struct.EnvFilter.html#directives
While debugging why running azure-init in a local VM hung forever, I
added some minimal log configuration to figure out what was happening.
Note that this only logs to stderr and is only configurable via the
`AZURE_INIT_LOG` environment variable. The most minimal usage is like
this:
AZURE_INIT_LOG=info azure-init
Which emits anything at info level or high. Refer to the
tracing-subscriber documentation[0] for more complex examples.
Logs look like this:
```
2024-07-16T14:41:16.924909Z INFO provision: azure_init: new
2024-07-16T14:41:16.928668Z INFO provision:get_environment: azure_init: new
...
2024-07-16T14:41:17.065528Z INFO provision:get_environment: azure_init: close time.busy=133ms time.idle=4.21ms
2024-07-16T14:41:17.073142Z INFO provision:get_username: azure_init: new
2024-07-16T14:41:17.076323Z INFO provision:get_username: azure_init: close time.busy=23.3µs time.idle=3.16ms
2024-07-16T14:41:17.081070Z INFO provision: azure_init: close time.busy=153ms time.idle=3.12ms
```
It's configured to emit logs when a span opens and closes in addition to
any explicit `tracing::{debug,info,warn,error}!` call, although we can
disable that if folks don't like it. I also added spans to most of the
library functions. All the spans are at the default `INFO` level and the
default log configuration is to write logs for warning or higher, so
running this without specifying `AZURE_INIT_LOG` results in the same
behavior as before.
This doesn't try to integrate with OpenTelemetry or pipe logs to KVP;
those are being wired up in Azure#83.
[0] https://docs.rs/tracing-subscriber/0.3.18/tracing_subscriber/filter/struct.EnvFilter.html#directives
While debugging why running azure-init in a local VM hung forever, I
added some minimal log configuration to figure out what was happening.
Note that this only logs to stderr and is only configurable via the
`AZURE_INIT_LOG` environment variable. The most minimal usage is like
this:
AZURE_INIT_LOG=info azure-init
Which emits anything at info level or high. Refer to the
tracing-subscriber documentation[0] for more complex examples.
Logs look like this:
```
2024-07-16T14:41:16.924909Z INFO provision: azure_init: new
2024-07-16T14:41:16.928668Z INFO provision:get_environment: azure_init: new
...
2024-07-16T14:41:17.065528Z INFO provision:get_environment: azure_init: close time.busy=133ms time.idle=4.21ms
2024-07-16T14:41:17.073142Z INFO provision:get_username: azure_init: new
2024-07-16T14:41:17.076323Z INFO provision:get_username: azure_init: close time.busy=23.3µs time.idle=3.16ms
2024-07-16T14:41:17.081070Z INFO provision: azure_init: close time.busy=153ms time.idle=3.12ms
```
It's configured to emit logs when a span opens and closes in addition to
any explicit `tracing::{debug,info,warn,error}!` call, although we can
disable that if folks don't like it. I also added spans to most of the
library functions. All the spans are at the default `INFO` level and the
default log configuration is to write logs for warning or higher, so
running this without specifying `AZURE_INIT_LOG` results in the same
behavior as before.
This doesn't try to integrate with OpenTelemetry or pipe logs to KVP;
those are being wired up in #83.
[0] https://docs.rs/tracing-subscriber/0.3.18/tracing_subscriber/filter/struct.EnvFilter.html#directives
While debugging why running azure-init in a local VM hung forever, I
added some minimal log configuration to figure out what was happening.
Note that this only logs to stderr and is only configurable via the
`AZURE_INIT_LOG` environment variable. The most minimal usage is like
this:
AZURE_INIT_LOG=info azure-init
Which emits anything at info level or high. Refer to the
tracing-subscriber documentation[0] for more complex examples.
Logs look like this:
```
2024-07-16T14:41:16.924909Z INFO provision: azure_init: new
2024-07-16T14:41:16.928668Z INFO provision:get_environment: azure_init: new
...
2024-07-16T14:41:17.065528Z INFO provision:get_environment: azure_init: close time.busy=133ms time.idle=4.21ms
2024-07-16T14:41:17.073142Z INFO provision:get_username: azure_init: new
2024-07-16T14:41:17.076323Z INFO provision:get_username: azure_init: close time.busy=23.3µs time.idle=3.16ms
2024-07-16T14:41:17.081070Z INFO provision: azure_init: close time.busy=153ms time.idle=3.12ms
```
It's configured to emit logs when a span opens and closes in addition to
any explicit `tracing::{debug,info,warn,error}!` call, although we can
disable that if folks don't like it. I also added spans to most of the
library functions. All the spans are at the default `INFO` level and the
default log configuration is to write logs for warning or higher, so
running this without specifying `AZURE_INIT_LOG` results in the same
behavior as before.
This doesn't try to integrate with OpenTelemetry or pipe logs to KVP;
those are being wired up in Azure#83.
[0] https://docs.rs/tracing-subscriber/0.3.18/tracing_subscriber/filter/struct.EnvFilter.html#directives
|
Closed, kept this open for documentation's sake but final implementation was merged in with #133. |
Draft PR to discuss OpenTelemetry Tracer and next steps for making tracer async, refactoring , and instrumenting the rest of the repo