Crystal: Spec reporting shows different line numbers in results

[straight-shoota]

require "spec"

def my_it(file = __FILE__, line = __LINE__)
  it "my_it", file, line do
    true.should be_false
  end
end

my_it

The result from this spec looks like this:

Failures:

  1) my_it

       Expected: false
            got: true

     # eval:5

Finished in 83 microseconds
1 examples, 1 failures, 0 errors, 0 pending

Failed examples:

crystal spec eval:9 # my_it

The line number is 5 in the detailed result and 9 in the summary. This is because the detailed view shows the location where the AssertionFailed was raised while the summary shows the location given to it using file and line variables.

I'd suggest that both should show the same line number and it should be the location provided to it (my_it => 9). If you're using such spec helpers (and explicitly set the location of the caller), you're usually interested in the helper call that caused it, not the location in the helper method definition.

We should however make sure that it doesn't affect other cases: When an it block directly contains several individual expectations, the line number should certainly point the location where the expectation was raised.

Take this example spec:

require "spec"

it do
  true.should be_true
  true.should be_false
end

It currently prints this result:

Failures:

  1) assert

       Expected: false
            got: true

     # eval:5

Finished in 519 microseconds
1 examples, 1 failures, 0 errors, 0 pending

Failed examples:

crystal spec eval:3 # assert

Line 5 is actually the important line. I'd suggest that the summary should also point to this line. I guess pointing to the beginning of the example is actually just a leftover from when spec could only target the beginning of the block for selected execution.

In essence, if it is invoked with explicit file and line arguments, those should be used as location of the failing spec in both detailed result and summary. Otherwise it should implicitly use the location of the failing expectation (or exception).

[asterite]

This is a feature:

describe "Parser" do
  it_parses "nil", nil

  it_parses "true", true.bool
  it_parses "false", false.bool
end

Imagine one of those fail. The important part where I want to look is the line that says it_parses. That's the important thing I want to start looking at. The line where the actual assertion failed is also helpful, because maybe there are a couple of assertions. But without an indication of the line where it_parses is located there would be no way to know where it failed in the first place.

This is the main reason __FILE__ and__LINE__ are forwarded in specs.

[asterite]

Basically:

• the summary tells you which test failed (if you forwarded it, the wrapper call is the test, like in the it_parses example above)
• the detail tells you which assertion failed

By the way, this is how it works in RSpec, minus the location forwarding, which is quite annoying in RSpec (you have to define helpers in a specific file and then mute those methods with a regex or something like that).

[straight-shoota]

@asterite That's what this is about: I would like to see the line number where it_parses is called in the detailed view.

Assuming your is somewhere in the middle of a larger spec file and it_parses is defined at the very beginning of that file, you get some output like this if the first and last example fail:

  1) it_parses

       Expected: nil
            got: foo

     # foo_spec.cr:12

  2) it_parses

       Expected: true
            got: foo

     # foo_spec.cr:12

The location passed as file and line is only displayed in the summary at the end:

crystal spec foo_spec.cr:310 # it_parses
crystal spec foo_spec.cr:313 # it_parses

When I'm debugging these failures I don't really need to know the line of the failing expectation, I need to know where it_parses is called to understand what the spec is about. It seldom helps to know which assertion failed without knowing the exact spec data. This requires me to scroll down to the summary to get that information.
That's why I suggest that the detailed result should show the line numbers of the example (foo_spec.cr:310 and foo_spec.cr:313)

In general, I find it very un-intuitive that the result shows different line numbers in detail and summary. It's not self-explanatory what they mean.

[asterite]

Well, I (and probably others) need to know the line of the failing expectation:

require "spec"

private def it_does_something(x, y)
  it "does something with #{x} and #{y}" do
    (x * y).should eq(12)
    (x + y).should eq(8)
  end
end

describe "foo" do
  it_does_something 2, 6
  it_does_something 3, 4
end

Now you get:

.F

Failures:

  1) foo does something with 3 and 4
     Failure/Error: (x + y).should eq(8)

       Expected: 8
            got: 7

     # foo.cr:6

Finished in 181 microseconds
2 examples, 1 failures, 0 errors, 0 pending

Failed examples:

crystal spec foo.cr:4 # foo does something with 3 and 4

Super clear:

• The test that failed is defined at line 4
• This assertion failed (x + y).should eq(8)
• And the assertion was at line 6

You got all the info you need. Repeating the number 4 instead of saying 6 gives you less information to debug.

You really want to know that the assertion that failed was the +. Without that information you'll have to start debugging the test itself to know where the assertion failure was.

[RX14]

