Tracking issue for `log_syntax`, `trace_macros`

[aturon]

The log_syntax feature gate allows use of the log_syntax macro attribute, and similarly for trace_macros. Both are "nasty hacks that will certainly be removed" (according to the reference manual).

[brson]

Does anybody care about either of these at all anymore? They are ancient debugging tools that seem unlikely to be stabilized without serious rethinking. Can we remove them?

cc #3065

[brson]

f? @rust-lang/compiler

[brson]

@durka says not to remove trace_macros!.

[durka]

I realize it's a hack, but it's pretty much impossible to debug complex macros without using the trace functionality. As of now it's accessible both by the trace_macros "macro" and a compiler flag of the same name, both unstable. I think at least one of those needs to remain available. I also think the tracing output needs work (formatting), but that doesn't mean it should be killed. cc @DanielKeep

[SimonSapin]

I used trace_macros!(true); yesterday and would have had a hard time without it or some kind of replacement. I just learned about the command-line option.

It’s only useful temporarily to see what’s going on, IMO never something I’d want to commit in git. So a command-line option instead of syntax extension would be ok (even slightly better) as long as how to use it with Cargo is documented in https://doc.rust-lang.org/book/macros.html#debugging-macro-code (cargo rustc -p my_crate -- -Z unstable-options -Z trace-macros ?)

[DanielKeep]

The problem with the switch is that it turns it on for everything. Due to the way it's output is formatted (spread across multiple lines), this can make debugging a badly behaving macro in the midst of lots of other macro expansions completely hellish.

If we could keep only one, I'd keep trace_macros!. It's overwhelmingly more flexible.

And just to reiterate what durka said: this is, indeed, one of the very, very few tools we have to debug macros. It's not very good, but it's not like there's really any alternative.

[Mark-Simulacrum]

Can we deprecate log_syntax? Or at least, can someone explain what the intent is? On #3065, it's not clear whether it's meant to provide an expansion "backtrace" or just print what it expanded to.

[durka]

I'm not sure what log_syntax! was intended to do, but as it is it essentially calls stringify! on whatever you pass to it, and has the compiler println! that at compile time. It's sort of a dual -- as trace_macros! can show you the input of a macro, log_syntax! can help you debug the output:

macro_rules! some_broken_macro {
    (...) => {
        struct $whatever { $($foo: $bar),* }
        // Let's say this causes a compile error for some reason, so macro expansion never finishes.
        // To debug, I could wrap the macro output in log_syntax!(...) to see what it would output.
    }
}

I use log_syntax! less than I use trace_macros!. It also overlaps with --pretty=expanded (but that is being taken away too).

[ExpHP]

I was going to comment on this tracking issue a couple weeks back around when I made this issue, but I guess I eventually decided against it. Perhaps I wanted to give it more time to develop since the new format was so recent.

In any case, I have not been enjoying the new format.

I can't say that I've ever needed a debugging tool to see what a macro expanded into; in all of my time debugging macros, it has been easy enough to figure out the issue based simply on what it was expanded from. But now these two types of information are all tangled together into one giant bowl of spaghetti with hardly any visual cue to help my eyes pull them apart.

Frankly, the zig-zagging shape formed by the note headers is making me dizzy!

