Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Since Codecept 3.6.9, our test that looks for a date time doesn't find it (but it's there) #4632

Open
a-roberts opened this issue Dec 10, 2024 · 16 comments

Comments

@a-roberts
Copy link

Hi, we're seeing this issue and we've tried pinning to older versions - 3.6.7 is OK.

What are you trying to achieve?

We have a test that's been passing up until now and does so with 3.6.7.

I can't use 3.6.8 because of Error: Cannot find module 'invisi-data' (I noticed a hotfix around this in the commits).

It started failing today (it could have failed sooner, we only noticed it today).

What do you get instead?

The following (I've noticed the UI here says 3.6.2, but when I do an npm list I am on 3.6.7, 3.6.8, or 3.6.9 depending on the test I am doing - we want to be on the latest and tried downgrading twice and as part of that verified 3.6.7 is ok).

image

This looks to me like it finds our text and then says it hasn't...

Provide console output if related. Use --verbose mode for more details.

1) User Logs
       It renders a User Log table:
     Text "2024-09-05 04:14:32.000" was not found on page after 1 sec.
      at Playwright.waitForText (node_modules/codeceptjs/lib/helper/Playwright.js:2854:26)
      at async Test.<anonymous> (codecept/user-logs.spec.js:39:3)
  
  

  2) User Logs
       It renders a new User Log table:
     Text "2024-09-06 10:14:50.000" was not found on page after 1 sec.
      at Playwright.waitForText (node_modules/codeceptjs/lib/helper/Playwright.js:2854:26)
      at runNextTicks (node:internal/process/task_queues:60:5)
      at process.processTimers (node:internal/timers:509:9)

Provide test source code if related
Sorry - I don't have a minimal reproduce yet - we basically have a simple logging page and we're looking for an event time on it in a row

