log-instrument 0.3.0

Offers an attribute procedural macro that adds `log::trace!` events at the start and end of attributed functions.
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
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

const ONE: &str = "../target/debug/examples/one";
const TWO: &str = "../target/debug/examples/two";
const THREE: &str = "../target/debug/examples/three";
const FOUR: &str = "../target/debug/examples/four";
const FIVE: &str = "../target/debug/examples/five";
const SIX: &str = "../target/debug/examples/six";

const TIMESTAMP_RANGE: std::ops::Range<usize> = 1..20;

/// Match stderr to expected skipping bytes containing the timestamp.
fn check(actual: &[u8], expected: &[u8]) {
    assert_eq!(actual.len(), expected.len());
    let mut j = 0;
    for i in 0..actual.len() {
        if actual[i] == b'\n' {
            j = 0;
        }
        if TIMESTAMP_RANGE.contains(&j) {
            continue;
        }
        assert_eq!(actual[i], expected[i]);
        j += 1;
    }
}

#[test]
fn one() {
    let output = std::process::Command::new(ONE).output().unwrap();
    assert!(output.status.success());
    assert_eq!(output.stdout, b"");
    let expected_stderr = b"\
        [2023-10-12T16:29:00Z TRACE log_instrument] ThreadId(1)>>one\n\
        [2023-10-12T16:29:00Z DEBUG one] cmp: true\n\
        [2023-10-12T16:29:00Z TRACE log_instrument] ThreadId(1)<<one\n\
        [2023-10-12T16:29:00Z INFO  one] 4\n\
        [2023-10-12T16:29:00Z TRACE log_instrument] ThreadId(1)>>one\n\
        [2023-10-12T16:29:00Z DEBUG one] cmp: false\n\
        [2023-10-12T16:29:00Z TRACE log_instrument] ThreadId(1)<<one\n\
        [2023-10-12T16:29:00Z INFO  one] 6\n\
        [2023-10-12T16:29:00Z TRACE log_instrument] ThreadId(1)>>one\n\
        [2023-10-12T16:29:00Z DEBUG one] cmp: false\n\
        [2023-10-12T16:29:00Z TRACE log_instrument] ThreadId(1)<<one\n\
        [2023-10-12T16:29:00Z INFO  one] 7\n\
    ";
    check(&output.stderr, expected_stderr);
}

#[test]
fn two() {
    let output = std::process::Command::new(TWO).output().unwrap();
    assert!(output.status.success());
    assert_eq!(output.stdout, b"");
    let expected_stderr = b"\
        [2023-10-12T16:29:30Z TRACE log_instrument] ThreadId(1)>>one\n\
        [2023-10-12T16:29:30Z TRACE log_instrument] ThreadId(1)<<one\n\
        [2023-10-12T16:29:30Z INFO  two] None\n\
        [2023-10-12T16:29:30Z TRACE log_instrument] ThreadId(1)>>one\n\
        [2023-10-12T16:29:30Z DEBUG two] [\"a\", \"b\"]\n\
        [2023-10-12T16:29:30Z TRACE log_instrument] ThreadId(1)<<one\n\
        [2023-10-12T16:29:30Z INFO  two] Some([\"a\", \"b\"])\n\
    ";
    check(&output.stderr, expected_stderr);
}

#[test]
fn three() {
    let output = std::process::Command::new(THREE).output().unwrap();
    assert!(output.status.success());
    assert_eq!(output.stdout, b"");
    let expected_stderr = b"\
        [2023-10-12T16:30:04Z TRACE log_instrument] ThreadId(1)>>one\n\
        [2023-10-12T16:30:04Z TRACE log_instrument] ThreadId(1)<<one\n\
        [2023-10-12T16:30:04Z INFO  three] None\n\
        [2023-10-12T16:30:04Z TRACE log_instrument] ThreadId(1)>>one\n\
        [2023-10-12T16:30:04Z DEBUG three] [\"a\", \"b\"]\n\
        [2023-10-12T16:30:04Z TRACE log_instrument] ThreadId(1)<<one\n\
        [2023-10-12T16:30:04Z INFO  three] Some([\"a\", \"b\"])\n\
    ";
    check(&output.stderr, expected_stderr);
}