The information is clear once you know how to interpret it but I agree that it's not self-explanitory UX.

I'd suggest something like

.F

Failures:

  1) in spec: foo does something with 3 and 4
     at foo.cr:4

     Failure/Error: (x + y).should eq(8)

       Expected: 8
            got: 7

     at foo.cr:6

Finished in 181 microseconds
2 examples, 1 failures, 0 errors, 0 pending

Failed examples:

crystal spec foo.cr:4 # foo does something with 3 and 4

That's not nearly perfect but you get the idea.

I've frequently wanted the foo.cr:4 line in the long message instead of the summary, when I have many failing specs and the summary is off the screen (common when porting).

[asterite]

@RX14 What you said last is a really good point. I also wanted this but didn't realize it, or just accepted things as they are.

Feel free to tweak the output format and send a PR :-)

[BobG1983]

Assuming you're planning on submitting a PR, can I suggest:

.F

Failures:

  1) in spec: foo does something with 3 and 4
     Failure/Error: (x + y).should eq(8)

       Expected: 8
            got: 7

     Assertion at: foo.cr:6
     Test at: foo.cr:4

Finished in 181 microseconds
2 examples, 1 failures, 0 errors, 0 pending

Failed examples:

crystal spec foo.cr:4 # foo does something with 3 and 4

or

.F

Failures:

  1) Spec (foo.cr:4): foo does something with 3 and 4
     Assertion (foo.cr:6): (x + y).should eq(8)

       Expected: 8
            got: 7

Finished in 181 microseconds
2 examples, 1 failures, 0 errors, 0 pending

Failed examples:

crystal spec foo.cr:4 (@foo.cr:6) # foo does something with 3 and 4

It gets the same amount of information across with more clarity, in a smaller space.

[straight-shoota]

Looks like you're trying to be more expressive... but I don't think that helps to improve readability.

I'd keep changes from the current output format at a minimum and go for something like @RX14 suggested.

By the way, I've been trying to setup some specs for the spec output. They're missing entirely.

[BobG1983]

@RX14, @straight-shoota What's your feeling on:

.F

Failures:

  1) Spec      (spec/play_spec.cr:4): foo does something with 3 and 4
     Assertion (spec/play_spec.cr:6): (x + y).should eq(8)

       Expected: 8
            got: 7

Finished in 462 microseconds
2 examples, 1 failures, 0 errors, 0 pending

Failed examples:

spec/play_spec.cr:4 (@spec/play_spec.cr:6) # foo does something with 3 and 4

Changes are fairly minimal but more explicit, and it means you get both line numbers in both outputs?

Also, I think I deleted my other comment as you posted, so I'm not sure which bit of it you're referring to.

FYI, I'm happy to make it look like whatever :)

[straight-shoota]

Taking this code as a reference. In the above examples, @asterite and @RX14 referred to the same code, I've just added the file and line arguments because you'd usually want to know where the helper method was invoked, not where it defines the example (because that would be identical to all created by it_does_something).

require "spec"

private def it_does_something(x, y, file = __FILE__, line = __LINE__)
  it "does something with #{x} and #{y}", file, line do
    (x * y).should eq(12)
    (x + y).should eq(8)
  end
end

describe "foo" do
  it_does_something 2, 6
  it_does_something 3, 4
end

I would just add the following minimal changes:

 .F

 Failures:

   1) foo does something with 3 and 4
+     at spec/foo_spec.cr:12
+     Failure/Error: (x + y).should eq(8)

       Expected: 8
            got: 7

     # spec/foo_spec.cr:6

Finished in 83 microseconds
2 examples, 1 failures, 0 errors, 0 pending

Failed examples:

crystal spec spec/foo_spec.cr:12 # foo does something with 3 and 4

[straight-shoota]

And an example which directly defines an expectation:

require "spec"

describe "foo" do
  it "does something with 3 and 4" do
    (3 + 4).should eq(8)
  end
end

F

Failures:

  1) foo does something with 3 and 4

       Expected: 8
            got: 7

     # spec/foo_spec.cr:5

Finished in 88 microseconds
1 examples, 1 failures, 0 errors, 0 pending

Failed examples:

-crystal spec spec/foo_spec.cr:4 # foo does something with 3 and 4
+crystal spec spec/foo_spec.cr:5 # foo does something with 3 and 4

Maybe we could add at spec/foo_spec.cr:4 in the detailed view like in the other example, but I'm not really conviced this would be necessary.

[BobG1983]

Personally, I would like spec/foo_spec.cr:4 in the detailed view, just for the sake of clarity and consistency.

I'll see if I can put something together today.