traceon 0.4.0

An easy to use log and tracing formatter with a flattened json or pretty output.
Documentation 
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

use claims::assert_some_eq;
use once_cell::sync::Lazy;
use serde_json::{Value, json};
use std::collections::HashMap;
use std::sync::Mutex;
use tracing::{Level, info, span};
use tracing_subscriber::Registry;
use tracing_subscriber::layer::SubscriberExt;

/// Tests have to be run on a single thread because we are re-using the same buffer for
/// all of them.
type InMemoryBuffer = Mutex<Vec<u8>>;
static BUFFER: Lazy<InMemoryBuffer> = Lazy::new(|| Mutex::new(vec![]));

// Run a closure and collect the output emitted by the tracing instrumentation using an in-memory buffer.
fn run_and_get_raw_output<F: Fn()>(action: F) -> String {
    let mut default_fields = HashMap::new();
    default_fields.insert("custom_field".to_string(), json!("custom_value"));
    let traceon = traceon::builder();
    let subscriber = Registry::default().with(traceon);
    tracing::subscriber::with_default(subscriber, action);

    // Return the formatted output as a string to make assertions against
    let mut buffer = BUFFER.lock().unwrap();
    let output = buffer.to_vec();
    // Clean the buffer to avoid cross-tests interactions
    buffer.clear();
    String::from_utf8(output).unwrap()
}

// Run a closure and collect the output emitted by the tracing instrumentation using
// an in-memory buffer as structured new-line-delimited JSON.
fn run_and_get_output<F: Fn()>(action: F) -> Vec<Value> {
    run_and_get_raw_output(action)
        .lines()
        .filter(|&l| !l.is_empty())
        .inspect(|l| println!("{}", l))
        .map(|line| serde_json::from_str::<Value>(line).unwrap())
        .collect()
}

// Instrumented code to be run to test the behaviour of the tracing instrumentation.
fn test_action() {
    let a = 2;
    let span = span!(Level::DEBUG, "shaving_yaks", a);
    let _enter = span.enter();

    info!("pre-shaving yaks");
    let b = 3;
    let new_span = span!(Level::DEBUG, "inner shaving", b);
    let _enter2 = new_span.enter();

    info!("shaving yaks");
}

#[test]
fn each_line_is_valid_json() {
    let tracing_output = run_and_get_raw_output(test_action);

    // Each line is valid JSON
    for line in tracing_output.lines().filter(|&l| !l.is_empty()) {
        assert!(serde_json::from_str::<Value>(line).is_ok());
    }
}

#[test]
fn each_line_has_the_mandatory_fields() {
    let tracing_output = run_and_get_output(test_action);

    for record in tracing_output {
        assert!(record.get("span").is_some());
        assert!(record.get("level").is_some());
        assert!(record.get("time").is_some());
        assert!(record.get("message").is_some());
    }
}

#[test]
fn encode_f64_as_numbers() {
    let f64_value: f64 = 0.5;
    let action = || {
        let span = span!(
            Level::DEBUG,
            "parent_span_f64",
            f64_field = tracing::field::Empty
        );
        let _enter = span.enter();
        span.record("f64_field", f64_value);
        info!("testing f64");
    };
    let tracing_output = run_and_get_output(action);

    for record in tracing_output {
        if record
            .get("msg")
            .and_then(Value::as_str)
            .map_or(false, |msg| msg.contains("testing f64"))
        {
            let observed_value = record.get("f64_field").and_then(|v| v.as_f64());
            assert_some_eq!(observed_value, f64_value);
        }
    }
}

#[test]
fn elapsed_milliseconds_are_present_on_exit_span() {
    let tracing_output = run_and_get_output(test_action);

    for record in tracing_output {
        if record
            .get("msg")
            .and_then(Value::as_str)
            .map_or(false, |msg| msg.ends_with("END]"))
        {
            assert!(record.get("elapsed_milliseconds").is_some());
        }
    }
}