Improve compile time error with --error-trace disabled

[paulcsmith]

Problem

We removed the full expanded trace in Crystal 0.30.

This was helpful for a few reasons:

• Made it much easier to focus on the error
• Less jarring for new users
• Made macro errors a lot more concise. These used to take potentially hundreds of lines of space

It also introduced some problems

• Some errors needed more context to diagnose (see https://github.com/crystal-lang/crystal/issues/8374#issuecomment-548518492)
• Was hard to pass the --error-trace flag in some cases https://github.com/crystal-lang/crystal/issues/8374

Proposed solution

We could revert the change and always show a full trace, and/or the proposal in #8374 would help toggle the flag, but I think we can do better!

The main problem with the full trace is when you need a bit more context, but the full trace shows too much and can make it hard to focus and find issues. Here's what I think we can do:

Show a concise list of frames leading up to the final frame

• Much less overwhelming for new users
• Removes lots of wasted space and Error instantiating.... over and over
• Shows the code that was called in bold so you can follow what happened easily and w/o looking at source!
• Visual distinction between what went wrong and the code that was called to get there. Important for guiding new and existing users alike.

Note: I used an old version of my error mockups so it may not look exactly right. The only part I'm suggesting adding is the dashed list above the main error

Should we still have the --error-trace flag then?

I think so. Or maybe we rename it.

The reason I think it is helpful is for macros. The "concise" trace shows just the line where the macro caused a problem and not the (potentially hundreds of) lines of code surrounding it. Usually you just want/need the line that caused the problem, but it is nice to be able to expand it if necessary.

So I think we should leave it or maybe call it --expand-macro-errors? But honestly I don't think it's worth spending a lot of time on. If we can improve the default trace like this I think that'll cover most cases and make working with compile time errors super nice.

[straight-shoota]

Oh, so this is essentially just a backtrace from the error location, showing each previous call location without context. Sounds good :+1:

This will still produce a lot of output when the call stack is pretty deep. Maybe that's fine. Maybe we could shorten it. I guess cutting at a fixed number (10?) should actually be fine. In normal use cases you shouldn't need more than a few steps back to figure out where the error comes from.

[bew]

I like the idea! I'm not sure about limiting the number of frames thought... Or maybe show the N first and the N last ones when the number of frames is greater than N*2.

For the short lines, I'd suggest also adding a prefix, with the type and if it's a method/macro, like:

- In macro Foo.macro arg_node 
  At the/location.cr:1
- In method Bar#method arg1, arg2, &block
  At the/location.cr:4

with colors

[paulcsmith]

@asterite mentioned in https://github.com/crystal-lang/crystal/issues/8374#issuecomment-548618792 that the type signature may be helpful. I’ll work on a mock that adds that but my hunch is that showing the code and file location is enough.

@straight-shoota I think having it long is ok since it is concise. The problem with huge traces before was that sometimes you’d have massive macro expansion that made it hard to go from call to call. The other was that each expression took quite a few lines so only a few fit in screen. I’d propose that way show them all and see how that goes and add a limit later if it gets clunky. What do you think?

@bew I think whether it is a macro or regular method is not as useful for debugging in the trace but maybe I’m missing a use case. Could you expound in that a bit more? Also I’ll work on a mock that includes type info but I’m not sure the extra information will be more help than harm, especially with longer lines and lots of arguments. It might just make it harder to scan the trace. But maybe it can work if the colors are right! I’ll try some stuff

[paulcsmith]

Some updated ideas.

My personal favorite so far:

• Uses green for the code that works. Nice visual indicator I think that differentiates working lines from the failed one
• Change green arrow to yellow, which ties the code to the yellow error below
• Added "Problem found in" to make it read a bit nicer
• Indented trace slightly (one space)

Added in the type sig

Same as above, but adds the type signature in bold (I made up the type sigs but they should be close to what we would output)

I personally feel that the source code is generally more helpful and the type signatures can sometimes be more confusing than not.

My suggestion is to show the type-signature when using --error-trace to give that extra bit of info when you need it, but not by default.

Moving forward

I'd love to move forward with one of these options since even if not perfect, I think it is a big step in the right direction. If others agree, I'll post another bounty for this like the last error message one! cc @martimatix :D

[straight-shoota]

I'm not sure about using green to indicate working calls. In fact, the error might actually be in some of these traces! It's not super important, but I'd opt for a different color.

I agree that signatures should not be displayed by default.

[bew]

I personally feel that the source code is generally more helpful and the type signatures can sometimes be more confusing than not.

My suggestion is to show the type-signature when using --error-trace to give that extra bit of info when you need it, but not by default.

When I see it like that, I agree it's too much, your proposition is better :+1:

For the source code lines in the frames list, it's confusing to see the code around the failing method.. For example when I saw the long line ending with perform_action I got confused "which call is failing here...". I think we should somehow highlight the frame's method name (with a different color / underline /...)

[straight-shoota]

I have an idea: What about printing the signature in that trace step which is actually in the respective method? This means essentially moving each signature line one line down:

 - handler.payload.new(context, handler.params).perform_action
   lib/lucky/src/lucky/route_handler.cr:10
 - inside Lucky::Action#peform_action
   response = call
   lib/lucky/src/lucky/renderable.cr:97
 - inside Lucky::Action#response
   html Users::ShowPage, user: user
   src/actions/user/show.cr.cr:11
 - inside Users::Show#html(Users::ShowPage, User)
   render_user(@user)
   src/actions/users/show_page.cr.cr:11

Problem found in src/pages/users/show_page.cr:23
Inside Users::ShowPage#render_user(User)

  23 | full_name(@user.age)
                 ^--------

It surely looks better with colors.

[asterite]

If we go this direction, I think --error-trace should disappear. I think we can always show the full trace in that compact format, assuming we only show one line of the error (in the past we used to dump the entire generated macro source, but that's not necessary). Then:

• you can focus on the main error at the bottom
• you have the trace with types at the top, if you need it
• no need to have an --error-trace flag and re-run the compilation from time to time
• no need to handle an extra flag in the compiler (simplified code)

[RX14]

If we include the argument types and all the ancillary information which was originally in the full trace we can consider removing the flag. We should separate removing the flag and merging this improvement though, so we can have a few versions of the compiler where we can still bring back the old behaviour if needed.

In the future we could "stop" the backtrace when the method arguments exactly match the type signature of the method (since any calls above that are useless).

[paulcsmith]

• Uses cyan instead of green. As @straight-shoota pointed out, these lines may be where the problem lies so better not to use a "good" color like green
• Adds where the source code is located
• Add some space because it got too busy with three lines per trace
• Uses a consistent color for text related to the problem

I'm also working on another tweaked version that might clarify what is going on. Will try to post later today

--error-trace

We should separate removing the flag and merging this improvement though, so we can have a few versions of the compiler where we can still bring back the old behaviour if needed.

I agree. I think we may get too bogged down trying to discuss both of those things in the same thread. I think we should separate the removal of --error-trace until after this is added and we see if we still need it or not, and if so, why. Maybe we need to rename it or make it do something else, but we won't know until we first actually use this new version IMO.

[paulcsmith]

This is my favorite so far. Less visual noise. Error section and rest of trace look more similar visually. Uses same colors and info as above

• Each trace looks more similar (not so disconnected visually)
• Also work better for long lines or small windows because they will be wrapped correctly. With the indented version it would throw off the indents (see below screenshot)

Previous solution (ew)

New solution (better)

[straight-shoota]

How about switching positions for location and code? This would make all traces follow a similar order as we're used to in the final message. It might actually be a good idea to change the order in the final one, too:

inside Lucky::Action#peform_action
lib/lucky/src/lucky/renderable.cr:97
response = call

inside Lucky::Action#response
src/actions/user/show.cr.cr:11
html Users::ShowPage, user: user

inside Users::Show#html(Users::ShowPage, User)
src/actions/users/show_page.cr.cr:11
render_user(@user)

Problem found in Users::ShowPage#render_user(User)
src/pages/users/show_page.cr:23

  23 | full_name(@user.age)
                 ^--------

[straight-shoota]

And perhaps we could consider highlighting the relevant columns in every code line, like in the final one. This probably wouldn't clog the white space but enhance it to be even more useful.

It might be weird for long method calls spanning multiple lines, though. But I guess that's also true for the final one.

While we're at it: I'm not sure about copying the line number prefix to the previous traces. It might improve readability. And having a uniform display is nice. But it's also good to have the final line stand out visually from the previous ones.

[paulcsmith]

Switching path with constant + method name

I like it better with the path + line in the second row 👍

Prefixing all source code with line number

I'm not sure how I feel about prefixing line numbers. Kind of like it, kind of don't 🤣

Had to add some dashes otherwise the last frame looked weird (too similar, but not quite the same)

Another version with path first

Here's one more version with the path + line first. I kind of like it. Just feels more natural to me for some reason but I don't feel strongly

[paulcsmith]

Also, I think if we feel this is close we can move forward with implementation and then make design tweaks in the PR. In some ways that's likely easier as this is a fairly manual process I'm doing right now

[bew]

I think there's still something missing: the highlighting/underline/.. of the actual call that fails.

it's confusing to see in the same color the code around the failing method.. For example when I saw the long line ending with perform_action I got confused "which call is failing here...". Is it handler? Is it payload? Is it new? Is it context? Is it params? Is it perform_action?

[paulcsmith]

@bew I’m not sure I understand. The line that fails is highlighted with yellow. Could you shed more light on what part is confusing? I’m not sure I’m seeing it

[paulcsmith]

Ok, a couple more that I think might address @bew's comments and that I think is clear in general

• Keeps the traces looking as similar as possible...
• but also makes it clearer which line had the error

Another alternative

• Similar but with slightly different colors and text

Moving forward

What say you core team? Shall we push forward with one of these? If so I'll open up a bounty. I'd love have this in :D

[bew]

It's not really what I meant.. Hard for me to show without nice graphics like you!

Given that foo.[[bar]].baz means that bar is highlighted in some way.

I'd like to see something like:

... some location info ... 
12 | handler.payload.new(context, handler.params).[[perform_action]]

... some location info ...
32 | reponse = [[call]]

... some location info ... 
41 | [[html]] User::ShowPage, user: user

To show exactly inside which call we go for the "next step".

I can try to "draw" a prototype like you if you need

[RX14]

Prefixing all source code with line number

I really like this one.

What @bew is proposing is that since we have the start/end character indexes of the part of the line which is causing the error (we use it for drawing the underline), we can highlight the part of the source code which fails in another colour. I'd actually de-highlight the rest of the source code to grey, and leave the part of the expression which is relevant as white.

This means that the new view contains all the information that the old error trace used, just more compactly. I really love the way this design is heading!

[rdp]

The current way definitely isn't quite satisfactory, since if I call .sort on an array of objects it sometimes prints out only the line in the stdlib, so there's room for improvement I think :)

Showing last frame. Use --error-trace for full trace.

In /usr/share/crystal/src/array.cr:193:22

 193 | n = @buffer[i] <=> other.to_unsafe[i]
                      ^--
Error: undefined method '<=>' for Url

(it doesn't show the line of code where I called .sort though it does mention it). :)

[paulcsmith]

@RX14 @bcardiff or any other core team members (I'm not sure who is core team now :P), I'm thinking we should move forward with this one: https://github.com/crystal-lang/crystal/issues/8410#issuecomment-554497957. I figure it may not be perfect but it is definitely better than what we have now. We can then tweak it in a PR or after it is merged, but at least we'll have something better and we can play around with it in real life to see how it works

If you agree I will make a bounty so that someone can get rewarded for this :D I think this is a really important enhancement for helping people debug their apps.

[asterite]

My suggestion for tackling this: revert the work done to improve the error messages that was done in the past, and then work on the original code base. The original code was showing all the frames. It seems we just needed to adjust how they were presented?

[paulcsmith]

I think that is a good idea. At this point I think showing the full trace is better as long as it also has this new style so it is clear where to focus and how to read it

[paulcsmith]

Actually never mind. Not sure we should revert it. That work also changed how macros are shown to make a lot more sense. And truncates the expanded macro since some macro expansions can be hundreds/thousands of lines long. I think we'd still want that

So I think we keep the full trace option but that shows more info in macro expansions, but we show all the frames either way. Maybe we rename the option but I think we could figure that out separately?

[asterite]

Sounds good. It's just that when I tried to actually implement what is described in the issue I couldn't understand the new code so I gave up. It probably just means that I was familiar with the code I wrote, that's all.

[sudo-nice]

But why do you want to put the error at the bottom? Wouldn't it be better to print the most important information (the error message) at the top, where it can be seen first? Most times the error is trivial and one doesn't even need the backtrace to catch the hint. If the error message wasn't enogh, one goes a level deeper, and so on and on. Also, with a narrow window, where the error to be reported, it would require to switch to that window and scroll it down to get to the error message.

Error: undefined method '<=>' for Url

193 | n = @buffer[i] <=> other.to_unsafe[i]
                      ^--

inside Lucky::Action#peform_action
lib/lucky/src/lucky/renderable.cr:97
response = call

inside Lucky::Action#response
src/actions/user/show.cr.cr:11
html Users::ShowPage, user: user

...

[paulcsmith]

@sudo-nice The main reason is that the top of the trace is often hidden outside the view of the terminal window so is actually harder to find. Traces are typically quite long, and many people use short terminal windows in tmux or VSCode that are only 20-30 lines high. Having it at the bottom is always shown as terminals will keep the scroll at the bottom by default

[paulcsmith]

@asterite Maybe it'd be easier to revert and reimplement the macro collapse code? I guess whoever tackles it can try it out and see what's easier! It may be easier to revert and start from scratch

[sudo-nice]

@paulcsmith Oh, I see. For me it's opposite, I see the top and have to scroll to the bottom when needed. So, currently it's quite comfortable for me to observe errors, but that won't longer be like that, in case there is no more option to disable full trace.