Codeception: Error stack trace is not helpful

[sahanh]

Since codeception wrap around phpunit, the errors that popout are showing a codeception files based stack trace instead of real application's stacktrace.

Sample
https://gist.github.com/sahanh/5cf78feb8c1a2223951c

As you can see the stack trace is completely hiding the real application files.

However in phpunit/src/Framework/TestResult.php@657

I removed the exception handler for Exception (fallback) http://d.pr/i/1hlqR+

And now it shows the correct, helpful stacktrace.

https://gist.github.com/sahanh/2ccd515f751276670687

Is there any option that we can tweak to get this to work without editing vendor files?

[vaseninm]

Hi. I have same problem, but my stacktrace always
1 /home/vaseninm/www/projects/dev-api/tests/codecept.phar:7

[neoascetic]

+1

[nsanden]

Huge +1

Thank you @sahanh for a temp fix!

[samdark]

Agree that it's a good thing to fix it but removing exception wrapper isn't a good idea since it could be actually used in unit tests. Need to make sure:

1. That real exception is somewhere in the exceptions chain.
2. Introduce our own handler that works after phpunit's and adjusts error message by getting original exception.

[DavertMik]

@samdark Looks like the real issue was not about exception wrapper. Its name is really confusing, that's all... But thrown Exception does not contain a precise stack trace, as test method is inovked via reflection there is no file or line information about the cause of error. That's why we can't see the source of error.

I fixed the issue by showing all available information we can handle from this, nevertheless we can't get info about file or line where error did happen :(

[samdark]

Is the exception formed at phpunit side? If yes it worth pull-requesting it with a fix.

[DavertMik]

If the test throws exception by itself there won't be any meaningful information because test id not executed directly, it is triggered from reflection. If exception happens it happens inside reflection->invoke method. Thus, nothing really useful ( If exception happens in methods that are executed from tests, they will be added to stack trace.

I hope this commit do its best to handle such cases
https://github.com/Codeception/Codeception/commit/75fd3e26d973e584f39efa757ea71df0eb141461

PS. You can update from 2.0 branch to get this fixed ASAP

[mindplay-dk]

I don't know if this is the same issue, or whether it's caused by Codeception or PhpUnit, but...

Take this example:

<?php

function foo() {
    bar();
}

function bar() {
    baz();
}

function baz() {
    throw new RuntimeException(); // line 12: untraceable!
}

foo();

With xdebug enabled, the output is:

Fatal error: Uncaught exception 'RuntimeException' in C:\temp\bam.php on line 12

RuntimeException:  in C:\temp\bam.php on line 12

Call Stack:
    0.0001     230384   1. {main}() C:\temp\bam.php:0
    0.0002     230416   2. foo() C:\temp\bam.php:15
    0.0002     230448   3. bar() C:\temp\bam.php:4
    0.0002     230480   4. baz() C:\temp\bam.php:8

The stack trace goes all the way to line 12, where the throw statement is issued.

The same is true for standard PHP error handling:

Fatal error: Uncaught exception 'RuntimeException' in C:\temp\bam.php:12
Stack trace:
#0 C:\temp\bam.php(8): baz()
#1 C:\temp\bam.php(4): bar()
#2 C:\temp\bam.php(15): foo()
#3 {main}
  thrown in C:\temp\bam.php on line 12

With xdebug, the stack traces are in backwards order, so Codeception appears to be consistent with PHP's stack trace order. (Good, in my opinion. I've asked Derick Rethans why they're backwards in xdebug.)

I don't know why xdebug doesn't replicate PHP's file/line number reference format in stack traces, and this is a minor annoyance, since e.g. PhpStorm can't make clickable references - annoying when trying to debug.

Codeception also doesn't follow that format - the file-names are clickable, but the line number references aren't recognized due to custom formatting.

More annoying is the fact that, when it reaches the top of the stack trace, e.g. the line in the test that started the calls, the reference isn't even a filename, it's a class-name and method-name, which is no way going to be clickable anywhere. I can't think of a good reason to justify the originating call site having inconsistent output formatting from any other call site?

Biggest issue though, is that the file/line number where the throw statement was issued, doesn't appear in the call stack in Codeception's output at all! The bottom of the output stack trace is the method/function that was called which generated the exception, but you can't tell at which line in the function that occurred.

I would like to suggest bringing the stack traces into alignment with standard PHP stack traces as much as possible - I can understand the need to filter the portion of the call stack generated by the test framework, but everything from there on out would be much more useful if it were consistent with ordinary stack traces. Having to "switch modes" and "parse" different output, is distracting.

[nsanden]

Still having issues as well... it should tell me the "stristr()" call is in my \components\Order.php

Time: 3.63 seconds, Memory: 11.75Mb

