Improve compile time error with --error-trace disabled

paulcsmith commented 5 years ago

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 commented 5 years ago

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 commented 5 years ago

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 commented 5 years ago

@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 commented 5 years ago

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 commented 5 years ago

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 commented 5 years ago

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 commented 5 years ago

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 commented 5 years ago

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 commented 5 years ago

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 commented 4 years ago

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 commented 4 years ago

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 commented 4 years ago

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 commented 4 years ago

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 commented 4 years ago

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 commented 4 years ago

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 commented 4 years ago

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 commented 4 years ago

@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 commented 4 years ago

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 commented 4 years ago

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 commented 4 years ago

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 commented 4 years ago

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 commented 4 years ago

@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 commented 4 years ago

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 commented 4 years ago

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 commented 4 years ago

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 commented 4 years ago

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 commented 4 years ago

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 commented 4 years ago

@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 commented 4 years ago

@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 commented 4 years ago

@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 commented 4 years ago

@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 commented 4 years ago

@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 commented 4 years ago

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 commented 4 years ago

@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 commented 4 years ago

@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 commented 4 years ago

@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 commented 4 years ago

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 commented 4 years ago

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

Blacksmoke16 commented 4 years ago

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

straight-shoota commented 4 years ago

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 commented 4 years ago

@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 commented 4 years ago

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

straight-shoota commented 4 years ago

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 commented 4 years ago

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 commented 4 years ago

@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 commented 4 years ago

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 commented 4 years ago

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.

asterite commented 3 years ago

We could at least remove the --error-trace option and always show the trace (without the "Nil trace" or "Foo trace" part, which seems to be not very useful). What do you think? Because the overall revamp is pretty hard, at least the way the compiler is done right now.

straight-shoota commented 3 years ago

I'm not sure it would be a worthy improvement because the status quo is already somewhat usable and works. If we change that it might be a disruption for some. So I'd rather work on a change for good.

Side note: I have begun to restart my efforts in this direction (#10197 is evidence of that). And I think I figured a plan how to do it in smaller incremental steps. Focusing on SyntaxError first should keep things simpler because many of the more complex concepts are only relevant for semantic errors. It's still not trivial though. As one of the next steps I would continue the discussion on how we actually want specific errors to format. Especially with respect to error traces and virtual files.

asterite commented 3 years ago

@straight-shoota Half of the time when I'm developing the compiler I find myself going back with my cursor to add --error-trace. It's very annoying.

The full error message is something like this:

trace 1
trace 2
trace ...
trace N # This is the last one
====== # All that follows might appear or not
Nil trace:
trace 1
trace 2
trace ...
trace N

Basically, a call trace that shows how you got to the error, and then an optional trace that shows how that type came to exist (for example, where did a nil value come from).

Most of the time the last part is not useful: you know why you got a nil value or an unexpected type. That's why in the past we hid that by default and made it only show with --error-trace.

But then another PR came and hide all of the original trace (trace 1 upto trace N - 1) so now if you pass an incorrect type to a method, and that method uses that unexpected type, you get an error in that method... which might have not been written by you!

What I suggest is to always show the initial trace, and --error-trace would show the type trace. For example, take a look at this:

[1, 2, 3, "foo"].max

This is the error that you get:

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

In /usr/local/Cellar/crystal/0.35.1_1/src/number.cr:193:10

 193 | self > other ? 1 : (self < other ? -1 : 0)
            ^
Error: no overload matches 'Int32#>' with type (Int32 | String)

I mean... WAT? That's not my code!

With my suggestion it would show this:

In foo.cr:1:18

 1 | [1, 2, 3, "foo"].max
                      ^--
Error: instantiating 'Array(Int32 | String)#max()'

In /usr/local/Cellar/crystal/0.35.1_1/src/enumerable.cr:852:5

 852 | max_by &.itself
       ^-----
Error: instantiating 'max_by()'

In /usr/local/Cellar/crystal/0.35.1_1/src/enumerable.cr:870:20

 870 | found, value = max_by_internal { |value| yield value }
                      ^--------------
Error: instantiating 'max_by_internal()'

In /usr/local/Cellar/crystal/0.35.1_1/src/enumerable.cr:886:5

 886 | each_with_index do |elem, i|
       ^--------------
Error: instantiating 'each_with_index()'

In /usr/local/Cellar/crystal/0.35.1_1/src/enumerable.cr:443:5

 443 | each do |elem|
       ^---
Error: instantiating 'each()'

In /usr/local/Cellar/crystal/0.35.1_1/src/indexable.cr:187:5

 187 | each_index do |i|
       ^---------
Error: instantiating 'each_index()'

In /usr/local/Cellar/crystal/0.35.1_1/src/indexable.cr:187:5

 187 | each_index do |i|
       ^---------
Error: instantiating 'each_index()'

In /usr/local/Cellar/crystal/0.35.1_1/src/enumerable.cr:443:5

 443 | each do |elem|
       ^---
Error: instantiating 'each()'

In /usr/local/Cellar/crystal/0.35.1_1/src/enumerable.cr:886:5

 886 | each_with_index do |elem, i|
       ^--------------
Error: instantiating 'each_with_index()'

In /usr/local/Cellar/crystal/0.35.1_1/src/enumerable.cr:888:20

 888 | if i == 0 || compare_or_raise(value, max) > 0
                    ^---------------
Error: instantiating 'compare_or_raise((Int32 | String), (Int32 | String))'

In /usr/local/Cellar/crystal/0.35.1_1/src/enumerable.cr:1117:11

 1117 | value <=> memo || raise ArgumentError.new("Comparison of #{value} and #{memo} failed")
              ^--
Error: instantiating '(Int32 | String)#<=>((Int32 | String))'

In /usr/local/Cellar/crystal/0.35.1_1/src/number.cr:193:10

 193 | self > other ? 1 : (self < other ? -1 : 0)
            ^
Error: no overload matches 'Int32#>' with type (Int32 | String)

I know, it's long. But what's the harm in that? The last frame is exactly the same as before. Maybe it's the useful one, maybe it's not. It doesn't matter because now I can scroll up and understand the problem without having to pass --error-trace, which after removing the possibility to pass flags at the end becomes even more cumbersome. For example I usually run crystal foo.cr. Now I need to change it into crystal build --error-trace foo.cr. Do you understand my problem? This happens to me all of the time.

crystal-lang / crystal