1
  2
  3
  4
  5
  6
  7
  8
  9
 10
 11
 12
 13
 14
 15
 16
 17
 18
 19
 20
 21
 22
 23
 24
 25
 26
 27
 28
 29
 30
 31
 32
 33
 34
 35
 36
 37
 38
 39
 40
 41
 42
 43
 44
 45
 46
 47
 48
 49
 50
 51
 52
 53
 54
 55
 56
 57
 58
 59
 60
 61
 62
 63
 64
 65
 66
 67
 68
 69
 70
 71
 72
 73
 74
 75
 76
 77
 78
 79
 80
 81
 82
 83
 84
 85
 86
 87
 88
 89
 90
 91
 92
 93
 94
 95
 96
 97
 98
 99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
226
227
228
229
230
231
232
233
234
235
236
237
238
239
240
241
242
243
244
245
246
247
248
249
250
251
252
253
254
255
256
257
258
259
260
261
262
263
264
265
266
267
268
269
270
271
272
273
274
275
276
277
278
279
280
281
282
283
284
285
286
287
288
289
290
291
292
293
294
295
296
297
298
299
300
301
302
303
304
305
306
307
308
309
310
311
312
313
314
315
316
317
318
319
320
321
322
323
324
325
326
327
328
329
330
331
332
333
334
335
336
337
338
339
340
341
342
343
344
345
346
347
348
349
350
351
352
353
354
355
#![warn(missing_docs)]
//! # Structured Contextual Logging (or tracing)
//! ## Why
//! [Watch](https://www.youtube.com/watch?v=JjItsfqFIdo) or [Read](https://tokio.rs/blog/2019-08-tracing/)
//!
//! ## Intention of this crate
//! This crate is designed ot be a place to experiment with ideas around
//! tracing and structured logging. This crate will probably never stabilize.
//! Instead it is my hope to feed any good ideas back into the underlying
//! dependencies.
//!
//! ## Usage
//! There are a couple of ways to use structured logging.
//! ### Console and filter
//! If you want to try and filter in on an issue it might be easiest to simply log to the console and filter on what you want.
//! Here's an example command:
//! ```bash
//! RUST_LOG='core[a{something="foo"}]=debug' my_bin
//! ```
//! Or a more simple version using the default `Log`:
//! ```bash
//! RUST_LOG=trace my_bin
//! ```
//! #### Types of tracing
//! There are many types of tracing exposed by this crate.
//! The [Output] type is designed to be used with something like [structopt](https://docs.rs/structopt/0.3.20/structopt/)
//! so you can easily set which type you want with a command line arg.
//! You could also use an environment variable.
//! The [Output] variant is passing into the [init_fmt] function on start up.
//! #### Filtering
//! ```bash
//! RUST_LOG='core[a{something="foo"}]=debug'
//! ```
//! Here we are saying show me all the events that are:
//! - In the `core` module
//! - Inside a span called `a`
//! - The span `a` has to have a field called `something` that is equal to `foo`
//! - They are at least debug level.
//!
//! Most of these options are optional.
//! They can be combined like:
//! ```bash
//! RUST_LOG='[{}]=error,[{something}]=debug'
//! ```
//! > The above means show me errors from anywhere but also any event or span with the field something that's at least debug.
//!
//! [See here](https://docs.rs/tracing-subscriber/0.2.2/tracing_subscriber/filter/struct.EnvFilter.html) for more info.
//!
//! #### Json
//! Sometimes there's too much data and it's better to capture it to interact with using another tool later.
//! For this we can output everything as Json using the flag `--structured Json`.
//! Then you can pipe the output from stdout to you're file of choice.
//! Here's some sample output:
//! ```json
//! {"time":"2020-03-03T08:07:05.910Z","name":"event crates/sim2h/src/sim2h_im_state.rs:695","level":"INFO","target":"sim2h::sim2h_im_state","module_path":"sim2h::sim2h_im_state","file":"crates/sim2h/src/sim2h_im_stat
//! e.rs","line":695,"fields":{"space_hashes":"[]"},"spans":[{"id":[1099511627778],"name":"check_gossip","level":"INFO","target":"sim2h::sim2h_im_state","module_path":"sim2h::sim2h_im_state","file":"crates/sim2h/src/s
//! im2h_im_state.rs","line":690}]}
//! ```
//! Every log will include the above information expect for the spans which will only show up if there are parent spans in the context of the event.
//!
//! You can combine filter with Json as well.
//!
//! ##### Tools
//! Some useful tools for formatting and using the json data.
//! - [json2csv](https://www.npmjs.com/package/json2csv)
//! - [jq](https://stedolan.github.io/jq/)
//! - [tad](https://www.tadviewer.com/)
//!
//! A sample workflow:
//! ```bash
//! RUST_LOG='core[{}]=debug' my_bin --structured Json > log.json
//! cat out.json | jq '. | {time: .time, name: .name, message: .fields.message, file: .file, line: .line, fields: .fields, spans: .spans}' | json2csv -o log.csv
//! tad log.csv
//! ```

