Add tracing support

[stevefan1999-personal]

This PR will address #344 but there is a catch: for some reason the macro just crash saying that something beyond my control:

PS E:\Git\github.com\stevefan1999-personal\rust-peg> cargo run -p peg-macros --features trace -- peg-macros/grammar.rustpeg > peg-macros/grammar_new.rs
    Finished dev [unoptimized + debuginfo] target(s) in 0.02s
     Running `target\debug\rust-peg.exe peg-macros/grammar.rustpeg`
thread 'main' panicked at 'index out of bounds: the len is 1994 but the index is 1994', peg-macros\tokens.rs:125:12
stack backtrace:
   0: std::panicking::begin_panic_handler
             at /rustc/23ee2af2f7669d521ad39ef8a506a4fa3d37ea5a/library\std\src\panicking.rs:577
   1: core::panicking::panic_fmt
             at /rustc/23ee2af2f7669d521ad39ef8a506a4fa3d37ea5a/library\core\src\panicking.rs:67
   2: core::panicking::panic_bounds_check
             at /rustc/23ee2af2f7669d521ad39ef8a506a4fa3d37ea5a/library\core\src\panicking.rs:162
   3: core::slice::index::impl$2::index<enum2$<rust_peg::tokens::Token> >
             at /rustc/23ee2af2f7669d521ad39ef8a506a4fa3d37ea5a\library\core\src\slice\index.rs:261
   4: alloc::vec::impl$13::index<enum2$<rust_peg::tokens::Token>,usize,alloc::alloc::Global>
             at /rustc/23ee2af2f7669d521ad39ef8a506a4fa3d37ea5a\library\alloc\src\vec\mod.rs:2694
   5: rust_peg::tokens::impl$3::position_repr
             at .\peg-macros\tokens.rs:125
   6: rust_peg::grammar::peg::__parse_peg_grammar
             at .\peg-macros\grammar.rs:155
   7: rust_peg::grammar::peg::peg_grammar
             at .\peg-macros\grammar.rs:32
   8: rust_peg::main
             at .\peg-macros\bin.rs:45
   9: core::ops::function::FnOnce::call_once<void (*)(),tuple$<> >
             at /rustc/23ee2af2f7669d521ad39ef8a506a4fa3d37ea5a\library\core\src\ops\function.rs:250
note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.
error: process didn't exit successfully: `target\debug\rust-peg.exe peg-macros/grammar.rustpeg` (exit code: 101) 

I'm not sure but does that looks like we have a memory constraint in procedural macros? I'm not aware of this, but so far the PR just added rule instrumentation and I tried to keep the original intent as much as possible. 

Not only instrumentation can let us get rid of another hidden std requirement, but that it will produce a nested context -- the level of calling of functions that is very valuable in debugging recursive call by providing a tree-like structure for diagnostic. To print the tracings is now left up to the users, say like either I want to print it directly in stdout, or I could make a super fancy web app that sends the data to a remote server with WebSocket and display it in a canvas that actively traces the input value for replaying (cough Jaeger)! Now I just showed one bizarre usage on how now the tracing's sky would be limitless.

But before I can pass the macro bootstrapping test, I would suggest keeping this in draft state.
It passed?! So now let me try to demonstrate how tracing would works and be valuable then...

[stevefan1999-personal]

@kevinmehall I think the PR test is a false positive. Maybe I need you to manually test the new grammar.rs, since the commit looks like hell. Or let's keep it as is because we rarely need to test the main procedural macro itself by using tracing...The rest of the tests looks stunningly fine on my side where I added tracing manually to the dependencies

[kevinmehall]

One concern I have with this is that right now you don't have to write any code to get the trace output; you just cargo run --features peg/trace. But with this, you'd need to set up tracing-subscriber to actually get any output printed, right?

I like the idea of using tracing spans to represent the tree structure -- do you have an example of what that looks like on any of the preexisting subscribers?

[kevinmehall]

