CodeceptJS icon indicating copy to clipboard operation
CodeceptJS copied to clipboard

Block in Github action

Open Horsty80 opened this issue 1 year ago • 1 comments

When i run to all test (~70) in 4 workers, at the end, i get stuck with this error message

✖ "after all" hook: codeceptjs.afterSuite in "Homepage feature" in 0ms
  • CodeceptJS version: 3.6.2
  • NodeJS Version: 20
  • playwright: 1.43.0
  • allure-codeceptjs: 2.15.1
  • Configuration file:

    Playwright: {
      url: testConfig.url,
      show: false,
      locale: "en-EN",
      browser: 'chromium',
      chromium: {
        args: ['--auth-server-whitelist=""'],
      },
      ignoreHTTPSErrors: true,
      fullPageScreenshots: true,
      windowSize: '1920x1080',
      waitForAction: 250,
      waitForTimeout: 10000, 
      waitForNavigation: 'load',
      restart: 'context',
      keepCookies: false,
      keepBrowserState: false
    },

I have allready open here https://github.com/codeceptjs/CodeceptJS/issues/3640 an issue before, but no response and the probleme has gone, but it's here again :'(

Horsty80 avatar May 21 '24 15:05 Horsty80

This issue, append in local too but it's not on each run, so it's seems to be random...

I don't know how to fix this

Horsty80 avatar May 21 '24 15:05 Horsty80

I've worked on a reproductible repo, you can find here https://github.com/Horsty80/codeceptjs-debug

Working test

pnpm i
pnpm working

Throwing error in After/Before without try/catch

 pnpm error-1

Lead to error but the CI is not block

  4) Error 1 @error1
       "before each" hook: Before for "test something 6":
     Error: done() called multiple times in hook <Error 1 @error1 "before each" hook: Before for "test something 6"> of file /Users/cyril/Workspace/codeceptjs-debug/tests/error-1_test.ts
      at /Users/cyril/Workspace/codeceptjs-debug/node_modules/.pnpm/[email protected]_@[email protected]_@[email protected][email protected][email protected]/node_modules/codeceptjs/lib/scenario.js:156:55
      at runNextTicks (node:internal/process/task_queues:60:5)
      at processTimers (node:internal/timers:511:9)

  5) Error 1 @error1
       "before each" hook: Before for "test something 5":
     Uncaught Async error
      at Timeout._onTimeout (tests/error-1_test.ts:7:11)
      at listOnTimeout (node:internal/timers:573:17)
      at processTimers (node:internal/timers:514:7)

Throwing error in some random Scenario without try/catch

 pnpm error-2

Lead to mentioned error ✖ "after all" hook: codeceptjs.afterSuite in "Error 2 @error2" in 0ms But the CI is block and it's impossible to take back control.

-- FAILURES:

  1) Error 2 @error2
       "before each" hook: Before for "test something 5":
     Uncaught Async error
      at Timeout._onTimeout (tests/error-2_test.ts:16:11)
      at listOnTimeout (node:internal/timers:573:17)
      at processTimers (node:internal/timers:514:7)
  
  Scenario Steps:
  - I.amOnPage("https://www.google.com") at Context.<anonymous> (./tests/error-2_test.ts:4:5)
  
  
  Scenario Steps:
  - I.amOnPage("https://www.google.com") at Context.<anonymous> (./tests/error-2_test.ts:4:5)
  

  2) Error 2 @error2
       "before each" hook: Before for "test something 5":
     Error: done() called multiple times in hook <Error 2 @error2 "before each" hook: Before for "test something 5"> of file /Users/cyril/Workspace/codeceptjs-debug/tests/error-2_test.ts
      at /Users/cyril/Workspace/codeceptjs-debug/node_modules/.pnpm/[email protected]_@[email protected]_@[email protected][email protected][email protected]/node_modules/codeceptjs/lib/scenario.js:156:55


  FAIL  | 1 passed, 2 failed   // 2s
    --- STARTED "before each" hook: Before for "test something 6" ---
    I am on page "https://www.google.com"
    › [Browser:Info] Autofocus processing was blocked because a document already has a focused element.
    › [Browser:Info] Autofocus processing was blocked because a document already has a focused element.
    › [Browser:Error] Permissions policy violation: unload is not allowed in this document.
    › [Browser:Error] Permissions policy violation: unload is not allowed in this document.
    --- ENDED "before each" hook: Before for "test something 6" ---
    I see element button#W0wltc
    I click button#W0wltc
    --- ENDED "before each" hook: Before for "test something 7" ---
    I see element button#W0wltc
    I click button#W0wltc
    I dont see element button#W0wltc
[03]   ✔ test something 6 in 59ms
  ✔ test something 6 in 168ms
  test something 9
    I dont see element button#W0wltc