new output (nightly)

    = note: expanding `gen_test_funcs! { @ named test_21 [ "/**" , "*" , false ] }`
    = note: to `# [ test ] fn test_21 (  ) { gen_tests ! ( [ "/**" , "*" , false ] ) ; }`
    = note: expanding `gen_tests! { [ "/**" , "*" , false ] }`
    = note: to `gen_tests ! ( @ single [ "/**" , "*" , false ] ) ;`
    = note: expanding `gen_tests! { @ single [ "/**" , "*" , false ] }`
    = note: to `gen_tests ! { @ test [ "/**" , "*" , None :: < String > ] }`
    = note: expanding `gen_tests! { @ test [ "/**" , "*" , None :: < String > ] }`
    = note: to `use $crate :: intersect ; let d = intersect ( "/**" , "*" , (  ) ) ; if d !=
            None::<String> {
            panic ! (
            "Assertion failed:\nInput:  intersect({:?}, {:?})\nExpected:  {:?}\n  Actual:  {:?}\n"
            , "/**" , "*" , None::<String> , d ) ; }`
    = note: expanding `panic! { "Assertion failed:\nInput:  intersect({:?}, {:?})\nExpected:  {:?}\n  Actual:  {:?}\n"
            , "/**" , "*" , None::<String> , d }`
    = note: to `{
            $crate :: rt :: begin_panic_fmt (
            & format_args ! (
            "Assertion failed:\nInput:  intersect({:?}, {:?})\nExpected:  {:?}\n  Actual:  {:?}\n"
            , "/**" , "*" , None::<String> , d ) , {
            static _FILE_LINE : ( & 'static str , u32 ) = ( file ! (  ) , line ! (  ) ) ;
            & _FILE_LINE } ) }`
    = note: expanding `gen_test_funcs! { @ name_them [
            test_22 test_23 test_24 test_25 test_26 test_27 test_28 test_29 test_30
            test_31 test_32 test_33 test_34 test_35 test_36 test_37 test_38 test_39
            test_40 test_41 test_42 test_43 test_44 test_45 test_46 test_47 test_48
            test_49 ] [ [ "**/" , "*" , false ] ] }`
    = note: to `gen_test_funcs ! ( @ named test_22 [ "**/" , "*" , false ] ) ; gen_test_funcs
            ! (
            @ name_them [
            test_23 test_24 test_25 test_26 test_27 test_28 test_29 test_30 test_31
            test_32 test_33 test_34 test_35 test_36 test_37 test_38 test_39 test_40
            test_41 test_42 test_43 test_44 test_45 test_46 test_47 test_48 test_49 ] [  ]
            ) ;`
    = note: expanding `gen_test_funcs! { @ named test_22 [ "**/" , "*" , false ] }`
    = note: to `# [ test ] fn test_22 (  ) { gen_tests ! ( [ "**/" , "*" , false ] ) ; }`
    = note: expanding `gen_tests! { [ "**/" , "*" , false ] }`
    = note: to `gen_tests ! ( @ single [ "**/" , "*" , false ] ) ;`
    = note: expanding `gen_tests! { @ single [ "**/" , "*" , false ] }`
    = note: to `gen_tests ! { @ test [ "**/" , "*" , None :: < String > ] }`
    = note: expanding `gen_tests! { @ test [ "**/" , "*" , None :: < String > ] }`
    = note: to `use $crate :: intersect ; let d = intersect ( "**/" , "*" , (  ) ) ; if d !=
            None::<String> {
            panic ! (
            "Assertion failed:\nInput:  intersect({:?}, {:?})\nExpected:  {:?}\n  Actual:  {:?}\n"
            , "**/" , "*" , None::<String> , d ) ; }`
    = note: expanding `panic! { "Assertion failed:\nInput:  intersect({:?}, {:?})\nExpected:  {:?}\n  Actual:  {:?}\n"
            , "**/" , "*" , None::<String> , d }`
    = note: to `{
            $crate :: rt :: begin_panic_fmt (
            & format_args ! (
            "Assertion failed:\nInput:  intersect({:?}, {:?})\nExpected:  {:?}\n  Actual:  {:?}\n"
            , "**/" , "*" , None::<String> , d ) , {
            static _FILE_LINE : ( & 'static str , u32 ) = ( file ! (  ) , line ! (  ) ) ;
            & _FILE_LINE } ) }`
    = note: expanding `gen_test_funcs! { @ name_them [
            test_23 test_24 test_25 test_26 test_27 test_28 test_29 test_30 test_31
            test_32 test_33 test_34 test_35 test_36 test_37 test_38 test_39 test_40
            test_41 test_42 test_43 test_44 test_45 test_46 test_47 test_48 test_49 ] [  ] }`
    = note: to ``