The test failure is real, and it's an issue with doing this -- the calls to tracing are emitted in the crate where the macro is invoked, so it's that crate, not peg, that needs to depend on tracing. The only way to not force the user to depend on tracing themselves is to re-export the tracing API from the peg / peg-runtime that we already require depending on.

Adding it to dev-dependencies merely works around this issue for the tests because trybuild adds dev dependencies as dependencies of the tests.

[stevefan1999-personal]

2023-04-10T15:03:00.102510Z TRACE expression:__parse_expression{rule="expression" pos=0}:__parse_sum{rule="sum" pos=0}:__parse_product{rule="product" pos=0}:__parse_atom{rule="atom" pos=0}:__parse_number{rule="number" pos=0}: trybuild011::arithmetic: Matched loc=1:1 eloc=1:2
2023-04-10T15:03:00.102541Z TRACE expression:__parse_expression{rule="expression" pos=0}:__parse_sum{rule="sum" pos=0}:__parse_product{rule="product" pos=0}:__parse_atom{rule="atom" pos=0}: trybuild011::arithmetic: Matched loc=1:1 eloc=1:2
2023-04-10T15:03:00.102568Z TRACE expression:__parse_expression{rule="expression" pos=0}:__parse_sum{rule="sum" pos=0}:__parse_product{rule="product" pos=0}: trybuild011::arithmetic: Matched loc=1:1 eloc=1:2
2023-04-10T15:03:00.102604Z TRACE expression:__parse_expression{rule="expression" pos=0}:__parse_sum{rule="sum" pos=0}:__parse__{rule="_" pos=1}: trybuild011::arithmetic: Attempting loc=1:2
2023-04-10T15:03:00.102629Z TRACE expression:__parse_expression{rule="expression" pos=0}:__parse_sum{rule="sum" pos=0}:__parse__{rule="_" pos=1}: trybuild011::arithmetic: Matched loc=1:2 eloc=1:2
2023-04-10T15:03:00.102665Z TRACE expression:__parse_expression{rule="expression" pos=0}:__parse_sum{rule="sum" pos=0}:__parse_product{rule="product" pos=0}: trybuild011::arithmetic: Attempting loc=1:1
2023-04-10T15:03:00.102693Z TRACE expression:__parse_expression{rule="expression" pos=0}:__parse_sum{rule="sum" pos=0}:__parse_product{rule="product" pos=0}:__parse_atom{rule="atom" pos=0}: trybuild011::arithmetic: Attempting loc=1:1
2023-04-10T15:03:00.102724Z TRACE expression:__parse_expression{rule="expression" pos=0}:__parse_sum{rule="sum" pos=0}:__parse_product{rule="product" pos=0}:__parse_atom{rule="atom" pos=0}:__parse_number{rule="number" pos=0}: trybuild011::arithmetic: Attempting loc=1:1
2023-04-10T15:03:00.102750Z TRACE expression:__parse_expression{rule="expression" pos=0}:__parse_sum{rule="sum" pos=0}:__parse_product{rule="product" pos=0}:__parse_atom{rule="atom" pos=0}:__parse_number{rule="number" pos=0}: trybuild011::arithmetic: Matched loc=1:1 eloc=1:2       
2023-04-10T15:03:00.102798Z TRACE expression:__parse_expression{rule="expression" pos=0}:__parse_sum{rule="sum" pos=0}:__parse_product{rule="product" pos=0}:__parse_atom{rule="atom" pos=0}: trybuild011::arithmetic: Matched loc=1:1 eloc=1:2
2023-04-10T15:03:00.102836Z TRACE expression:__parse_expression{rule="expression" pos=0}:__parse_sum{rule="sum" pos=0}:__parse_product{rule="product" pos=0}:__parse__{rule="_" pos=1}: trybuild011::arithmetic: Attempting loc=1:2
2023-04-10T15:03:00.102860Z TRACE expression:__parse_expression{rule="expression" pos=0}:__parse_sum{rule="sum" pos=0}:__parse_product{rule="product" pos=0}:__parse__{rule="_" pos=1}: trybuild011::arithmetic: Matched loc=1:2 eloc=1:2
2023-04-10T15:03:00.102897Z TRACE expression:__parse_expression{rule="expression" pos=0}:__parse_sum{rule="sum" pos=0}:__parse_product{rule="product" pos=0}:__parse_atom{rule="atom" pos=0}: trybuild011::arithmetic: Attempting loc=1:1
2023-04-10T15:03:00.102930Z TRACE expression:__parse_expression{rule="expression" pos=0}:__parse_sum{rule="sum" pos=0}:__parse_product{rule="product" pos=0}:__parse_atom{rule="atom" pos=0}:__parse_number{rule="number" pos=0}: trybuild011::arithmetic: Attempting loc=1:1
2023-04-10T15:03:00.102956Z TRACE expression:__parse_expression{rule="expression" pos=0}:__parse_sum{rule="sum" pos=0}:__parse_product{rule="product" pos=0}:__parse_atom{rule="atom" pos=0}:__parse_number{rule="number" pos=0}: trybuild011::arithmetic: Matched loc=1:1 eloc=1:2       
2023-04-10T15:03:00.102988Z TRACE expression:__parse_expression{rule="expression" pos=0}:__parse_sum{rule="sum" pos=0}:__parse_product{rule="product" pos=0}:__parse_atom{rule="atom" pos=0}: trybuild011::arithmetic: Matched loc=1:1 eloc=1:2
2023-04-10T15:03:00.103016Z TRACE expression:__parse_expression{rule="expression" pos=0}:__parse_sum{rule="sum" pos=0}:__parse_product{rule="product" pos=0}: trybuild011::arithmetic: Matched loc=1:1 eloc=1:2
2023-04-10T15:03:00.103042Z TRACE expression:__parse_expression{rule="expression" pos=0}:__parse_sum{rule="sum" pos=0}: trybuild011::arithmetic: Matched loc=1:1 eloc=1:2
2023-04-10T15:03:00.103066Z TRACE expression:__parse_expression{rule="expression" pos=0}: trybuild011::arithmetic: Matched loc=1:1 eloc=1:2
2023-04-10T15:03:00.103096Z TRACE expression:__parse_expression{rule="expression" pos=0}: trybuild011::arithmetic: Attempting loc=1:1
2023-04-10T15:03:00.103123Z TRACE expression:__parse_expression{rule="expression" pos=0}:__parse_sum{rule="sum" pos=0}: trybuild011::arithmetic: Attempting loc=1:1
2023-04-10T15:03:00.103149Z TRACE expression:__parse_expression{rule="expression" pos=0}:__parse_sum{rule="sum" pos=0}:__parse_product{rule="product" pos=0}: trybuild011::arithmetic: Attempting loc=1:1
2023-04-10T15:03:00.103178Z TRACE expression:__parse_expression{rule="expression" pos=0}:__parse_sum{rule="sum" pos=0}:__parse_product{rule="product" pos=0}:__parse_atom{rule="atom" pos=0}: trybuild011::arithmetic: Attempting loc=1:1
2023-04-10T15:03:00.103209Z TRACE expression:__parse_expression{rule="expression" pos=0}:__parse_sum{rule="sum" pos=0}:__parse_product{rule="product" pos=0}:__parse_atom{rule="atom" pos=0}:__parse_number{rule="number" pos=0}: trybuild011::arithmetic: Attempting loc=1:1
2023-04-10T15:03:00.103236Z TRACE expression:__parse_expression{rule="expression" pos=0}:__parse_sum{rule="sum" pos=0}:__parse_product{rule="product" pos=0}:__parse_atom{rule="atom" pos=0}:__parse_number{rule="number" pos=0}: trybuild011::arithmetic: Matched loc=1:1 eloc=1:2       
2023-04-10T15:03:00.103269Z TRACE expression:__parse_expression{rule="expression" pos=0}:__parse_sum{rule="sum" pos=0}:__parse_product{rule="product" pos=0}:__parse_atom{rule="atom" pos=0}: trybuild011::arithmetic: Matched loc=1:1 eloc=1:2
2023-04-10T15:03:00.103306Z TRACE expression:__parse_expression{rule="expression" pos=0}:__parse_sum{rule="sum" pos=0}:__parse_product{rule="product" pos=0}:__parse__{rule="_" pos=1}: trybuild011::arithmetic: Attempting loc=1:2
2023-04-10T15:03:00.103331Z TRACE expression:__parse_expression{rule="expression" pos=0}:__parse_sum{rule="sum" pos=0}:__parse_product{rule="product" pos=0}:__parse__{rule="_" pos=1}: trybuild011::arithmetic: Matched loc=1:2 eloc=1:2
2023-04-10T15:03:00.103368Z TRACE expression:__parse_expression{rule="expression" pos=0}:__parse_sum{rule="sum" pos=0}:__parse_product{rule="product" pos=0}:__parse_atom{rule="atom" pos=0}: trybuild011::arithmetic: Attempting loc=1:1
2023-04-10T15:03:00.103400Z TRACE expression:__parse_expression{rule="expression" pos=0}:__parse_sum{rule="sum" pos=0}:__parse_product{rule="product" pos=0}:__parse_atom{rule="atom" pos=0}:__parse_number{rule="number" pos=0}: trybuild011::arithmetic: Attempting loc=1:1
2023-04-10T15:03:00.103427Z TRACE expression:__parse_expression{rule="expression" pos=0}:__parse_sum{rule="sum" pos=0}:__parse_product{rule="product" pos=0}:__parse_atom{rule="atom" pos=0}:__parse_number{rule="number" pos=0}: trybuild011::arithmetic: Matched loc=1:1 eloc=1:2       
2023-04-10T15:03:00.103458Z TRACE expression:__parse_expression{rule="expression" pos=0}:__parse_sum{rule="sum" pos=0}:__parse_product{rule="product" pos=0}:__parse_atom{rule="atom" pos=0}: trybuild011::arithmetic: Matched loc=1:1 eloc=1:2
2023-04-10T15:03:00.103486Z TRACE expression:__parse_expression{rule="expression" pos=0}:__parse_sum{rule="sum" pos=0}:__parse_product{rule="product" pos=0}: trybuild011::arithmetic: Matched loc=1:1 eloc=1:2
2023-04-10T15:03:00.103521Z TRACE expression:__parse_expression{rule="expression" pos=0}:__parse_sum{rule="sum" pos=0}:__parse__{rule="_" pos=1}: trybuild011::arithmetic: Attempting loc=1:2
2023-04-10T15:03:00.103543Z TRACE expression:__parse_expression{rule="expression" pos=0}:__parse_sum{rule="sum" pos=0}:__parse__{rule="_" pos=1}: trybuild011::arithmetic: Matched loc=1:2 eloc=1:2
2023-04-10T15:03:00.103579Z TRACE expression:__parse_expression{rule="expression" pos=0}:__parse_sum{rule="sum" pos=0}:__parse_product{rule="product" pos=0}: trybuild011::arithmetic: Attempting loc=1:1
2023-04-10T15:03:00.103608Z TRACE expression:__parse_expression{rule="expression" pos=0}:__parse_sum{rule="sum" pos=0}:__parse_product{rule="product" pos=0}:__parse_atom{rule="atom" pos=0}: trybuild011::arithmetic: Attempting loc=1:1
2023-04-10T15:03:00.103639Z TRACE expression:__parse_expression{rule="expression" pos=0}:__parse_sum{rule="sum" pos=0}:__parse_product{rule="product" pos=0}:__parse_atom{rule="atom" pos=0}:__parse_number{rule="number" pos=0}: trybuild011::arithmetic: Attempting loc=1:1
2023-04-10T15:03:00.103669Z TRACE expression:__parse_expression{rule="expression" pos=0}:__parse_sum{rule="sum" pos=0}:__parse_product{rule="product" pos=0}:__parse_atom{rule="atom" pos=0}:__parse_number{rule="number" pos=0}: trybuild011::arithmetic: Matched loc=1:1 eloc=1:2       
2023-04-10T15:03:00.103700Z TRACE expression:__parse_expression{rule="expression" pos=0}:__parse_sum{rule="sum" pos=0}:__parse_product{rule="product" pos=0}:__parse_atom{rule="atom" pos=0}: trybuild011::arithmetic: Matched loc=1:1 eloc=1:2
2023-04-10T15:03:00.103737Z TRACE expression:__parse_expression{rule="expression" pos=0}:__parse_sum{rule="sum" pos=0}:__parse_product{rule="product" pos=0}:__parse__{rule="_" pos=1}: trybuild011::arithmetic: Attempting loc=1:2
2023-04-10T15:03:00.103767Z TRACE expression:__parse_expression{rule="expression" pos=0}:__parse_sum{rule="sum" pos=0}:__parse_product{rule="product" pos=0}:__parse__{rule="_" pos=1}: trybuild011::arithmetic: Matched loc=1:2 eloc=1:2
2023-04-10T15:03:00.103805Z TRACE expression:__parse_expression{rule="expression" pos=0}:__parse_sum{rule="sum" pos=0}:__parse_product{rule="product" pos=0}:__parse_atom{rule="atom" pos=0}: trybuild011::arithmetic: Attempting loc=1:1
2023-04-10T15:03:00.103838Z TRACE expression:__parse_expression{rule="expression" pos=0}:__parse_sum{rule="sum" pos=0}:__parse_product{rule="product" pos=0}:__parse_atom{rule="atom" pos=0}:__parse_number{rule="number" pos=0}: trybuild011::arithmetic: Attempting loc=1:1
2023-04-10T15:03:00.103864Z TRACE expression:__parse_expression{rule="expression" pos=0}:__parse_sum{rule="sum" pos=0}:__parse_product{rule="product" pos=0}:__parse_atom{rule="atom" pos=0}:__parse_number{rule="number" pos=0}: trybuild011::arithmetic: Matched loc=1:1 eloc=1:2       
2023-04-10T15:03:00.103895Z TRACE expression:__parse_expression{rule="expression" pos=0}:__parse_sum{rule="sum" pos=0}:__parse_product{rule="product" pos=0}:__parse_atom{rule="atom" pos=0}: trybuild011::arithmetic: Matched loc=1:1 eloc=1:2
2023-04-10T15:03:00.103923Z TRACE expression:__parse_expression{rule="expression" pos=0}:__parse_sum{rule="sum" pos=0}:__parse_product{rule="product" pos=0}: trybuild011::arithmetic: Matched loc=1:1 eloc=1:2
2023-04-10T15:03:00.103949Z TRACE expression:__parse_expression{rule="expression" pos=0}:__parse_sum{rule="sum" pos=0}: trybuild011::arithmetic: Matched loc=1:1 eloc=1:2
2023-04-10T15:03:00.103972Z TRACE expression:__parse_expression{rule="expression" pos=0}: trybuild011::arithmetic: Matched loc=1:1 eloc=1:2
2023-04-10T15:03:00.103995Z ERROR expression: trybuild011::arithmetic: error=error at 1:2: expected one of "*", "+", EOF, [' ' | '\n'], ['0' ..= '9']
┈┈┈┈┈┈┈┈┈┈┈┈┈┈┈┈┈┈┈┈┈┈┈┈┈┈┈┈┈┈┈┈┈┈┈┈┈┈┈┈┈┈┈┈┈┈┈┈┈┈┈┈┈┈┈┈┈┈┈┈

Wow! Although it looks insanely long, but the key point is already there! Now we just need to tidy it up give it a unique look. I'm also pretty sure it would look much cooler in Jaeger/Loki

[stevefan1999-personal]

This PR would also solve #141. Can't believe we dug up a necro-issue...

[stevefan1999-personal]

I'm not satisfied with this tracing test result. Why wouldn't GH Actions prettify JSON for me...