[01]   ✔ test something 7 in 177ms
  ✔ OK in 177ms

  OK  | 3 passed   // 3s
    --- STARTED "before each" hook: Before for "test something 9" ---
    I am on page "https://www.google.com"
    › [Browser:Info] Autofocus processing was blocked because a document already has a focused element.
    › [Browser:Error] Permissions policy violation: unload is not allowed in this document.
    --- ENDED "before each" hook: Before for "test something 9" ---
    I see element button#W0wltc
    I click button#W0wltc
    I dont see element button#W0wltc
[03]   ✔ test something 9 in 168ms
  ✔ OK in 168ms


-- FAILURES:
  ✖ "after all" hook: codeceptjs.afterSuite in "Error 2 @error2" in 0ms

Throwing error in some random Scenario with try/catch

 pnpm error-3

Lead to the same error as pnpm error-2 the CI / terminal is block and impossible to take back the control

Throwing error in Before with try/catch

 pnpm error-4

Lead to the same error as pnpm error-1, test failed, but we take back the control.

Horsty80 avatar May 23 '24 21:05 Horsty80

So my first conclusion are something in my test code throw an async error and it's not try/catch and Codecept can not handle it correctly. But on my workflow of test (not the linked repository) I use codeceptJs method, and I have remove all throw that I can find on my custom helper.

Tomorrow I will work on adding some try/catch on stuff I presume can lead to unhandled error, but is it possible that some error inside codeceptJs code can lead to unhandled error ?

Horsty80 avatar May 23 '24 21:05 Horsty80

🎉UPDATE

It's seems that if I remove retry: 3 in the codecept.conf.ts the "blocking" not happens anymore. I will try some retry configuration to check this clue

Horsty80 avatar May 23 '24 21:05 Horsty80

I invok @DavertMik 🙌 you have work on the global retry feature and maybe you can help me on it or how to find the root cause

Horsty80 avatar May 23 '24 22:05 Horsty80

Last test and last conclusion ^^

For codeceptjs: 3.4.1 is working ✅ for 3.5.0 is not working ❌

With the same config

After checking changelog, I've found the line that cause the issue from the fix here #3667

https://github.com/codeceptjs/CodeceptJS/pull/3667/files#diff-9c88056d70f40caa621cb9519252872211ec64f80a84fa1c127c1f98880a93b8R47

I've try to replace this code block

    if (Number.isInteger(+retryConfig)) {
       if (test.retries() === -1) test.retries(retryConfig);
       return;
     }

By this:

    if (Number.isInteger(+retryConfig)) {
       if (isNotSet(test.retries())) test.retries(retryConfig);
       return;
     }

I don't really understand what is in cause, but clearly the test.retries() === -1 cause this issue

Horsty80 avatar May 23 '24 23:05 Horsty80

... Wrong fixed, that is not the root cause of the issue. But strangely adding line of code here have impact on the blocking issue 🤔 even a console.log() inside the if achieve the same thing...

So I keep investigate ✌️

Horsty80 avatar May 24 '24 21:05 Horsty80

I think using a console.log inside of this force JavaScript to load this part of code. And thus import Suite from Mocha: https://github.com/Horsty80/CodeceptJS/blob/3c009e0759b3ddda7caa1984209fe248213553d2/lib/scenario.js#L175

test.retries is an inside method of Mocha: https://github.com/mochajs/mocha/blob/master/lib/suite.js#L129

to me, test.retries should not be undefined. Not sure where should be the root cause

andonary avatar May 27 '24 12:05 andonary

to me, test.retries should not be undefined. Not sure where should be the root cause

Yes it's test.retries is defined, just a wrong idea of the root cause for me ( that for i delete my PR) I'm keep investigate, but the code base of the lib and the project are difficult to understand

test.retries for Scenario and not Suite is defined here if i understand: https://github.com/mochajs/mocha/blob/master/lib/test.js#L75

Horsty80 avatar May 27 '24 13:05 Horsty80

Maybe link with #4197 ?

Horsty80 avatar May 28 '24 14:05 Horsty80

We patched the retryTo issue in 3.5.11 > https://codecept.io/changelog/#_3-5-11 and the stale issue is found by you from 3.5.0. So the issue should be somewhere else, I think.

kobenguyent avatar May 29 '24 06:05 kobenguyent

Ok so the issue ara around the retry and how promise rejection are handled i presume ?

Horsty80 avatar May 29 '24 07:05 Horsty80

adding more debug info

2024-05-29T07:46:29.650Z mocha:runner total number of failures: 2
  ✖ test something 3 in 81ms
    --- ENDED "after each" hook: After for "test something 3" ---
    --- STARTED "before each" hook: Before for "test something 3" ---
    I am on page "https://www.google.com"
