Error string on engine errors lacks actual error message

[dreed-sd]

Versions

(list all versions where you have replicated the bug)

• Godot: 4.6
• GUT: 9.5
• OS: MacOS

The Bug

When a test fails due to an engine error, the text that reports why the test failed lacks the original error message from the engine.

Reason is that when there's an engine error, there are 2 strings provided to the OS logger that is registered (in this case GUT's ErrorTracker): code, and rationale. The code is usually some arcane statement like the variable that was asserted on, while the rationale has a more meaningful message. But GUT reports only the code.

Steps To Reproduce

Run this test:

func test_gut_error_reporting() -> void:
	OS.delay_usec(-10)
	assert_true(true)

The test will fail with:

    [Failed]:  Unexpected Errors:
    [1] <engine-0>Condition "p_usec < 0" is true.
          at line -1

But the actual error message logged by the engine was much better:

ERROR: Can't sleep for -10 microseconds. The delay provided must be greater than or equal to 0 microseconds.

This is not the best example as even the 'code' message is useful, but often times it isn't. If there's a problem loading a scene, for example, then the error 'code' is just "!valid was true" instead of the much more meaningful string about what part of the scene had a problem.

I believe the fix should be to update the ErrorTracker to do this ternary operation in get_fail_text_for_errors, but maybe there's a better format that uses both strings, and maybe there are other locations where this should be done.

	if(errors.items.has(test_id)):
		for error in errors.items[test_id]:
			if(_is_error_failable(error)):
				error_texts.append(str('<', error.get_error_type_name(), '>', error.rationale if error.rationale else error.code)) # <-- use rationale if provided

[dreed-sd]

Even better would be to include the file name and line number like this:

                           var msg = str('<', error.get_error_type_name(), '>', error.rationale if error.rationale else error.code)
                           if error.file and error.file != GutUtils.NO_TEST and error.line >= 0:
                                   msg += str('\n    at: ', error.function, ' (', error.file, ':', error.line, ')')
                           error_texts.append(msg)

That way you get this:

    [Failed]:  Unexpected Errors:
    [1] <engine-2>Trying to assign value of type 'String' to a variable of type 'int'.
        at: SomeType.some_method (res://some_script.gd:123)

...instead of this which is borders on useless:

    [Failed]:  Unexpected Errors:
    [1] <engine-2>Trying to assign value of type 'String' to a variable of type 'int'.

Perhaps it should include the full stack, but that is likely too verbose. This at least points at the location of the problem.

[bitwes]

I agree, It should be better, especially when run through the editor. From the command line/VSCode it's not so bad, since the full error is in the log. From the editor though, it's in the debug tab and can be lost with the rest of the errors that you expected to happen.

Perhaps it should include the full stack, but that is likely too verbose. This at least points at the location of the problem.

I don't think this is necessary in the summary, nor from the command line. In the editor though, it would be good to put more info when the test fails if that is possible. Possibly add error info to the tree too.

[dreed-sd]

From the command line/VSCode it's not so bad, since the full error is in the log.

I came across this from running tests via command line in a github action. We have a lot of tests, thousands, so the summary at the end is absolutely critical or you're scrolling through a slowly paged log in github or downloading megabytes of text to start grepping in. I've patched our local copy of GUT just to get around this problem for now.

[bitwes]

Ahh, I hadn't thought of that. I've added the code you suggested for the message. I also added the line number in the test script where the error happened.

Given these tests:

extends GutTest

func test_forced_engine_error() -> void:
	OS.delay_usec(-10)
	pass_test('has forced engine error')


func test_with_two_forced_engine_error() -> void:
	OS.delay_usec(-10)
	OS.delay_usec(-11)
	pass_test('has forced engine error')


class TestInnerClassOutput:
	extends GutTest

	func test_forced_engine_error() -> void:
		OS.delay_usec(-10)
		pass_test('has forced engine error')

GUT now outputs:

test/output_tests/test_with_errors.gd
- test_forced_engine_error
    [Failed]:  Unexpected Errors:
    [1] <engine-0>Can't sleep for -10 microseconds. The delay provided must be greater than or equal to 0 microseconds.
        at: delay_usec (core/core_bind.cpp:607)
        at line: 4

- test_with_two_forced_engine_error
    [Failed]:  Unexpected Errors:
    [1] <engine-0>Can't sleep for -10 microseconds. The delay provided must be greater than or equal to 0 microseconds.
        at: delay_usec (core/core_bind.cpp:607)
        at line: 9
    [2] <engine-0>Can't sleep for -11 microseconds. The delay provided must be greater than or equal to 0 microseconds.
        at: delay_usec (core/core_bind.cpp:607)
        at line: 10


test/output_tests/test_with_errors.gd.TestInnerClassOutput
- test_forced_engine_error
    [Failed]:  Unexpected Errors:
    [1] <engine-0>Can't sleep for -10 microseconds. The delay provided must be greater than or equal to 0 microseconds.
        at: delay_usec (core/core_bind.cpp:607)
        at line: 18

If this is good enough for now, I'll merge it in.

I'm going to add an issue for future enhancements to the error tracking. I think adding the full stack trace to the summary is a good idea, but I'd like to be able to disable it. I can probably add additional error info into the JUnit XML export. In working through this, I've found some implementation details that should be addressed sooner rather than later as well.