Scenario('It renders a User Log table', async ({ I }) => {
  I.amOnPage('http://localhost:5057/iframe.html?args=&id=demo-logs-page--renders-correctly&viewMode=story')

  I.waitForText('Logs', 10)

  await sleep(10000)

  // Check there is a table
  I.seeElement('.IntegrationDataTable')
  I.seeNumberOfVisibleElements('.UserLogsPage__Table tbody tr[data-parent-row="true"]', 14)
  I.see('14 of 10000')

  // Check column headings
  I.see('Event time (UTC)')
  I.see('Message')
  I.see('Transaction ID')
  I.see('Flow ID')
  I.see('Log level')

  // Check first row
  let firstRow = locate('.UserLogsPage__Table tbody tr[data-parent-row="true"]').first()
  console.log('first', firstRow)

  await within(firstRow, () => {
    I.waitForText('2024-09-05 04:14:32.000') <---------- see here
  })

Details

  • CodeceptJS version: 3.6.9
  • NodeJS Version: we've tried with Node.js 22.9.0 and 18.20.4
  • Operating System: I'm on Mac OSX
  • puppeteer || webdriverio || testcafe version (if related)

We are using Playwright 1.49.1

  • Configuration file:
exports.config = {
  tests: './codecept/*.spec.js',
  output: './codecept/screenshots',
  retry: 2,
  helpers: {
    Playwright: {
      url: 'http://localhost:9010',
      show: false,
      browser: 'chromium',
      pressKeyDelay: 2,
      waitForAction: 5000
    }
  },
  bootstrap: null,
  mocha: {},
  name: 'ui-logging',
  plugins: {
    pauseOnFail: {},
    retryFailedStep: {
      enabled: true
    },
    tryTo: {
      enabled: true
    },
    screenshotOnFail: {
      enabled: true
    },
    customLocator: {
      enabled: true,
      attribute: 'data-testid'
    }
  }
}
@kobenguyent
Copy link
Collaborator

hi @a-roberts I'm doubt if the issue is due to those PRs as they touch waitFor* and within

#4528
#4557

@kobenguyent
Copy link
Collaborator

tried to reproduce with this html

<!DOCTYPE html>
<html lang="en">
<head>
    <meta charset="UTF-8">
    <meta name="viewport" content="width=device-width, initial-scale=1.0">
    <title>User Logs Table</title>
    <style>
        .UserLogsPage__Table {
            width: 100%;
            border-collapse: collapse;
        }

        .UserLogsPage__Table th, .UserLogsPage__Table td {
            border: 1px solid #ddd;
            padding: 8px;
        }

        .UserLogsPage__Table th {
            background-color: #f4f4f4;
            text-align: left;
        }
    </style>
</head>
<body>

<?php
$data = [
    ["timestamp" => "2024-09-05 04:14:32.000", "name" => "Test"],
    ["timestamp" => "2024-09-05 04:15:45.000", "name" => "Test"]
];
?>

<table class="UserLogsPage__Table">
    <thead>
        <tr>
            <th>Timestamp</th>
            <th>Name</th>
        </tr>
    </thead>
    <tbody>
        <?php foreach ($data as $row): ?>
        <tr data-parent-row="true">
            <td><?php echo $row['timestamp']; ?></td>
            <td><?php echo $row['name']; ?></td>
        </tr>
        <?php endforeach; ?>
    </tbody>
</table>

</body>
</html>

but it works just fine for me.

Screenshot 2024-12-11 at 12 05 44

@a-roberts
Copy link
Author

@kobenguyent
Thank you for taking a look and trying for the reproduce, it's really appreciated

We are using a Carbon DataGrid so it's entirely possible the locator is now different or the locator is the same but under the covers it's just not picking up the element OK now. Or rather, it finds it (based on my screenshot) but then somehow fails the match. Not sure.

I'll try to spend some time looking into this later to find a minimal reproduce. I am sure under the covers there is a regular table in there so it should be OK.

@a-roberts
Copy link
Author

I have:

  • added code in node_modules/codeceptjs/lib/helper/Playwright.js so we retry five times every 5 second. no good, suggesting not a "timing thing"

  • confirmed we enter this code in lib/helper/playwright.js:

const _contextObject = this.frame ? this.frame : contextObject
      let count = 0
      do {
        waiter = await _contextObject
          .locator(`:has-text(${JSON.stringify(text)})`)
          .first()
          .isVisible()
        if (waiter) break
        await this.wait(1)
        count += 1000
      } while (count <= waitTimeout)

      if (!waiter) throw new Error(`${errorMessage}`)
  • confirmed there's never a waiter (obvious when you look at the code as that's the one throwing the error)

If I inspect the value of _contextObject and also this.frame while I'm at it, it is:

_contextObject: {"_type":"Page","_guid":"page@a4a6cdfa1f4af9fa1b39cbbd8766ef17"}
this.frame: null

(not that useful to help our debugging)

This is on Codecept 3.6.9 where the problem is and if I downgrade to 3.6.7 where it works and look at the same values, I don't gain any useful insights. There aren't enough things i can inspect in this helper file alone to help me debug what's going on.

I'm going to try and get the simplest reproduce for you and will push to my github.

@kobenguyent
Copy link
Collaborator

I have:

  • added code in node_modules/codeceptjs/lib/helper/Playwright.js so we retry five times every 5 second. no good, suggesting not a "timing thing"
  • confirmed we enter this code in lib/helper/playwright.js:
const _contextObject = this.frame ? this.frame : contextObject
      let count = 0
      do {
        waiter = await _contextObject
          .locator(`:has-text(${JSON.stringify(text)})`)
          .first()
          .isVisible()
        if (waiter) break
        await this.wait(1)
        count += 1000
      } while (count <= waitTimeout)

      if (!waiter) throw new Error(`${errorMessage}`)
  • confirmed there's never a waiter (obvious when you look at the code as that's the one throwing the error)

If I inspect the value of _contextObject and also this.frame while I'm at it, it is:

_contextObject: {"_type":"Page","_guid":"page@a4a6cdfa1f4af9fa1b39cbbd8766ef17"}
this.frame: null

(not that useful to help our debugging)

This is on Codecept 3.6.9 where the problem is and if I downgrade to 3.6.7 where it works and look at the same values, I don't gain any useful insights. There aren't enough things i can inspect in this helper file alone to help me debug what's going on.

I'm going to try and get the simplest reproduce for you and will push to my github.

Thanks for trying it out. May you give this a try on your local?

