archfz
commented
2 months ago Is this reproducing only on CI? Or locally as well? Is it only for certain tests or all tests? Have you tried different settings? Like not having file logging enabled?
Open patrickgeorge1 opened 2 months ago
archfz
commented
2 months ago Is this reproducing only on CI? Or locally as well? Is it only for certain tests or all tests? Have you tried different settings? Like not having file logging enabled?
patrickgeorge1
commented
2 months ago Hello @archfz, Thanks for answering!
Is this reproducing only on CI?
No, I managed to reproduce it from my local machine (from docker). I think the problem arise only when running from docker.
Or locally as well?
Yes, from docker.
Is it only for certain tests or all tests?
All test I guess. I created a very simple test with a small it block. Afterwards I've noticed it in other tests as well.
Have you tried different settings? Like not having file logging enabled?
Yes, I've tested it with log-only-on-failure and the same behavior occurred.
This is the output produced when failing from local docker:
Running: dependencies.cy.ts (1 of 1)
error: XDG_RUNTIME_DIR is invalid or not set in the environment.
error: XDG_RUNTIME_DIR is invalid or not set in the environment.
<?xml version="1.0" encoding="UTF-8"?>
<testsuites name="Mocha Tests" time="133.478" tests="1" failures="1">
<testsuite name="Root Suite" timestamp="2024-09-03T13:48:24" tests="0" file="cypress/e2e/athena/dependencies.cy.ts" time="0.000" failures="0">
</testsuite>
<testsuite name="AS core functionality" timestamp="2024-09-03T13:49:00" tests="1" time="97.379" failures="1">
<testcase name="AS core functionality "after each" hook for "underlying dependencies (db & storage) should work as expected when creating a project"" time="0.000" classname=""after each" hook for "underlying dependencies (db & storage) should work as expected when creating a project"">
<failure message="`cy.task('ctrLogMessages')` timed out after waiting `60000ms`.
https://on.cypress.io/api/task
Because this error occurred during a `after each` hook we are skipping all of the remaining tests." type="CypressError"><![CDATA[CypressError: `cy.task('ctrLogMessages')` timed out after waiting `60000ms`.
https://on.cypress.io/api/task
Because this error occurred during a `after each` hook we are skipping all of the remaining tests.
at <unknown> (https://as.loc/__cypress/runner/cypress_runner.js:135394:70)
at tryCatcher (https://as.loc/__cypress/runner/cypress_runner.js:1807:23)
at <unknown> (https://as.loc/__cypress/runner/cypress_runner.js:4186:41)
at tryCatcher (https://as.loc/__cypress/runner/cypress_runner.js:1807:23)
at Promise._settlePromiseFromHandler (https://as.loc/__cypress/runner/cypress_runner.js:1519:31)
at Promise._settlePromise (https://as.loc/__cypress/runner/cypress_runner.js:1576:18)
at Promise._settlePromise0 (https://as.loc/__cypress/runner/cypress_runner.js:1621:10)
at Promise._settlePromises (https://as.loc/__cypress/runner/cypress_runner.js:1697:18)
at _drainQueueStep (https://as.loc/__cypress/runner/cypress_runner.js:2407:12)
at _drainQueue (https://as.loc/__cypress/runner/cypress_runner.js:2400:9)
at Async._drainQueues (https://as.loc/__cypress/runner/cypress_runner.js:2416:5)
at Async.drainQueues (https://as.loc/__cypress/runner/cypress_runner.js:2286:14)
From Your Spec Code:
at Context.eval (webpack://studio-web-e2e/./node_modules/cypress-terminal-report/src/collector/LogCollectSimpleControl.js:67:0)]]></failure>
</testcase>
</testsuite>
</testsuites>Ok. So it is only from docker. So it is not really local. I think it might be something related to node version or some other aspects of the docker image.
Is it possible for you to create a minimal reproducible docker image? As I am having difficulty to reproduce this issue.
patrickgeorge1
commented
2 months ago Sure, this is what I can share:
Docker file:
FROM cypress/included:13.13.1
RUN apt-get update && apt-get install -y jq && apt-get clean && rm -rf /var/lib/apt/lists/*
RUN apt-get update && apt-get install -y curl && apt-get clean && rm -rf /var/lib/apt/lists/*
RUN curl -sL https://aka.ms/InstallAzureCLIDeb | bash
WORKDIR /opt/app
COPY . /opt/app
// other file related copy / move operations
COPY --chmod=0755 script.sh /validateHow we run it:
docker run `
--entrypoint /validate`
--network=host `
image-built-with-dockerfile:v1package.json
{
"name": "......",
"version": "0.0.0",
"scripts": {
.....
},
"private": true,
"devDependencies": {
"@cypress/skip-test": "^2.6.1",
"@types/faker": "^5.1.4",
"@types/node": "^12.20.55",
"cypress": "^13.13.1",
"cypress-terminal-report": "^6.1.2",
"faker": "^5.1.0",
"junit": "^0.5.1",
"junit-merge": "^2.0.0",
"jwt-decode": "^3.1.2",
"tslint": "~6.1.0",
"typescript": "~4.0.2"
}
}
e2e.ts
...
const IGNORED_URLS = ['launchdarkly', 'visualstudio'];
require('cypress-terminal-report/src/installLogsCollector')({
filterLog: ({ message }: any) => !IGNORED_URLS.some(url => message.includes(url)) && !message.includes('@ngrx/store-devtools'),
xhr: {
printHeaderData: false,
printRequestData: false,
},
});
...cypress.config.ts
...
module.exports = defineConfig({
viewportWidth: 1920,
viewportHeight: 1080,
chromeWebSecurity: false,
blockHosts: [...],
reporter: 'junit',
reporterOptions: {
mochaFile: 'cypress/results/e2e-output.[hash].xml',
toConsole: true,
},
requestTimeout: 15000,
defaultCommandTimeout: 15000,
e2e: {
testIsolation: false,
experimentalSkipDomainInjection: [....],
supportFile: "cypress/support/e2e.ts",
// We've imported your old cypress plugins here.
// You may want to clean this up later by importing these.
setupNodeEvents(on, config) {
on('before:browser:launch', (browser, launchOptions) => {
if (browser.name === 'chrome' && browser.isHeadless) {
launchOptions.args = launchOptions.args.map((arg) => {
if (arg === '--headless') {
return '--headless=new'
}
return arg
})
}
return launchOptions
})
on(
'after:spec',
(_spec, results) => {
if (results && results.video) {
// Do we have failures for any retry attempts?
const failures = results.tests.some((test) =>
test.attempts.some((attempt) => attempt.state === 'failed')
)
if (!failures) {
// delete the video if the spec passed and no tests retried
unlinkSync(results.video)
}
}
}
)
return require('cypress-terminal-report/src/installLogsPrinter')(on, {
printLogsToFile: 'always',
printLogsToConsole: 'never',
outputRoot: config.projectRoot + '/cypress/logs/',
specRoot: 'cypress/e2e',
outputTarget: {
'.|txt': 'txt',
}
});
},
video: true,
videoCompression: true,
baseUrl: 'https://localhost:32805',
},
});
['logs', 'screenshots', 'videos'].forEach(dir =>
mkdirSync(`cypress/${dir}`, { recursive: true })
);
...test that runs
// no before / before each
it("....", () => {
cy.visitApp();
// 1 Create a project via API call
const project = Projects.getRandomProject();
project.name = `...${project.name}`;
createProjectViaApi(project);
cy.visitApp();
// 2 Check it exists in the UI
cy.contains(project.name).should("exist");
})
// no after / after eachI attempted to reproduce but still failed. Check here https://github.com/archfz/cypress-terminal-report-demo/tree/issue_249 You can build the image and run cypress in it, and it works.
Now you have claimed that simply running cypress run in your local works. Based on this it is docker. However since I cannot reproduce with just the configuration and version being the same, I suspect this is also due to your test code somehow.
Could you attempt running one of the specs on your project setup from cypress-terminal-report-demo? Or just add a simpler spec that doesn't use those visitApp() or doesn't visit your actual site being tested.
patrickgeorge1
commented
2 months ago @archfz Thank you for your help! Unfortunately this is not happening always. Only sometimes, but it's enough to trigger some alerts. So please make sure to try multiple times.
I will try to follow your suggestion and use the demo repo (recommended in the previous comment), BUT before that I managed to reproduce again the issue (seemed to be exponentially harder to reproduce it if DEBUG=cypress:* was enabled) and I'm pasting here the sanitized logs. Maybe it can help you to figure out the problem. Please check in the end of logs by must only be invoked from the spec file or support file.
Looking forward for your response.
archfz
commented
2 months ago Ok. So based on this new information and also based on some rechecks on things and config.
You are using the SimpleControl for log collection. In the screenshots I see that you have an initial error on ctrlLogMessage but then also a secondary timeout error on ctrLogFiles. So there seems to be two problems, maybe related. However lets focus on the first one.
must only be invoked from the spec file or support file Now this issue can happen in two cases in SimpleControl case. And none of those cases seem to be trigger-able in your case, with your config. One case is when you have continuosLogging enabled, but you don't. Another case is when you have skipped tests, that were manually skipped, basically not with it.skip but with programmatic skip, maybe this is your cases? Otherwise I am baffled by that above error as it should not be able to happen.
I have no additional information on the case of timeout on ctrLogFiles. What would be good here if you could confirm that both errors happen at the same time, or there are times when only one fails.
Also you have posted those screenshots. How did you create those screenshots? Because I understood that this only reproduces in docker, not locally as well. But you wouldn't be able to do cypress open in docker, so you wouldn't have been able to create the screenshots.
patrickgeorge1
commented
2 months ago Thank you for investigating further @archfz !
You are using the SimpleControl for log collection
Indeed, the config is exactly what I mentioned in the code snippets from the above comments
error on ctrlLogMessage but then also a secondary timeout error on ctrLogFiles
I can confirm that sometimes I saw ctrlLogMessage being reported in the error and other times ctrLogFiles. I cannot be sure if I saw both of them, but there is a high chance.
One case is when you have continuosLogging enabled
Indeed, that's not the case
Another case is when you have skipped tests, that were manually skipped, basically not with it.skip but with programmatic skip, maybe this is your cases?
The project contains multiple typescript test spec files (each containing test suites wrapped with describe) like Core.ts / Performance.ts etc.
The spec that I used for testing (the one which fails in CI and docker local + all logs and comments above correspond to) does not contain any sort of skip. It's approximatively what I sent above:
describe("yyyy", () => {
it("zzzz", () => {
cy.visitApp(); // like normal cy.visit, but sets some query params
// 1 Create a project via API call
const project = Projects.getRandomProject(); // just use random to prepare a string
project.name = `prefix_${project.name}`;
createProjectViaApi(project); // just uses Cypress to load stuff from local storage and issues an Http request
cy.visitApp();
// 2 Check it exists in the UI
cy.contains(project.name).should("exist");
})
})However, I've noticed that other spec files make use of skip functionality using different strategies:
it.skip(string, callback) from Mocha.TestFunctionskipOn(string, callback) from @cypress/skip-testxit(string, callback) from Mocha PendingTestFunctionI don't know if those other spec files are the culprits because I don't trigger them with npx cypress run, but maybe it's relevant and can help you figure out things.
I have no additional information on the case of timeout on ctrLogFiles. What would be good here if you could confirm that both errors happen at the same time, or there are times when only one fails
We have a tool which tests at scale (e.g. can run a docker container a 100 hundred times) and I remember seeing each of them being reported, but I can't remember if they were both reported as part of the same failed test. I would say "maybe yes" and I will continue to check and post a new comment here in case I manage to confirm it.
Also you have posted those screenshots. How did you create those screenshots? Because I understood that this only reproduces in docker, not locally as well. But you wouldn't be able to do cypress open in docker, so you wouldn't have been able to create the screenshots.
These screenshots are coming from CI which indeed runs cypress in docker, but it has video recording enabled and we export test results / screenshots / videos (created by cypress) as generated pipeline artifacts. I just pasted from there.
Regarding running from docker local, I just did the same: once the docker container finished executing I just downloaded the artifacts from inside it.
It is true that I could not reproduce the bug when running cypress locally without docker (directly running npx cypress run from my terminal), so that is why I test it locally from docker (docker run ... from my terminal - which inside is calling npx cypress run).
Extra information which could help:
e2e.ts
beforeEach(function () {
addCanaryHeader();
// ignore certain network requests from the logging
cy.intercept('GET', /\.(jsx?|coffee|woff2|html|dll|png|less|s?css|svg)(\?.*)?$/, { log: false });
cy.intercept(/something/, { log: false });
cy.window()
.its('console')
.then(console => cy.spy(console, 'log').as('log').log(false));
});
...
Cypress.Commands.add('waitForConsoleLog', (keywords: string[], timeout: number = 15000): Cypress.Chainable<void> => {
const startTime = Date.now();
function checkLogs(): Cypress.Chainable<void> {
return cy.get('@log').invoke('getCalls').then((calls: any[]) => {
const found = calls.some((call: any) => {
return keywords.every((keyword: string) => {
return call.args.some((arg: any) => typeof arg === 'string' && arg.includes(keyword));
});
});
if (found) {
return;
}
const elapsed = Date.now() - startTime;
if (elapsed >= timeout) {
throw new Error(`Timeout waiting for console log messages containing keywords: ${keywords}`);
}
return cy.wait(500).then(checkLogs);
});
}
return checkLogs();
});Cypress.on('uncaught:exception', (err) => {
if (err.message.includes('ResizeObserver')) {
return false
}
if (err.stack?.includes('platform-cdn.company.com/product-packages')) {
return false;
}
// we still want to ensure there are no other unexpected
// errors, so we let them fail the test
})I hope that you'll find my answer helpful. If you need more information please let me know. Looking forward for your response. Thanks!
archfz
commented
2 months ago Ok, It seems your cypress project is quite customized. I think it will be very hard to debug this. I am thinking that I will extend the debug option of this plugin to log much more information. Once you update and enabled we can investigate further.
archfz
commented
1 month ago So I have been thinking on where to log additional debug stuff to figure this out. But I couldn't really pinpoint where it would be best. I have however became more confused on what is going on.
So you have said that you have disabled file logging and you've still got ctrLogMessages timed out error. Now if you have console logging disabled, file logging disabled, log compacting not enabled, collect test logs not enabled, then the ctrLogMessages task is essentially not doing anything. So why would it time out? Either way why would it time out, this issue seems very strange. Could it be that the payload that is sent with the messages to the task is too big? I would assume you have reproduced this issue in an isolated run of a single spec / test from the spec. And from what I understood that test doesn't have a lot of code, so not a lot of logs should be generated, so this should not be the case.
archfz
commented
1 month ago I've published 6.2.0 with debug option on plugin install side. Please check README as well. Enable this and reproduce the issue, there should be atleast some [cypress-terminal-report:debug] logs in the terminal. If there aren't any that also gives some information.
patrickgeorge1
commented
1 month ago Thank you @archfz for checking
Ok, It seems your cypress project is quite customized. I think it will be very hard to debug this. I am thinking that I will extend the debug option of this plugin to log much more information. Once you update and enabled we can investigate further.
Indeed, the project is medium-large and a debug option is welcomed.
So you have said that you have disabled file logging and you've still got ctrLogMessages timed out error. Now if you have console logging disabled, file logging disabled, log compacting not enabled, collect test logs not enabled, then the ctrLogMessages task is essentially not doing anything. So why would it time out? Either way why would it time out, this issue seems very strange. Could it be that the payload that is sent with the messages to the task is too big?
I think this is a real possibility because I saw big log file being generated when the error was not thrown and no log file at all when the error was thrown. After checking one of the generated log files it seems that the total number of chars from inside was 1408628 (used this tool for measuring) and then I picked the biggest individual log which seemed to be an cons:log (K): Action and it had 678197. Maybe this is the problem. I'll look for a way to cap the length of individual logs to maximum 1000 characters ( maybe by using options.processLog or options.defaultTrimLength - any recommendation ?) and test again, then I will post the results here.
I would assume you have reproduced this issue in an isolated run of a single spec / test from the spec. And from what I understood that test doesn't have a lot of code, so not a lot of logs should be generated, so this should not be the case.
Even though the test spec is almost trivial, the web application under test is generating a lot of logs so I guess this could be a valid concern as showed above.
I've published 6.2.0 with debug option on plugin install side. Please check README as well. Enable this and reproduce the issue, there should be atleast some [cypress-terminal-report:debug] logs in the terminal. If there aren't any that also gives some information.
I managed to reproduce it. Attaching the logs here. Btw I noticed that when I did docker run .... > file.txt I couldn't reproduce it so I just run docker run .. without any output redirect and copy-pasted terminal output. I guess this is exactly what you are looking for.
log-file-with-debug-enabled.txt
The config used was:
cypress.config.ts
...
return require('cypress-terminal-report/src/installLogsPrinter')(on, {
debug: true,
printLogsToFile: 'always',
printLogsToConsole: 'never',
outputRoot: config.projectRoot + '/cypress/logs/',
specRoot: 'cypress/e2e',
outputTarget: {
'.|txt': 'txt',
}
});
...e2e.ts
...
const IGNORED_URLS = ['blah', 'visualstudio'];
require('cypress-terminal-report/src/installLogsCollector')({
filterLog: ({ message }: any) => !IGNORED_URLS.some(url => message.includes(url)) && !message.includes('@ngrx/store-devtools'),
xhr: {
printHeaderData: false,
printRequestData: false,
},
});
...Looking forward for your response. Thanks!
archfz
commented
1 month ago Yepp I can see that none of the debug logs are triggered from the ctrLogMessages, only a single one from ctrLogFiles task.
In this case I really think its an issue with the payload of the task, which contains maybe too many messages.
Please try to configure collectTypes on support side, with incremental types starting from empty array. And see when does the issue reproduce.
patrickgeorge1
commented
1 month ago @archfz
After experimenting I extracted the following conclusions:
collectTypes in installLogsCollector did not help. It seemed that regardless of the value it still failed.My feeling is that there is still some processing in the background (e.g. setting collectTypes: [] still failed).
I'm attaching a sanitized log file that was generated when the error didn't occur (run 100 times the same dummy test and 30% failed because of this) sanitized-logs.txt. These are the logs which should be printed in all test iterations (failed included).
Do you know what is the performance limit of the plugin ? What do you recommend me to try next ?
Thanks
archfz
commented
1 month ago With collectTypes set to empty array no logs will be collected. So this is very strange. If in that case you still got timeout on ctrLogMessages then something else is going on other than the size of the payload.
At this point I would recommend experimenting with collectTypes as empty array and different cypress / node / docker image version.
archfz
commented
1 month ago I don't know the performance limitations of this plugin. Noone ever reported a case where a test case was generating so many logs that it would break.
archfz
commented
1 month ago Another thing you could try is enabling continuous logging. While this is not the best fit for actual usage it could give some more information where the problem might be. With this options there should not be a buildup of logs as all logs are immediately sent.
https://github.com/archfz/cypress-terminal-report?tab=readme-ov-file#optionsenablecontinuouslogging
When using cypress to test some web application it gets after the end of a successful test into some
after each/afterbocks (plugin defined) and then fails withcy.task(ctrLogMessages) timed out after waiting 60000ms.This makes the test to fail.
Operating System: Ubuntu latest Software Version: Cypress 13.13.1, cypress-terminal-report ^5.0.2 (tried with ^6.1.2) Additional Information: The web application is written with Angular and Cypress is used to test it. Cypress runs inside a docker container from Azure VM / Pipeline.
Error
e2e.ts
cypress.config.ts