old output (nightly-2017-03-01)

gen_test_funcs! { [ "{x,{a,b}}" , "*" , "{x,a,b}" ] [
"{{x,y},{ab{bc,{de}}}}" , "*" , "{x,y,ab{bc,de}}" ] [
"{{{},{{}}},{{{},{{}}}}}" , "*" , "" ] }
gen_test_funcs! { @ name_them [
test_01 test_02 test_03 test_04 test_05 test_06 test_07 test_08 test_09
test_10 test_11 test_12 test_13 test_14 test_15 test_16 test_17 test_18
test_19 test_20 test_21 test_22 test_23 test_24 test_25 test_26 test_27
test_28 test_29 test_30 test_31 test_32 test_33 test_34 test_35 test_36
test_37 test_38 test_39 test_40 test_41 test_42 test_43 test_44 test_45
test_46 test_47 test_48 test_49 ] [
[ "{x,{a,b}}" , "*" , "{x,a,b}" ] [
"{{x,y},{ab{bc,{de}}}}" , "*" , "{x,y,ab{bc,de}}" ] [
"{{{},{{}}},{{{},{{}}}}}" , "*" , "" ] ] }
gen_test_funcs! { @ named test_01 [ "{x,{a,b}}" , "*" , "{x,a,b}" ] }
gen_tests! { [ "{x,{a,b}}" , "*" , "{x,a,b}" ] }
gen_tests! { @ single [ "{x,{a,b}}" , "*" , "{x,a,b}" ] }
gen_tests! { @ test [ "{x,{a,b}}" , "*" , Some ( "{x,a,b}" . to_string (  ) ) ] }
panic! { "Assertion failed:\nInput:  intersect({:?}, {:?})\nExpected:  {:?}\n  Actual:  {:?}\n"
, "{x,{a,b}}" , "*" , Some("{x,a,b}".to_string()) , d }
gen_test_funcs! { @ name_them [
test_02 test_03 test_04 test_05 test_06 test_07 test_08 test_09 test_10
test_11 test_12 test_13 test_14 test_15 test_16 test_17 test_18 test_19
test_20 test_21 test_22 test_23 test_24 test_25 test_26 test_27 test_28
test_29 test_30 test_31 test_32 test_33 test_34 test_35 test_36 test_37
test_38 test_39 test_40 test_41 test_42 test_43 test_44 test_45 test_46
test_47 test_48 test_49 ] [
[ "{{x,y},{ab{bc,{de}}}}" , "*" , "{x,y,ab{bc,de}}" ] [
"{{{},{{}}},{{{},{{}}}}}" , "*" , "" ] ] }
gen_test_funcs! { @ named test_02 [ "{{x,y},{ab{bc,{de}}}}" , "*" , "{x,y,ab{bc,de}}" ] }
gen_tests! { [ "{{x,y},{ab{bc,{de}}}}" , "*" , "{x,y,ab{bc,de}}" ] }
gen_tests! { @ single [ "{{x,y},{ab{bc,{de}}}}" , "*" , "{x,y,ab{bc,de}}" ] }
gen_tests! { @ test [
"{{x,y},{ab{bc,{de}}}}" , "*" , Some ( "{x,y,ab{bc,de}}" . to_string (  ) ) ] }
panic! { "Assertion failed:\nInput:  intersect({:?}, {:?})\nExpected:  {:?}\n  Actual:  {:?}\n"
, "{{x,y},{ab{bc,{de}}}}" , "*" , Some("{x,y,ab{bc,de}}".to_string()) , d }
gen_test_funcs! { @ name_them [
test_03 test_04 test_05 test_06 test_07 test_08 test_09 test_10 test_11
test_12 test_13 test_14 test_15 test_16 test_17 test_18 test_19 test_20
test_21 test_22 test_23 test_24 test_25 test_26 test_27 test_28 test_29
test_30 test_31 test_32 test_33 test_34 test_35 test_36 test_37 test_38
test_39 test_40 test_41 test_42 test_43 test_44 test_45 test_46 test_47
test_48 test_49 ] [ [ "{{{},{{}}},{{{},{{}}}}}" , "*" , "" ] ] }
gen_test_funcs! { @ named test_03 [ "{{{},{{}}},{{{},{{}}}}}" , "*" , "" ] }
gen_tests! { [ "{{{},{{}}},{{{},{{}}}}}" , "*" , "" ] }
gen_tests! { @ single [ "{{{},{{}}},{{{},{{}}}}}" , "*" , "" ] }
gen_tests! { @ test [ "{{{},{{}}},{{{},{{}}}}}" , "*" , Some ( "" . to_string (  ) ) ] }
panic! { "Assertion failed:\nInput:  intersect({:?}, {:?})\nExpected:  {:?}\n  Actual:  {:?}\n"
, "{{{},{{}}},{{{},{{}}}}}" , "*" , Some("".to_string()) , d }
gen_test_funcs! { @ name_them [
test_04 test_05 test_06 test_07 test_08 test_09 test_10 test_11 test_12
test_13 test_14 test_15 test_16 test_17 test_18 test_19 test_20 test_21
test_22 test_23 test_24 test_25 test_26 test_27 test_28 test_29 test_30
test_31 test_32 test_33 test_34 test_35 test_36 test_37 test_38 test_39
test_40 test_41 test_42 test_43 test_44 test_45 test_46 test_47 test_48
test_49 ] [  ] }

