Crystal: 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.

[paulcsmith]

@sudo-nice Oh interesting! I've never had that happen so that's pretty interesting that yours does that. I'm curious to hear what your setup is.

[sudo-nice]

@paulcsmith I use [neovim] with [vim-dispatch] plugin, which catches the errors into a special window.
I understand that majority would benefit from the layout you suggested, so I'm not raising an objection here, just indicating to the devs that it might be good to have an option for a really short trace (like the current one), if possible.

[paulcsmith]

Oh interesting. Thanks for sharing! And yes I could see how an option to reverse order or show just the last frame (--last-exception-frame or something) might be helpful as an additional feature later on

[RX14]

@sudo-nice sounds like a feature request to that vim plugin would be nice!

I really like the "Another alternative" design in the comment you proposed, I'd like to keep any fancy unicode to a minimum.

[asterite]

@paulcsmith What's the agreed error format, and what colors did you use in the screenshot? I'll try to implement this. It doesn't seem to be that hard after all.

[paulcsmith]

@asterite here is the newest screenshot. Simpler colors, less bold. Error is highlighted in red so it is more visible with white terminals (yellow is practically invisible)

Colors and sample code for this example here: https://github.com/paulcsmith/crystal-errors/blob/master/errors/trace_all.cr

I think macros should still do just the error line and not the full expandd macro by default and the -error-trace should be something like --expand-error-trace (or something like that) if you want to see the macros fully expanded. Or maybe we just don't add that and people have to use the crystal tool to see macros.

Personally I'd like to be able to expand them, but can see if it is better to figure out later

[Blacksmoke16]

It's also not real helpful that macro code within like included/inherited/finished don't really show the line that the exception happens.

https://play.crystal-lang.org/#/r/8xiz

module Test
  macro included
    {{ raise "err" }}
  end
end

class Bar
  include Test
end

crystal test.cr
Showing last frame. Use --error-trace for full trace.

In test.cr:8:3

 8 | include Test
     ^
Error: err

Or with --error-trace

crystal test.cr --error-trace
In test.cr:8:3

 8 | include Test
     ^
Error: err

Much more helpful :S

[straight-shoota]

@Blacksmoke16 That's a different story. There might already be an issue for that, otherwise open a new one.

[Blacksmoke16]

Yea there is https://github.com/crystal-lang/crystal/issues/7147 and https://github.com/crystal-lang/crystal/issues/7394

[straight-shoota]

I've been taking a look at this. Unfortunately, it's probably not that easy. The whole process of handling compiler error is very convoluted.

The problem is probably that this code has grown over time and more and more feature where added. But the design has not grown to handle the complexity. For example, the complex error formatting is directly embedded into exception types and message generation spread all over the compiler source. Even lots of specs depend on that formatting.

I believe a bigger refactoring of compiler errors is necessary to enable us to redefine the error output without creating a complete mess.
However, I've already started with that and there's already quite some progress. Compiler errors are now reduced to storing data and a separate formatter is responsible for printing them. And I've started adding lots of specs to formalize the expected behaviour.
Right now I'm looking into untangling the wrapping chains for capturing error frames, which currently buries the actual error deeply nested in a hierarchy of wrapping exceptions, thus making it hard to reach.

(WIP preview is available https://github.com/crystal-lang/crystal/compare/master...straight-shoota:feature/compiler-error)

[asterite]

@straight-shoota Thank you for this. I also took a look at it and came to the same conclusion. And I'm glad you are taking care of it, it's probably better if someone looks at the problem with fresh eyes. And you code extremely clear and well, much better than me, so the resulting code will be great.

[RX14]

@straight-shoota i assume this partially clears up the "printing" part of the warnings code too

[straight-shoota]

Yes. I've refactored warnings to work likeas errors, just that they're not raised and directly added to program.warnings. Every warning is an instance of a WarningError. We'll probably need to refine the exact behaviour of warnings, but there's now a very solid base for that.

[RX14]

Yes. I've refactored warnings to work likeas errors, just that they're not raised and directly added to program.warnings. Every warning is an instance of a WarningError

perfect!!!

Adding warnings to Program instead of listing them directly was the basis of my warnings refactor to not litter the output :)

I'm sure this'll make it a lot easier, thank you.

[paulcsmith]

@straight-shoota That is incredible news. I imagine that at some point in the future this code could be used to allow library authors to raise custom errors more easily too! But that is for another day 😜

Thanks for working on this 💚

[straight-shoota]

To give you an update on the process: The first PRs are on their way. Once those preliminaries are merged, I'll proceed to PR the main refactoring. Unfortunatly this is hard to separate into isolated commits. I'll try my best but it's going to be a heavy review process :/

This will also add a new ErrorFormatter class which is responsible for printing error message. I suppose the first iteration should probably have pretty much the same behaviour as currently: only show the last frame by default and opt in for more using --error-frame, and probably also similar formatting.

The next step would then be to start iterating on improvements to the error formatting.
This process can already start, though. The formatter implementation is working good enough for that.
If you want to give it a try, it's available in my working branch:
https://github.com/straight-shoota/crystal/tree/feature/compiler-error

A good help for that would be to collect examples that produce different kinds of error messages. Reproducible source code would be great. Maybe we can enhance Paul's error repo with this? https://github.com/paulcsmith/crystal-errors
Just pasting in a few source files that trigger compiler errors would be great. Then we can easily run current and redesigned error formatter side by side to see what they produce and how the output can be improved.

One insight I have already gained is that we'll definitely need an upper limit of error frames to display by default. While working on the compiler I noticed traces going hundreds of frames deep. There's no point in showing so much. So we should find some default size 1 < x < Int32::MAX that shows enough information right away, but doesn't spill out too much to completely lose context.

[RX14]

There was a suggestion in this thread to print all stack frames except for the last one on a single line, without context, which I think would help a lot with long stacktraces. Could experiment with that first before limiting length.