2024-05-29T07:46:29.743Z mocha:runner uncaught(): got truthy exception Error: Async error
    at Timeout._onTimeout (/Users/t/Desktop/projects/codeceptjs-debug/tests/error-4_test.ts:8:13)
    at listOnTimeout (node:internal/timers:569:17)
    at processTimers (node:internal/timers:512:7)
  ✖ FAILED in 35ms
2024-05-29T07:46:29.743Z mocha:runner uncaught(): forcing Runnable to complete with Error
2024-05-29T07:46:29.743Z mocha:runner total number of failures: 3

       --- STARTED "after each" hook: After for "test something 3" ---
After hook
2024-05-29T07:46:29.834Z mocha:runner uncaught(): throwing after run has completed!
[03] Worker Error: Error: Async error
    at Timeout._onTimeout (/Users/t/Desktop/projects/codeceptjs-debug/tests/error-4_test.ts:8:13)
    at listOnTimeout (node:internal/timers:569:17)
    at processTimers (node:internal/timers:512:7)
2024-05-29T07:46:29.853Z mocha:runner uncaught(): throwing after run has completed!
[03] Worker Error: Error: Async error
    at Timeout._onTimeout (/Users/t/Desktop/projects/codeceptjs-debug/tests/error-4_test.ts:8:13)
    at listOnTimeout (node:internal/timers:569:17)
    at processTimers (node:internal/timers:512:7)
    › [Browser:Info] Autofocus processing was blocked because a document already has a focused element.
    › [Browser:Error] Permissions policy violation: unload is not allowed in this document.
    --- ENDED "after each" hook: After for "test something 3" ---
2024-05-29T07:46:30.429Z mocha:runner total number of failures: 4
  ✖ FAILED in 35ms

    --- ENDED "after each" hook: After for "test something 3" ---
2024-05-29T07:46:30.436Z mocha:runner _addEventListener(): adding for event error; 0 current listeners
2024-05-29T07:46:30.437Z mocha:runner runSuite(): running Working @working:

2024-05-29T07:46:30.437Z mocha:runner runSuite(): bailing
2024-05-29T07:46:30.437Z mocha:runner run(): root suite completed; emitting end
2024-05-29T07:46:30.442Z mocha:runner uncaught(): got truthy exception TypeError: Cannot read properties of undefined (reading 'stack')
    at /Users/t/Desktop/projects/codeceptjs-debug/node_modules/codeceptjs/lib/cli.js:189:25
    at Array.map (<anonymous>)
    at Cli.result (/Users/t/Desktop/projects/codeceptjs-debug/node_modules/codeceptjs/lib/cli.js:160:21)
    at Runner.emit (node:events:529:35)
    at Runner.emit (node:domain:489:12)
    at end (/Users/t/Desktop/projects/codeceptjs-debug/node_modules/mocha/lib/runner.js:1049:10)
    at /Users/t/Desktop/projects/codeceptjs-debug/node_modules/mocha/lib/runner.js:908:7
    at next (/Users/t/Desktop/projects/codeceptjs-debug/node_modules/mocha/lib/runner.js:485:14)
    at Immediate.<anonymous> (/Users/t/Desktop/projects/codeceptjs-debug/node_modules/mocha/lib/runner.js:570:5)
    at processImmediate (node:internal/timers:476:21)
2024-05-29T07:46:30.442Z mocha:runner uncaught(): forcing Runnable to complete with Error
2024-05-29T07:46:30.443Z mocha:runner total number of failures: 5
-- FAILURES:
  ✖ "after all" hook: codeceptjs.afterSuite in "Error 4 @error4" in 1ms
2024-05-29T07:46:30.569Z mocha:runner uncaught(): got truthy exception Error: Async error
    at Timeout._onTimeout (/Users/t/Desktop/projects/codeceptjs-debug/tests/error-4_test.ts:19:11)
    at listOnTimeout (node:internal/timers:569:17)
    at processTimers (node:internal/timers:512:7)
2024-05-29T07:46:30.569Z mocha:runner uncaught(): Runnable has already failed
2024-05-29T07:46:30.714Z mocha:runner uncaught(): got truthy exception Error: Async error
    at Timeout._onTimeout (/Users/t/Desktop/projects/codeceptjs-debug/tests/error-4_test.ts:8:13)
    at listOnTimeout (node:internal/timers:569:17)
    at processTimers (node:internal/timers:512:7)
2024-05-29T07:46:30.715Z mocha:runner uncaught(): Runnable has already failed
2024-05-29T07:46:30.748Z mocha:runner uncaught(): got truthy exception Error: Async error
    at Timeout._onTimeout (/Users/tDesktop/projects/codeceptjs-debug/tests/error-4_test.ts:19:11)
    at listOnTimeout (node:internal/timers:569:17)
    at processTimers (node:internal/timers:512:7)
2024-05-29T07:46:30.748Z mocha:runner uncaught(): Runnable has already failed