The old output was chaotic, but at least it tells a story. You can read the gen_tests! lines right from top to bottom to see how the macro evolves over time.

There is a note about this with plans to eliminate redundant "expanding" lines, but I am suspicious as to whether that is enough to make the output comprehensible.

[ExpHP]

I see the motivating issue here but to me it would have seemed sufficient to just fix the misleading "expands to" to "expanding".

Is there a home-run example of a problem that would be difficult to debug without the added information of what a macro expanded into?

cc @jorendorff

[durka]

I've certainly wanted to see expansion results though I don't have a specific example. I think the answer here may lie in "--error-format json" and some tool that presents the info in an actually readable way.

…

On Tue, Jul 4, 2017 at 7:20 PM, Michael Lamparski ***@***.***> wrote: I see the motivating issue here <#42072> but to me it would have seemed sufficient to just fix the misleading "expands to" to "expanding". Is there a real home-run example of a problem that would be difficult to debug without the added information of what a macro expanded into? cc @jordendorff — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#29598 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AAC3n4-4ZiLkpnbTZPQycCycqXnNCREWks5sKsi-gaJpZM4GcPa8> .

[jorendorff]

Is there a home-run example of a problem that would be difficult to debug without the added information of what a macro expanded into?

I don't know if it's a "home run", but I'll give an example. First some background. There are two cases where I think the output is helpful:

1. Usually if I'm debugging a macro, it is because something is not expanding the way I expect. To fix this, I need to know (a) which expansion is misbehaving; (b) what part of the expansion is wrong. Seeing the output helps tremendously with both.

2. Sometimes a macro expands to rather a lot of code (often an impl) and something in there triggers a compile error. The error message shows the line number of the original macro call in the source—useless. I want to see what the Rust compiler sees.

Now my example. Once in a while I write $x:expr in a macro template when of course I should write $x. Dumb; but for some reason I tend to overlook this bug when I'm staring at the macro definition. If I use trace_macros!, the to: output makes it really jump out at me. The :expr in the buggy output is a dead giveaway; it doesn't look anything like correct Rust code.

[jorendorff]

There are definitely some things in the trace_macros! output that are less than ideal: the redundancy is bad, and the nondeterministic order is worse. Both fixable!

[nikomatsakis]

I have often wanted both the inputs/outputs as well, no question. Not to say that the current output is the easiest to parse.

[ExpHP]

An issue where the new trace_macros! fails to show anything: #51754 (edit: Gave it its own issue: #51960)

As the compiler never hits an error, nothing is ever shown.