There was 1 error:

---------
1) Test get plan (OrderTest::testGetPlan)

  [yii\base\ErrorException] stristr(): Empty needle

C:\xampp\htdocs\manage\tests\codeception\unit\OrderTest.php:65
C:\xampp\htdocs\manage\vendor\phpunit\phpunit\src\Framework\TestCase.php:886
C:\xampp\htdocs\manage\vendor\phpunit\phpunit\src\Framework\TestCase.php:886
C:\xampp\htdocs\manage\vendor\phpunit\phpunit\src\Framework\TestCase.php:746
C:\xampp\htdocs\manage\vendor\phpunit\phpunit\src\Framework\TestResult.php:601
C:\xampp\htdocs\manage\vendor\phpunit\phpunit\src\Framework\TestCase.php:702
C:\xampp\htdocs\manage\vendor\phpunit\phpunit\src\Framework\TestSuite.php:735
C:\xampp\htdocs\manage\vendor\codeception\codeception\src\Codeception\PHPUnit\Ru
nner.php:89
C:\xampp\htdocs\manage\vendor\codeception\codeception\src\Codeception\SuiteManag
er.php:153
C:\xampp\htdocs\manage\vendor\codeception\codeception\src\Codeception\Codecept.p
hp:203
C:\xampp\htdocs\manage\vendor\codeception\codeception\src\Codeception\Codecept.p
hp:172
C:\xampp\htdocs\manage\vendor\codeception\codeception\src\Codeception\Command\Ru
n.php:184
C:\xampp\htdocs\manage\vendor\symfony\console\Command\Command.php:259
C:\xampp\htdocs\manage\vendor\symfony\console\Application.php:878
C:\xampp\htdocs\manage\vendor\symfony\console\Application.php:195
C:\xampp\htdocs\manage\vendor\symfony\console\Application.php:126
C:\xampp\htdocs\manage\vendor\codeception\codeception\codecept:28

[mindplay-dk]

Stack traces are still inconsistent.

Scenario Steps:

 1. $I->testConstraints("Kodus\Forms\Fields\TextField",["foo"],["",null) at tests\unit\FieldConstraintCest.php:19

#1  C:\workspace\test\forms\tests\_support\Helper\Unit.php:82
#2  Helper\Unit->testConstraints
#3  C:\workspace\test\forms\tests\_support\_generated\UnitTesterActions.php:378
#4  C:\workspace\test\forms\tests\unit\FieldConstraintCest.php:19
#5  Kodus\Forms\Test\FieldConstraintCest->checkTextField

FAILURES!
Tests: 50, Assertions: 284, Errors: 1.

Two out of five stack points don't show a filename and line-number.

Also note the mangled parens in testConstraints("Kodus\Forms\Fields\TextField",["foo"],["",null) - the closing ] is missing.

[mindplay-dk]

For the record, I have filed bug reports against xdebug and php-unit for controversial stack-trace order.

This really needs to be fixed, here, in xdebug, and in php-unit, all of which are inconsistent with php's own error and exception stack traces.

You can argue in favor of one direction or the other - I don't personally care at all, but I care about consistency, because it's time-consuming to make that mental switch and try to figure out the order of stack-traces in various contexts through a normal work-day.

PHP's own stack-traces for errors and exceptions are consistent with that of JavaScript browser consoles, with Node, as well as with Java, C# and probably other languages.

Here's a standard error and exception stack trace from php 7:

$ php -r "function foo() { throw new RuntimeException; } function bar() { foo(); } function baz() { bar(); } baz();"
PHP Fatal error:  Uncaught RuntimeException in Command line code:1
Stack trace:
#0 Command line code(1): foo()
#1 Command line code(1): bar()
#2 Command line code(1): baz()
#3 {main}
  thrown in Command line code on line 1

Fatal error: Uncaught RuntimeException in Command line code:1
Stack trace:
#0 Command line code(1): foo()
#1 Command line code(1): bar()
#2 Command line code(1): baz()
#3 {main}
  thrown in Command line code on line 1

Please, let's try to get stack-traces that are more consistent with php:

• Displayed in head-first order
• Consistently numbered as 0 (head of call stack) to n
• Include {main} in the stack trace
• Consistently display filenames and line-numbers (not classes or test-names)

It's fine to _also_ display the class/test-name of course, but please don't weave that information into the stack-trace - the visual inconsistency between lines is distracting. Please display this extra information above or below the stack-trace itself.

[nsanden]

this makes me really sad

There was 1 error:

---------
1) Test modify account (OrderTest::testModifyAccount)

  [yii\base\ErrorException] Trying to get property of non-object