kobenguyent avatar May 29 '24 07:05 kobenguyent

Using the version 3.6.3-beta.2 doesn't change the behavior, i still have the blocked issue

-- FAILURES:
  ✖ "after all" hook: codeceptjs.afterSuite in "My custom test" in 1ms

Maybe that can help you, but i get a lot of allure report error like this mention that something wrong append from codeceptjs/lib/actor.js:146:11

       Something went wrong Error: Something went wrong
    at AllureReporter.debug (/e2e/node_modules/.pnpm/[email protected]/node_modules/allure-codeceptjs/src/index.ts:316:19)
    at AllureReporter.allureStepByCodeceptStep (/e2e/node_modules/.pnpm/[email protected]/node_modules/allure-codeceptjs/src/index.ts:127:12)
    at AllureReporter.stepFinished (/e2e/node_modules/.pnpm/[email protected]/node_modules/allure-codeceptjs/src/index.ts:289:29)
    at EventEmitter.emit (node:events:526:35)
    at EventEmitter.emit (node:domain:488:12)
    at Object.emit (/e2e/node_modules/.pnpm/[email protected][email protected]/node_modules/codeceptjs/lib/event.js:149:28)
    at /e2e/node_modules/.pnpm/[email protected][email protected]/node_modules/codeceptjs/lib/actor.js:146:11

Horsty80 avatar May 29 '24 12:05 Horsty80

hey @Horsty80 which allure report are you using? the legacy one or the one from allure team? Also if you disable the allure plugin, does your CI still stale?

kobenguyent avatar May 29 '24 12:05 kobenguyent

I use this one : https://www.npmjs.com/package/allure-codeceptjs I get:

  • allure-codeceptjs: 2.15.0
  • allure-commandline: 2.27.0

Before this new beta version, I have already try to remove allure but there are no impact on the issue. I can retry with the beta to be sure.

I pointing on this allure's error only because the stacktrace begin inside codeceptjs lib so maybe that can help to debug

Horsty80 avatar May 29 '24 12:05 Horsty80

well if that's possible, adding the DEBUG=* would provide us more info and perhaps we could learn something from there.

kobenguyent avatar May 29 '24 12:05 kobenguyent

So i've retry without allure, and i get the same behavior. I have start another test with DEBUG=* i hope i can have something that can help

Horsty80 avatar May 29 '24 13:05 Horsty80

well if that's possible, adding the DEBUG=* would provide us more info and perhaps we could learn something from there.

With debug, I have a tons of log to explore, but I see nothing strange or something can be useful Maybe you have something in mind that can help me to find the right log ?

Just to recap, I play 70 tests with run-worker command (with 4 or 6 workers), and I use plugin autoLogin and Retry + the Allure reporter

My CI is blocked each time, and even remove the retry didn't have the expected solution.

I don't know where to search but I can test what you propose, let me know

Horsty80 avatar May 29 '24 22:05 Horsty80

Out of curiosity, are you using the After/AfterSuite in your Scenario files?

I recall recently I got the issue (the process hangs) when using the hook like Before/After stuff like that. So the solution is moving the code from those hooks to a function and call that function in the scenario. Not a clean solution but at least it helped.

Before(() => {...}) -> preconditions() {...}

After(() => {...}) -> postconditions() {...}

Scenario('test', () => { preconditions(); ... postconditions(); })

kobenguyent avatar May 30 '24 05:05 kobenguyent

Out of curiosity, are you using the After/AfterSuite in your Scenario files?

I recall recently I got the issue (the process hangs) when using the hook like Before/After stuff like that. So the solution is moving the code from those hooks to a function and call that function in the scenario. Not a clean solution but at least it helped.

Before(() => {...}) -> preconditions() {...}

After(() => {...}) -> postconditions() {...}

Scenario('test', () => { preconditions(); ... postconditions(); })

Yes i have that before, but i have remove all before/after from scenario files And has you can see in my code that i share here https://github.com/Horsty80/codeceptjs-debug https://github.com/Horsty80/codeceptjs-debug/blob/main/tests/error-2_test.ts the Before is only a I.amOnPage

Horsty80 avatar May 30 '24 07:05 Horsty80

https://github.com/Horsty80/codeceptjs-debug/blob/main/tests/error-2_test.ts#L3

maybe redundant async cause some side effects?

kobenguyent avatar May 30 '24 08:05 kobenguyent

I will update with a new test file without the befare and test that but i think i get the same behavior

Horsty80 avatar May 30 '24 09:05 Horsty80

@kobenguyent i still have the stale process issue with the 3.6.3-beta.2

The debug show me some much logs that can not exploit them

Horsty80 avatar Jun 03 '24 12:06 Horsty80

Did you spot any unusual with your After block?

kobenguyent avatar Jun 03 '24 14:06 kobenguyent