use tracing::{Event, Subscriber};
use tracing_subscriber::{
    filter::EnvFilter,
    fmt::{format::FmtSpan, time::ChronoUtc, FmtContext},
    registry::LookupSpan,
    FmtSubscriber,
};

use std::{str::FromStr, sync::Once};

use flames::{toml_path, FlameTimed};
use fmt::*;

mod flames;
mod fmt;
pub mod metrics;
mod open;

#[cfg(all(feature = "opentelemetry-on", feature = "channels"))]
pub use open::channel;
#[cfg(feature = "opentelemetry-on")]
pub use open::should_run;
pub use open::{Config, Context, MsgWrap, OpenSpanExt};

pub use tracing;

#[derive(Debug, Clone)]
/// Sets the kind of structured logging output you want
pub enum Output {
    /// More compact version of above
    Compact,
    /// Outputs everything as json
    Json,
    /// Json with timed spans
    JsonTimed,
    /// Regular logging (default)
    Log,
    /// Regular logging plus timed spans
    LogTimed,
    /// Creates a flamegraph from timed spans
    FlameTimed,
    /// Creates a flamegraph from timed spans using idle time
    IceTimed,
    /// Opentelemetry tracing
    OpenTel,
    /// No logging to console
    None,
}

/// ParseError is a String
pub type ParseError = String;

static INIT: Once = Once::new();

impl FromStr for Output {
    type Err = ParseError;
    fn from_str(day: &str) -> Result<Self, Self::Err> {
        match day {
            "Json" => Ok(Output::Json),
            "JsonTimed" => Ok(Output::JsonTimed),
            "IceTimed" => Ok(Output::IceTimed),
            "Log" => Ok(Output::Log),
            "LogTimed" => Ok(Output::LogTimed),
            "FlameTimed" => Ok(Output::FlameTimed),
            "Compact" => Ok(Output::Compact),
            "OpenTel" => Ok(Output::OpenTel),
            "None" => Ok(Output::None),
            _ => Err("Could not parse log output type".into()),
        }
    }
}

/// Run logging in a unit test
/// RUST_LOG or CUSTOM_FILTER must be set or
/// this is a no-op
pub fn test_run() -> Result<(), errors::TracingError> {
    if std::env::var_os("RUST_LOG").is_none() {
        return Ok(());
    }
    init_fmt(Output::Log)
}

/// Run tracing in a test that uses open telemetry to
/// send span contexts across process and thread boundaries.
pub fn test_run_open() -> Result<(), errors::TracingError> {
    if std::env::var_os("RUST_LOG").is_none() {
        return Ok(());
    }
    init_fmt(Output::OpenTel)
}

/// Same as test_run but with timed spans
pub fn test_run_timed() -> Result<(), errors::TracingError> {
    if std::env::var_os("RUST_LOG").is_none() {
        return Ok(());
    }
    init_fmt(Output::LogTimed)
}

/// Same as test_run_timed but saves as json
pub fn test_run_timed_json() -> Result<(), errors::TracingError> {
    if std::env::var_os("RUST_LOG").is_none() {
        return Ok(());
    }
    init_fmt(Output::JsonTimed)
}

/// Generate a flamegraph from timed spans "busy time".
/// Takes a path where you are piping the output into.
/// If the path is provided a flamegraph will automatically be generated.
/// TODO: Get auto inferno to work
/// for now use (fish, or the bash equiv):
/// `2>| inferno-flamegraph > flamegraph_test_ice_(date +'%d-%m-%y-%X').svg`
/// And run with `cargo test --quiet`
pub fn test_run_timed_flame(path: Option<&str>) -> Result<Option<impl Drop>, errors::TracingError> {
    if std::env::var_os("RUST_LOG").is_none() {
        return Ok(None);
    }
    init_fmt(Output::FlameTimed)?;
    Ok(path.and_then(|p| {
        toml_path().map(|mut t| {
            t.push(p);
            FlameTimed::new(t)
        })
    }))
}

/// Generate a flamegraph from timed spans "idle time".
/// Takes a path where you are piping the output into.
/// If the path is provided a flamegraph will automatically be generated.
/// TODO: Get auto inferno to work
/// for now use (fish, or the bash equiv):
/// `2>| inferno-flamegraph -c blue > flamegraph_test_ice_(date +'%d-%m-%y-%X').svg`
/// And run with `cargo test --quiet`
pub fn test_run_timed_ice(path: Option<&str>) -> Result<Option<impl Drop>, errors::TracingError> {
    if std::env::var_os("RUST_LOG").is_none() {
        return Ok(None);
    }
    init_fmt(Output::IceTimed)?;
    Ok(path.and_then(|p| {
        toml_path().map(|mut t| {
            t.push(p);
            FlameTimed::new(t)
        })
    }))
}