async waitForText(text, sec = null, context = null) {
  if (typeof text !== 'string') throw new TypeError('Parameter "text" must be a string');
  const waitTimeout = sec ? sec * 1000 : this.options.waitForTimeout;
  const errorMessage = `Text "${text}" was not found on page after ${waitTimeout / 1000} sec.`;
  const contextObject = await this._getContext();
  const _contextObject = this.frame ? this.frame : contextObject;

  try {
    if (context) {
      const locator = new Locator(context, 'css');
      const locatorQuery = locator.isCustom()
        ? `${locator.type}=${locator.value}`
        : locator.simplify();

      if (!locator.isXPath()) {
        await contextObject
          .locator(`${locatorQuery} >> text=${text}`)
          .first()
          .waitFor({ timeout: waitTimeout, state: 'visible' });
      } else {
        await contextObject.waitForFunction(
          ([locator, text, xpathFn]) => {
            const el = xpathFn(null, locator);
            return el.length && el[0].innerText.includes(text);
          },
          [locator.value, text, $XPath],
          { timeout: waitTimeout }
        );
      }
    } else {
      const startTime = Date.now();
      let waiter;
      do {
        waiter = await _contextObject
          .locator(`:has-text(${JSON.stringify(text)})`)
          .first()
          .isVisible();
        if (waiter) break;
        await this.wait(1);
      } while (Date.now() - startTime <= waitTimeout);

      if (!waiter) throw new Error(errorMessage);
    }
  } catch (e) {
    throw new Error(`${errorMessage}\nDetails: ${e.message}`);
  }
}

@a-roberts
Copy link
Author

^^ that failed too unfortunately

  1) User Logs
       It renders a User Log table:
     Error: Text "2024-09-05 04:14:32.000" was not found on page after 1 sec.
Details: Text "2024-09-05 04:14:32.000" was not found on page after 1 sec.
      at Playwright.waitForText (node_modules/codeceptjs/lib/helper/Playwright.js:2847:13)
  
  

  2) User Logs
       It renders a new User Log table:
     Error: Text "2024-09-06 10:14:50.000" was not found on page after 1 sec.
Details: Text "2024-09-06 10:14:50.000" was not found on page after 1 sec.
      at Playwright.waitForText (node_modules/codeceptjs/lib/helper/Playwright.js:2847:13)

If I play with these lines

  waiter = await _contextObject
            .locator(`:has-text(${JSON.stringify(text)})`)
            .first()
            .isVisible();

I removed .first() and get this output which may offer some clues

  1) User Logs
       It renders a User Log table:
     Text "Logs" was not found on page after 5 sec.
Details: locator.isVisible: Error: strict mode violation: locator(':has-text("Logs")') resolved to 17 elements:
    1) <html lang="en">…</html> aka locator('html')
    2) <body class="sb-main-fullscreen sb-show-main">…</body> aka locator('body')
    3) <div id="storybook-root">…</div> aka locator('#storybook-root')
    4) <div>…</div> aka locator('div').filter({ hasText: 'LogsSearch logs on this' }).nth(1)
    5) <div class="UserLogsPage">…</div> aka locator('div').filter({ hasText: 'LogsSearch logs on this' }).nth(2)
    6) <div class="UserLogsPage__header">…</div> aka getByText('LogsSearch logs on this')
    7) <h2 class="cds--modal-header__heading">Logs</h2> aka getByRole('heading', { name: 'Logs' })
    8) <div class="cds--btn-set">…</div> aka getByText('Search logs on this page3Build a query to filter logsExport displayed')
    9) <span class="cds--popover-container cds--popover--caret cds--popover--high-contrast cds--popover--top cds--tooltip cds--icon-tooltip">…</span> aka locator('span').filter({ hasText: 'Search logs on this page' }).first()
    10) <span role="tooltip" id="tooltip-:r0:" aria-hidden="true" class="cds--popover">…</span> aka locator('span').filter({ hasText: 'Search logs on this page' }).nth(1)
    ...

Call log:
    - checking visibility of locator(':has-text("Logs")')

I would need more rows though to see if the HTML has my row with its data in. Do we have an equivalent of screen.debug we could use here?

@kobenguyent
Copy link
Collaborator

@a-roberts is it possible to print out the await _contextObject.locator(:has-text(${JSON.stringify(text)}))? just curious if the correct locator is used here.