#[test]
fn four() {
    let output = std::process::Command::new(FOUR).output().unwrap();
    assert!(output.status.success());
    assert_eq!(output.stdout, b"");
    let expected_stderr = b"\
        [2023-10-12T16:30:37Z TRACE log_instrument] ThreadId(1)>>one\n\
        [2023-10-12T16:30:37Z TRACE log_instrument] ThreadId(1)<<one\n\
        [2023-10-12T16:30:37Z INFO  four] None\n\
        [2023-10-12T16:30:37Z TRACE log_instrument] ThreadId(1)>>one\n\
        [2023-10-12T16:30:37Z DEBUG four] [\"a\", \"b\"]\n\
        [2023-10-12T16:30:37Z TRACE log_instrument] ThreadId(1)<<one\n\
        [2023-10-12T16:30:37Z INFO  four] Some([\"a\", \"b\"])\n\
    ";
    check(&output.stderr, expected_stderr);
}

#[test]
fn five() {
    let output = std::process::Command::new(FIVE).output().unwrap();
    assert!(output.status.success());
    assert_eq!(output.stdout, b"");
    println!("{:?}", std::str::from_utf8(&output.stderr).unwrap());
    let expected_stderr = b"\
        [2023-10-12T16:31:12Z TRACE log_instrument] ThreadId(1)>>one\n\
        [2023-10-12T16:31:12Z TRACE log_instrument] ThreadId(1)<<one\n\
        [2023-10-12T16:31:12Z INFO  five] None\n\
        [2023-10-12T16:31:12Z TRACE log_instrument] ThreadId(1)>>one\n\
        [2023-10-12T16:31:12Z DEBUG five] [\"a\", \"b\"]\n\
        [2023-10-12T16:31:12Z DEBUG five] 23\n\
        [2023-10-12T16:31:12Z TRACE log_instrument] ThreadId(1)<<one\n\
        [2023-10-12T16:31:12Z INFO  five] Some([\"a\", \"b\"])\n\
    ";
    check(&output.stderr, expected_stderr);
}

#[test]
fn six() {
    let output = std::process::Command::new(SIX).output().unwrap();
    assert!(output.status.success());
    assert_eq!(output.stdout, b"");
    println!("{:?}", std::str::from_utf8(&output.stderr).unwrap());
    let expected_stderr = b"\
        [2023-10-12T16:31:54Z TRACE log_instrument] ThreadId(1)>>one\n\
        [2023-10-12T16:31:54Z DEBUG six] cmp: true\n\
        [2023-10-12T16:31:54Z TRACE log_instrument] ThreadId(1)<<one\n\
        [2023-10-12T16:31:54Z INFO  six] 4\n\
        [2023-10-12T16:31:54Z TRACE log_instrument] ThreadId(1)>>one\n\
        [2023-10-12T16:31:54Z DEBUG six] cmp: false\n\
        [2023-10-12T16:31:54Z TRACE log_instrument] ThreadId(1)::one>>two\n\
        [2023-10-12T16:31:54Z DEBUG six] res: 0\n\
        [2023-10-12T16:31:54Z TRACE log_instrument] ThreadId(1)::one<<two\n\
        [2023-10-12T16:31:54Z TRACE log_instrument] ThreadId(1)<<one\n\
        [2023-10-12T16:31:54Z INFO  six] 0\n\
        [2023-10-12T16:31:54Z TRACE log_instrument] ThreadId(1)>>one\n\
        [2023-10-12T16:31:54Z DEBUG six] cmp: false\n\
        [2023-10-12T16:31:54Z TRACE log_instrument] ThreadId(1)::one>>two\n\
        [2023-10-12T16:31:54Z DEBUG six] res: 1\n\
        [2023-10-12T16:31:54Z TRACE log_instrument] ThreadId(1)::one<<two\n\
        [2023-10-12T16:31:54Z TRACE log_instrument] ThreadId(1)<<one\n\
        [2023-10-12T16:31:54Z INFO  six] 1\n\
    ";
    check(&output.stderr, expected_stderr);
}