/// This checks RUST_LOG for a filter but doesn't complain if there is none or it doesn't parse.
/// It then checks for CUSTOM_FILTER which if set will output an error if it doesn't parse.
pub fn init_fmt(output: Output) -> Result<(), errors::TracingError> {
    let mut filter = match std::env::var("RUST_LOG") {
        Ok(_) => EnvFilter::from_default_env(),
        Err(_) => EnvFilter::from_default_env().add_directive("[wasm_debug]=debug".parse()?),
    };
    if std::env::var("CUSTOM_FILTER").is_ok() {
        EnvFilter::try_from_env("CUSTOM_FILTER")
            .map_err(|e| eprintln!("Failed to parse CUSTOM_FILTER {:?}", e))
            .map(|f| {
                filter = f;
            })
            .ok();
    }
    let fm: fn(
        ctx: &FmtContext<'_, _, _>,
        &mut dyn std::fmt::Write,
        &Event<'_>,
    ) -> std::fmt::Result = format_event;
    let fm_flame: fn(
        ctx: &FmtContext<'_, _, _>,
        &mut dyn std::fmt::Write,
        &Event<'_>,
    ) -> std::fmt::Result = format_event_flame;
    let fm_ice: fn(
        ctx: &FmtContext<'_, _, _>,
        &mut dyn std::fmt::Write,
        &Event<'_>,
    ) -> std::fmt::Result = format_event_ice;

    let subscriber = FmtSubscriber::builder()
        .with_writer(std::io::stderr)
        .with_target(true);

    match output {
        Output::Json => {
            let subscriber = subscriber
                .with_env_filter(filter)
                .with_timer(ChronoUtc::rfc3339())
                .json()
                .event_format(fm);
            finish(subscriber.finish())
        }
        Output::JsonTimed => {
            let subscriber = subscriber
                .with_span_events(FmtSpan::CLOSE)
                .with_env_filter(filter)
                .with_timer(ChronoUtc::rfc3339())
                .json()
                .event_format(fm);
            finish(subscriber.finish())
        }
        Output::Log => finish(subscriber.with_env_filter(filter).finish()),
        Output::LogTimed => {
            let subscriber = subscriber.with_span_events(FmtSpan::CLOSE);
            finish(subscriber.with_env_filter(filter).finish())
        }
        Output::FlameTimed => {
            let subscriber = subscriber
                .with_span_events(FmtSpan::CLOSE)
                .with_env_filter(filter)
                .with_timer(ChronoUtc::rfc3339())
                .event_format(fm_flame);
            finish(subscriber.finish())
        }
        Output::IceTimed => {
            let subscriber = subscriber
                .with_span_events(FmtSpan::CLOSE)
                .with_env_filter(filter)
                .with_timer(ChronoUtc::rfc3339())
                .event_format(fm_ice);
            finish(subscriber.finish())
        }
        Output::Compact => {
            let subscriber = subscriber.compact();
            finish(subscriber.with_env_filter(filter).finish())
        }
        Output::OpenTel => {
            #[cfg(feature = "opentelemetry-on")]
            {
                use open::OPEN_ON;
                use opentelemetry::api::Provider;
                OPEN_ON.store(true, std::sync::atomic::Ordering::SeqCst);
                use tracing_subscriber::prelude::*;
                open::init();
                let tracer = opentelemetry::sdk::Provider::default().get_tracer("component_name");
                let telemetry = tracing_opentelemetry::layer().with_tracer(tracer);
                finish(
                    subscriber
                        .with_env_filter(filter)
                        .finish()
                        .with(telemetry)
                        .with(open::OpenLayer),
                )
            }
            #[cfg(not(feature = "opentelemetry-on"))]
            {
                Ok(())
            }
        }
        Output::None => Ok(()),
    }
}

fn finish<S>(subscriber: S) -> Result<(), errors::TracingError>
where
    S: Subscriber + Send + Sync + for<'span> LookupSpan<'span>,
{
    let mut result = Ok(());
    INIT.call_once(|| {
        result = tracing::subscriber::set_global_default(subscriber).map_err(Into::into);
    });
    result
}

pub mod errors {
    //! Error in the tracing/logging framework

    use thiserror::Error;

    /// Error in the tracing/logging framework
    #[allow(missing_docs)] // should be self-explanatory
    #[derive(Error, Debug)]
    pub enum TracingError {
        #[error(transparent)]
        SetGlobal(#[from] tracing::subscriber::SetGlobalDefaultError),
        #[error("Failed to setup tracing flame")]
        TracingFlame,
        #[error(transparent)]
        BadDirective(#[from] tracing_subscriber::filter::ParseError),
    }
}