@a-roberts
Copy link
Author

await _contextObject.locator(:has-text(${JSON.stringify(text)}))?

Yep, so if I put it it in the else

  } else {
        const startTime = Date.now();
        let waiter;
        do {
          const debugWaiter = await _contextObject
          .locator(`:has-text(${JSON.stringify(text)})`)
          console.log('debugWaiter: ' + JSON.stringify(debugWaiter)) <----- see here
          
          waiter = await _contextObject
            .locator(`:has-text(${JSON.stringify(text)})`)
            .first()
            .isVisible();
          if (waiter) break;
          await this.wait(1);
        } while (Date.now() - startTime <= waitTimeout);
  
        if (!waiter) throw new Error(errorMessage);
      }
    } catch (e) {
      throw new Error(`${errorMessage}\nDetails: ${e.message}`);
    }

I get this output on 3.6.9:

debugWaiter: {"_frame":{"_type":"Frame","_guid":"frame@70d5995d3d8faf99e053290a5e08ee18"},"_selector":"xpath=(//*[@id = 'logTable']//tbody//tr)[position()=1] >> nth=0 >> :has-text(\"2024-09-06 10:14:50.000\")"}

If I do the same experiment on 3.6.6:

debugWaiter: {"_frame":{"_type":"Frame","_guid":"frame@f5099b5684cdf741d30e38e12fdb4e30"},"_selector":":has-text(\"2024-09-05 04:14:32.000\")"}

@kobenguyent
Copy link
Collaborator

await _contextObject.locator(:has-text(${JSON.stringify(text)}))?

Yep, so if I put it it in the else

  } else {
        const startTime = Date.now();
        let waiter;
        do {
          const debugWaiter = await _contextObject
          .locator(`:has-text(${JSON.stringify(text)})`)
          console.log('debugWaiter: ' + JSON.stringify(debugWaiter)) <----- see here
          
          waiter = await _contextObject
            .locator(`:has-text(${JSON.stringify(text)})`)
            .first()
            .isVisible();
          if (waiter) break;
          await this.wait(1);
        } while (Date.now() - startTime <= waitTimeout);
  
        if (!waiter) throw new Error(errorMessage);
      }
    } catch (e) {
      throw new Error(`${errorMessage}\nDetails: ${e.message}`);
    }

I get this output on 3.6.9:

debugWaiter: {"_frame":{"_type":"Frame","_guid":"frame@70d5995d3d8faf99e053290a5e08ee18"},"_selector":"xpath=(//*[@id = 'logTable']//tbody//tr)[position()=1] >> nth=0 >> :has-text(\"2024-09-06 10:14:50.000\")"}

If I do the same experiment on 3.6.6:

debugWaiter: {"_frame":{"_type":"Frame","_guid":"frame@f5099b5684cdf741d30e38e12fdb4e30"},"_selector":":has-text(\"2024-09-05 04:14:32.000\")"}

Thank you! Just noticed some difference here. On my local, it's

locator('xpath=(//*[@class and contains(concat(\' \', normalize-space(@class), \' \'), \' UserLogsPage__Table \')]//tbody//tr[@data-parent-row = \'true\'])[position()=1]').first().locator(':has-text("2024-09-05 04:14:32.000")').first()

so your table is inside a frame.

@a-roberts
Copy link
Author

a-roberts commented Dec 11, 2024

so your table is inside a frame.

Hmm it always has been*, we've been using Codecept for months, if not years, across our project (to great success so thank you).

I wonder if we now need to provide some more information to the locator?
But it feels wrong to have to to do that inside of a patch version change (3.6.7 to 3.6.9) indicating that the behaviour is now subtly different and I would consider that a bug - what do you think?

*I've just realised I don't know what a frame is in this context - what I'd like to say is instead is...we haven't changed our code...

Edit 2: I wonder if we were always relying on unintended behaviour that has since been fixed...

@kobenguyent
Copy link
Collaborator

so your table is inside a frame.

Hmm it always has been*, we've been using Codecept for months, if not years, across our project (to great success so thank you).

I wonder if we now need to provide some more information to the locator? But it feels wrong to have to to do that inside of a patch version change (3.6.7 to 3.6.9) indicating that the behaviour is now subtly different and I would consider that a bug - what do you think?