C:\xampp\htdocs\manage\tests\codeception\unit\OrderTest.php:299
C:\xampp\htdocs\manage\vendor\phpunit\phpunit\src\Framework\TestCase.php:909
C:\xampp\htdocs\manage\vendor\phpunit\phpunit\src\Framework\TestCase.php:909
C:\xampp\htdocs\manage\vendor\phpunit\phpunit\src\Framework\TestCase.php:768
C:\xampp\htdocs\manage\vendor\phpunit\phpunit\src\Framework\TestResult.php:612
C:\xampp\htdocs\manage\vendor\phpunit\phpunit\src\Framework\TestCase.php:724
C:\xampp\htdocs\manage\vendor\phpunit\phpunit\src\Framework\TestSuite.php:747
C:\xampp\htdocs\manage\vendor\codeception\codeception\src\Codeception\PHPUnit\Runner.php:89
C:\xampp\htdocs\manage\vendor\codeception\codeception\src\Codeception\SuiteManager.php:153
C:\Users\Nate\AppData\Roaming\Composer\vendor\codeception\codeception\src\Codeception\Codecept.php:203
C:\Users\Nate\AppData\Roaming\Composer\vendor\codeception\codeception\src\Codeception\Codecept.php:172
C:\Users\Nate\AppData\Roaming\Composer\vendor\codeception\codeception\src\Codeception\Command\Run.php:184
C:\Users\Nate\AppData\Roaming\Composer\vendor\symfony\console\Command\Command.php:259
C:\Users\Nate\AppData\Roaming\Composer\vendor\symfony\console\Application.php:844
C:\Users\Nate\AppData\Roaming\Composer\vendor\symfony\console\Application.php:192
C:\Users\Nate\AppData\Roaming\Composer\vendor\symfony\console\Application.php:123
C:\Users\Nate\AppData\Roaming\Composer\vendor\codeception\codeception\codecept:28

[DavertMik]

@nsanden

[yii\base\ErrorException] Trying to get property of non-object

C:xampp\htdocs\managetests\codeception\unit\OrderTest.php:299

what is wrong here? You have a file and line with error in stack trace. If there is something more than that, please attach a code of OrderTest

[nsanden]

@DavertMik

The error "Tying to get propery of non-object" is something that occurred inside my code somewhere, in some other file, not OrderTest.php:299 - Infact it ended up being in a file Order.php in my project. I was only able to really track that down when I removed the code in the original comment in this issue from sahanh - then the stack trace included one more line like this:

() at C:\xampp\htdocs\manage\modules\order\components\Order.php:259

---

It seems this issue might only be occuring with xdebug on - i'll report back when i know more

[mindplay-dk]

I've started working on a dedicated stack-trace library - this will provide an API and object model for working with stack-traces, will generate error-messages, format stack-traces, report error-types, etc... it's still a bit rough, but feel free to take a look.

[DavertMik]

@mindplay-dk I really like the idea, and I hope to try it, and include in future versions of codeception once it is ready.

[motin]

May I propose that this issue is closed and split up into the separate sub-issues that have emerged?

_Issue 1_ - OP's issue was that the errors are showing a codeception files based stack trace instead of real application's stacktrace.

This issue was been fixed a while back, since with codeception 2.2 the following type of stack trace is shown:

  [Error] Call to a member function getFoo() on null

Scenario Steps:
... *scenario steps omitted for clarity* ...

#1  /app/src/Foo.php:280
#2  /app/src/Bar.php:150
...

_Issue 2_ - Then we have @nsanden's issue that the actual file and line where the exception was thrown is missing from the stack trace. This is still prevalent in 2.2 and is reported here: https://github.com/Codeception/Codeception/issues/3200

_Issue 3_ - Finally we have a mention from @mindplay-dk about a dedicated stack-trace library. The suggestion to use that library should be a new issue

[samdark]

Yes, @motin please create separate issues and notify us so we close this one.

[motin]

@samdark, I already created a separate issue for "Issue 2" back in June (#3200), and it would probably make more sense for @mindplay-dk to create a separate issue for "Issue 3" when that becomes relevant.

[mindplay-dk]

I started the stack-trace library here but got hung up on problems that made me question the usefulness of it to begin with.

I ended up extracting this library which made it very easy to create a readable stack trace in another project where the stack-trace library didn't fit.

The latter might be of some use. I'm not sure I want to pursue the first, as it is actually rather easy to implement with that second library - I'm not convinced of the reuse value of a stack-trace abstraction; it mostly seemed to get in the way, but maybe the design just wasn't good enough, I'm not sure...

[DavertMik]

Yeah, this discussion should proceed in other issues. If you have a problem please create an issue with a stacktrace and Codeception version. Working on this currently impossible as lots of things may have changed from the time it was originally reported.

@mindplay-dk any progress on your library? I hope you didn't dump that project