Stage actor initialization suppresses original exception message #1823

1MateuszKruk · 2023-07-28T12:45:13Z

Hi,
When I was working on Actor set up, I have encountered few errors with external clients, but as they were inside Abilitiy initialization, I only get an error like this:
ConfigurationError: TestActor encountered a problem when preparing actor "Alice" for stage <stack trace>
The original exception message gets lost, making debugging it less convenient.

How to reproduce:

in any prepare method or in any Ability initialization inside a class implementing a Cast interface, throw an error with a message of your choice f. ex
throw new Error("custom error message")
check error logs
the error should resemble that stated above

The text was updated successfully, but these errors were encountered:

jan-molak · 2023-07-28T22:31:42Z

Hey @1MateuszKruk, I tried to reproduce it in the following unit test:

serenity-js/packages/core/spec/stage/Stage.spec.ts

Lines 353 to 364 in 2876a74

    
           it('complains if the Cast throws an error during actor instantiation', () => { 
        
               const 
        
                   name   = 'Alice', 
        
                   actors: Cast = { 
        
                       prepare: (actor: Actor) => { throw new Error(`I'm not working today`); }, 
        
                   }, 
        
                   stage  = new Stage(actors, stageManager as unknown as StageManager, new ErrorFactory(), clock, interactionTimeout); 
        
               expect(() => { 
        
                   stage.actor(name); 
        
               }).to.throw(ConfigurationError, `Cast encountered a problem when preparing actor "${ name }" for stage`); 
        
           });

It looks like the stack trace of the cause is correctly concatenated with the wrapping error:

ConfigurationError: Cast encountered a problem when preparing actor "Alice" for stage
    at Stage.actor (/Users/jan/Projects/serenity-js/serenity-js/packages/core/src/stage/Stage.ts:118:23)
    at /Users/jan/Projects/serenity-js/serenity-js/packages/core/spec/stage/Stage.spec.ts:362:23
    at Proxy.assertThrows (/Users/jan/Projects/serenity-js/serenity-js/node_modules/chai/lib/chai/core/assertions.js:2648:7)
    at Proxy.methodWrapper (/Users/jan/Projects/serenity-js/serenity-js/node_modules/chai/lib/chai/utils/addMethod.js:57:25)
    at doAsserterAsyncAndAddThen (/Users/jan/Projects/serenity-js/serenity-js/node_modules/chai-as-promised/lib/chai-as-promised.js:289:22)
    at Proxy.<anonymous> (/Users/jan/Projects/serenity-js/serenity-js/node_modules/chai-as-promised/lib/chai-as-promised.js:255:20)
    at Proxy.overwritingMethodWrapper (/Users/jan/Projects/serenity-js/serenity-js/node_modules/chai/lib/chai/utils/overwriteMethod.js:78:33)
    at Context.<anonymous> (/Users/jan/Projects/serenity-js/serenity-js/packages/core/spec/stage/Stage.spec.ts:364:21)
    at callFn (/Users/jan/Projects/serenity-js/serenity-js/packages/core/node_modules/mocha/lib/runnable.js:366:21)
    at Test.Runnable.run (/Users/jan/Projects/serenity-js/serenity-js/packages/core/node_modules/mocha/lib/runnable.js:354:5)
    at Runner.runTest (/Users/jan/Projects/serenity-js/serenity-js/packages/core/node_modules/mocha/lib/runner.js:666:10)
    at /Users/jan/Projects/serenity-js/serenity-js/packages/core/node_modules/mocha/lib/runner.js:789:12
    at next (/Users/jan/Projects/serenity-js/serenity-js/packages/core/node_modules/mocha/lib/runner.js:581:14)
    at /Users/jan/Projects/serenity-js/serenity-js/packages/core/node_modules/mocha/lib/runner.js:591:7
    at next (/Users/jan/Projects/serenity-js/serenity-js/packages/core/node_modules/mocha/lib/runner.js:474:14)
    at Immediate._onImmediate (/Users/jan/Projects/serenity-js/serenity-js/packages/core/node_modules/mocha/lib/runner.js:559:5)
    at processImmediate (node:internal/timers:476:21)
Caused by: Error: I'm not working today
    at Object.prepare (/Users/jan/Projects/serenity-js/serenity-js/packages/core/spec/stage/Stage.spec.ts:357:56)
    at Stage.actor (/Users/jan/Projects/serenity-js/serenity-js/packages/core/src/stage/Stage.ts:112:35)
    at /Users/jan/Projects/serenity-js/serenity-js/packages/core/spec/stage/Stage.spec.ts:362:23
    at Proxy.assertThrows (/Users/jan/Projects/serenity-js/serenity-js/node_modules/chai/lib/chai/core/assertions.js:2648:7)
    at Proxy.methodWrapper (/Users/jan/Projects/serenity-js/serenity-js/node_modules/chai/lib/chai/utils/addMethod.js:57:25)
    at doAsserterAsyncAndAddThen (/Users/jan/Projects/serenity-js/serenity-js/node_modules/chai-as-promised/lib/chai-as-promised.js:289:22)
    at Proxy.<anonymous> (/Users/jan/Projects/serenity-js/serenity-js/node_modules/chai-as-promised/lib/chai-as-promised.js:255:20)
    at Proxy.overwritingMethodWrapper (/Users/jan/Projects/serenity-js/serenity-js/node_modules/chai/lib/chai/utils/overwriteMethod.js:78:33)
    at Context.<anonymous> (/Users/jan/Projects/serenity-js/serenity-js/packages/core/spec/stage/Stage.spec.ts:364:21)
    at callFn (/Users/jan/Projects/serenity-js/serenity-js/packages/core/node_modules/mocha/lib/runnable.js:366:21)
    at Test.Runnable.run (/Users/jan/Projects/serenity-js/serenity-js/packages/core/node_modules/mocha/lib/runnable.js:354:5)
    at Runner.runTest (/Users/jan/Projects/serenity-js/serenity-js/packages/core/node_modules/mocha/lib/runner.js:666:10)
    at /Users/jan/Projects/serenity-js/serenity-js/packages/core/node_modules/mocha/lib/runner.js:789:12
    at next (/Users/jan/Projects/serenity-js/serenity-js/packages/core/node_modules/mocha/lib/runner.js:581:14)
    at /Users/jan/Projects/serenity-js/serenity-js/packages/core/node_modules/mocha/lib/runner.js:591:7
    at next (/Users/jan/Projects/serenity-js/serenity-js/packages/core/node_modules/mocha/lib/runner.js:474:14)
    at Immediate._onImmediate (/Users/jan/Projects/serenity-js/serenity-js/packages/core/node_modules/mocha/lib/runner.js:559:5)
    at processImmediate (node:internal/timers:476:21)

However, if we know that the cause is correctly attached, but you don't see it, it most likely means that the cause message gets swallowed somewhere on the way.

Would you be able to reproduce the error using one of the Serenity/JS project templates that most closely resembles your setup? Let's get to the bottom of this!

jbpros · 2023-09-01T20:23:08Z

Hey -- I run into the same issue. I'm using Playwright and I wondered if that could play a role in the swallowing of the original exception. @1MateuszKruk are you, by any chance, also using Playwright as a test runner?

jan-molak · 2023-09-02T21:10:31Z

@jbpros - you're right, nice catch! It looks like error serialisation in Playwright Test removes information about the nested error. It's the serialisation that happens when Playwright Test passes the error stack trace from the worker to the main process, I think.

I managed to reproduce it in a test, now we just need to figure out why that happens and how to fix it :-)

jbpros · 2023-09-02T21:23:47Z

Haha! That was quite a wild guess, tbh. Is Serenity using the Error#cause property? If so, is that what's getting lost by the Playwright serialiser?

jan-molak · 2023-09-02T21:49:05Z

Is Serenity using the Error#cause property?

Hmm, not the Node 16 spec; Serenity/JS nested errors were introduced back in Node 12 times, so they should be modernised to use { cause: error } option.

Even with that though, I'm not sure if Playwright Test supports error.cause either since they're relatively new... Let's check.

jan-molak · 2023-09-02T22:24:21Z

OK, so it looks like the issue comes down to Playwright Test removing anything from the stack trace that's not a reference to a file system location:

Error retrieved from the test has the cause information in the stack trace: https://github.com/microsoft/playwright/blob/v1.37.1/packages/playwright-test/src/worker/testInfo.ts#L236-L238
but then filteredStackTrace removes this information:
https://github.com/microsoft/playwright/blob/v1.37.1/packages/playwright-test/src/util.ts#L32-L49
because the nested error message attached to the stack doesn't is not a stack frame
https://github.com/microsoft/playwright/blob/v1.37.1/packages/playwright-test/src/util.ts#L51-L62 and https://github.com/microsoft/playwright/blob/v1.37.1/packages/playwright-core/src/utilsBundle.ts#L50-L52

So the next question is: Does Playwright support Error#cause property?

jan-molak · 2023-09-02T22:33:17Z

And the answer is: no, Playwright doesn't support Error#cause.

When I modified the test as follows:

import { describe, it } from '@serenity-js/playwright-test';

describe('Playwright Test reporting', () => {

    describe('A scenario', () => {

        it('fails with a nested error', () => {
            try {
                throw new Error('Example nested error');
            }
            catch (error) {
                throw new Error('Example configuration error', { cause: error })
            }
        });
    });
});

I still got:

[out]     Error: Example configuration error
[out] 
[out]       12 |             catch (error) {
[out]       13 |                 // throw new ConfigurationError('Example configuration error', error)
[out]     > 14 |                 throw new Error('Example configuration error', { cause: error })
[out]          |                       ^
[out]       15 |             }
[out]       16 |         });
[out]       17 |     });
[out] 
[out]         at /Users/jan/Projects/serenity-js/serenity-js/integration/playwright-test/examples/failing/failing-serenity-js-configuration-error.spec.ts:14:23

So, there is no information about the nested error.

I think an optimal solution to this would be for:

Playwright Core and Playwright Test to respect Error#cause property
Serenity/JS to also use Error#cause and something like sindresorhus/serialize-error for internal serialisation/deserialisation

I think it might be a significant change on the Playwright side since they rely heavily on embedding additional information like Playwright zones in the stack trace. It's worth asking, though.

If that doesn't work, Serenity/JS could merge error messages from nested errors and embed them in the top-level error message.

jan-molak added @serenity-js/playwright-test Serenity/JS reporter and test APIs for Playwright Test bug labels Sep 2, 2023

jan-molak added a commit that referenced this issue Sep 2, 2023

test(playwright-test): example test to reproduce #1823

212443e

jan-molak mentioned this issue Sep 2, 2023

fix(playwright-test): nested error handling #1897

Draft

jan-molak added a commit to jan-molak/playwright-error-cause-serialization that referenced this issue Sep 2, 2023

Repro of serenity-js/serenity-js#1823

68c741b

jan-molak mentioned this issue Sep 2, 2023

[BUG] Playwright should report Error#cause microsoft/playwright#26848

Open

1 task

jan-molak self-assigned this Sep 24, 2023

jan-molak mentioned this issue Dec 1, 2023

feat(core): nested error cause is now added to the main error message #2101

Merged

jan-molak closed this as completed in 815c8ce Dec 2, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Stage actor initialization suppresses original exception message #1823

Stage actor initialization suppresses original exception message #1823

1MateuszKruk commented Jul 28, 2023

jan-molak commented Jul 28, 2023

jbpros commented Sep 1, 2023

jan-molak commented Sep 2, 2023

jbpros commented Sep 2, 2023

jan-molak commented Sep 2, 2023 •

edited

jan-molak commented Sep 2, 2023 •

edited

jan-molak commented Sep 2, 2023 •

edited

Stage actor initialization suppresses original exception message #1823

Stage actor initialization suppresses original exception message #1823

Comments

1MateuszKruk commented Jul 28, 2023

jan-molak commented Jul 28, 2023

jbpros commented Sep 1, 2023

jan-molak commented Sep 2, 2023

jbpros commented Sep 2, 2023

jan-molak commented Sep 2, 2023 • edited

jan-molak commented Sep 2, 2023 • edited

jan-molak commented Sep 2, 2023 • edited

jan-molak commented Sep 2, 2023 •

edited

jan-molak commented Sep 2, 2023 •

edited

jan-molak commented Sep 2, 2023 •

edited