*I've just realised I don't know what a frame is in this context - what I'd like to say is instead is...we haven't changed our code...

Edit 2: I wonder if we were always relying on unintended behaviour that has since been fixed...

I'd think that if you could provide a sample repo where we could try to reproduce and debug from there. It'll be great start point.

@kobenguyent
Copy link
Collaborator

I tried to switch to iframe and it works. Just curious if you also need to switch to that frame?

    I am on page "http://127.0.0.1:8000/iframe"
    › [Browser:Error] Failed to load resource: the server responded with a status of 404 (Not Found)
    I switch to "iframe"
    Within "{"type":"xpath","output":null,"strict":true,"locator":{"xpath":"(//*[@class and contains(concat(' ', normalize-space(@class), ' '), ' UserLogsPage__Table ')]//tbody//tr[@data-parent-row = 'true'])[position()=1]"},"value":"(//*[@class and contains(concat(' ', normalize-space(@class), ' '), ' UserLogsPage__Table ')]//tbody//tr[@data-parent-row = 'true'])[position()=1]"}" ""
      I wait for text "2024-09-05 04:14:32.000", 1
locator('iframe').contentFrame().locator(':has-text("2024-09-05 04:14:32.000")').first()
  ✔ OK in 289ms


  OK  | 1 passed   // 2s

@a-roberts
Copy link
Author

Scenario('It renders a User Log table', async ({ I }) => {
  I.amOnPage('http://localhost:5057/iframe.html?args=&id=demo-logs-page--renders-correctly&viewMode=story') <--------

  I.waitForText('Logs', 5)

  await sleep(5000)

  // Check there is a table
  I.seeElement('.IntegrationDataTable')
  I.seeNumberOfVisibleElements('.UserLogsPage__Table tbody tr[data-parent-row="true"]', 14)
  I.see('14 of 10000')

  // Check column headings
  I.see('Event time (UTC)')
  I.see('Message')
  I.see('Transaction ID')
  I.see('Flow ID')
  I.see('Log level')

  // Check first row
  let firstRow = locate('.UserLogsPage__Table tbody tr[data-parent-row="true"]') <----------------
  await within(firstRow, () => {
    I.waitForText('2024-09-05 04:14:32.000')
    I.waitForText('appconnect: read the configurations default-switch-server')
    I.waitForText('5523yhy6-1662-11e8-afc4-f58041344r3r')
    I.waitForText('audit')
  })

Hmm, am I not already on an iframe though from the i.amOnPage. check? Do you think I need to change the locate part now? I don't know enough about the frame versus iframe you're mentioning although it feels like I should....

@kobenguyent
Copy link
Collaborator

Scenario('It renders a User Log table', async ({ I }) => {
  I.amOnPage('http://localhost:5057/iframe.html?args=&id=demo-logs-page--renders-correctly&viewMode=story') <--------

  I.waitForText('Logs', 5)

  await sleep(5000)

  // Check there is a table
  I.seeElement('.IntegrationDataTable')
  I.seeNumberOfVisibleElements('.UserLogsPage__Table tbody tr[data-parent-row="true"]', 14)
  I.see('14 of 10000')

  // Check column headings
  I.see('Event time (UTC)')
  I.see('Message')
  I.see('Transaction ID')
  I.see('Flow ID')
  I.see('Log level')

  // Check first row
  let firstRow = locate('.UserLogsPage__Table tbody tr[data-parent-row="true"]') <----------------
  await within(firstRow, () => {
    I.waitForText('2024-09-05 04:14:32.000')
    I.waitForText('appconnect: read the configurations default-switch-server')
    I.waitForText('5523yhy6-1662-11e8-afc4-f58041344r3r')
    I.waitForText('audit')
  })

Hmm, am I not already on an iframe though from the i.amOnPage. check? Do you think I need to change the locate part now? I don't know enough about the frame versus iframe you're mentioning although it feels like I should....

I tried to simulate the iframe to load the table inside. if I switch to iframe, it works.

Scenario.only('jkljkljlk', async ({ I }) => {
  I.amOnPage('http://127.0.0.1:8000/iframe')

  I.switchTo('iframe')
  // Check first row
  let firstRow = locate('.UserLogsPage__Table tbody tr[data-parent-row="true"]').first()
  console.log('first', firstRow)

   await within(firstRow, () => {
    I.waitForText('2024-09-05 04:14:32.000', 1)
  })
});

If I don't switch to iframe, I got the error.

    I am on page "http://127.0.0.1:8000/iframe"
    › [Browser:Error] Failed to load resource: the server responded with a status of 404 (Not Found)
    Within "{"type":"xpath","output":null,"strict":true,"locator":{"xpath":"(//*[@class and contains(concat(' ', normalize-space(@class), ' '), ' UserLogsPage__Table ')]//tbody//tr[@data-parent-row = 'true'])[position()=1]"},"value":"(//*[@class and contains(concat(' ', normalize-space(@class), ' '), ' UserLogsPage__Table ')]//tbody//tr[@data-parent-row = 'true'])[position()=1]"}" ""
      I wait for text "2024-09-05 04:14:32.000", 1
locator('xpath=(//*[@class and contains(concat(\' \', normalize-space(@class), \' \'), \' UserLogsPage__Table \')]//tbody//tr[@data-parent-row = \'true\'])[position()=1]').first().locator(':has-text("2024-09-05 04:14:32.000")').first()
locator('xpath=(//*[@class and contains(concat(\' \', normalize-space(@class), \' \'), \' UserLogsPage__Table \')]//tbody//tr[@data-parent-row = \'true\'])[position()=1]').first().locator(':has-text("2024-09-05 04:14:32.000")').first()
    [1] <within>  Error (Non-Terminated) | Error: Text "2024-09-05 04:14:32.000" was not found on page after 1 sec. | (err) => { step.status = 'failed'; step.endTime = ...
    [1] <within> Error | Error: Text "2024-09-05 04:14:32.000" was not found on page after 1 sec. (err) => { output.stepShift = 1; throw err; }...
    [1] <within> Error | Error: Text "2024-09-05 04:14:32.000" was not found on page after 1 sec. undefined...
    [1] <teardown>  Stopping recording promises
  › <screenshotOnFail> Test failed, try to save a screenshot
  › Screenshot is saving to /Users/t/Desktop/projects/codeceptjs-playwright-fun/output/jkljkljlk.failed.png
  ✖ FAILED in 2364ms

    [2]  Starting recording promises

-- FAILURES:

  1) tryTo
       jkljkljlk:
     Text "2024-09-05 04:14:32.000" was not found on page after 1 sec.
      at Playwright.waitForText (node_modules/codeceptjs/lib/helper/Playwright.js:2857:26)
      at async Test.<anonymous> (tests/tryto_test.ts:11:4)
  

@a-roberts
Copy link
Author

a-roberts commented Dec 11, 2024

Like this?

  • /iframe in the i.amOnPage on the end (kinda weird since we've got iframe.html already in there)
  • a switch to iframe immediately after
  • a .first() on the locale

Anything I'm missing? Same error

Scenario('It renders a User Log table', async ({ I }) => {
  I.amOnPage('http://localhost:5057/iframe.html?args=&id=demo-logs-page--renders-correctly&viewMode=story/iframe')
  I.switchTo('iframe')

  I.waitForText('Logs', 5)

  await sleep(5000)

  // Check there is a table
  I.seeElement('.IntegrationDataTable')
  I.seeNumberOfVisibleElements('.UserLogsPage__Table tbody tr[data-parent-row="true"]', 14)
  I.see('14 of 10000')

  // Check column headings
  I.see('Event time (UTC)')
  I.see('Message')
  I.see('Transaction ID')
  I.see('Flow ID')
  I.see('Log level')

  // Check first row
  let firstRow = locate('.UserLogsPage__Table tbody tr[data-parent-row="true"]').first()
  await within(firstRow, () => {
    I.waitForText('2024-09-05 04:14:32.000')
    I.waitForText('appconnect: read the configurations default-switch-server')
    I.waitForText('5523yhy6-1662-11e8-afc4-f58041344r3r')
    I.waitForText('audit')
  })

(Appreciate all of the suggestions and help!)

@kobenguyent
Copy link
Collaborator

may you happen to share the html code of that webpage if that's possible? just the minimum version with obfuscated data ofc.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants