Skip to content

refactor: improve e2e test reporting #10304

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

Merged
merged 9 commits into from
Oct 17, 2023
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
3 changes: 3 additions & 0 deletions site/.eslintrc.yaml
Original file line number Diff line number Diff line change
Expand Up @@ -91,6 +91,9 @@ rules:
- allowSingleExtends: true
"brace-style": "off"
"curly": ["error", "all"]
"eslint-comments/disable-enable-pair":
- error
- allowWholeFile: true
"eslint-comments/require-description": "error"
eqeqeq: error
import/default: "off"
Expand Down
2 changes: 1 addition & 1 deletion site/e2e/playwright.config.ts
Original file line number Diff line number Diff line change
Expand Up @@ -6,7 +6,7 @@ export const port = process.env.CODER_E2E_PORT
? Number(process.env.CODER_E2E_PORT)
: defaultPort;

const coderMain = path.join(__dirname, "../../enterprise/cmd/coder/main.go");
const coderMain = path.join(__dirname, "../../enterprise/cmd/coder");

export const STORAGE_STATE = path.join(__dirname, ".auth.json");

Expand Down
159 changes: 110 additions & 49 deletions site/e2e/reporter.ts
Original file line number Diff line number Diff line change
@@ -1,85 +1,146 @@
import fs from "fs";
/* eslint-disable no-console -- Logging is sort of the whole point here */
import * as fs from "fs/promises";
import type {
FullConfig,
Suite,
TestCase,
TestResult,
FullResult,
Reporter,
TestError,
} from "@playwright/test/reporter";
import axios from "axios";
import type { Writable } from "stream";

class CoderReporter implements Reporter {
config: FullConfig | null = null;
testOutput = new Map<string, Array<[Writable, string]>>();
passedCount = 0;
failedTests: TestCase[] = [];
timedOutTests: TestCase[] = [];

onBegin(config: FullConfig, suite: Suite) {
// eslint-disable-next-line no-console -- Helpful for debugging
console.log(`Starting the run with ${suite.allTests().length} tests`);
this.config = config;
console.log(`==> Running ${suite.allTests().length} tests`);
}

onTestBegin(test: TestCase) {
// eslint-disable-next-line no-console -- Helpful for debugging
console.log(`Starting test ${test.title}`);
this.testOutput.set(test.id, []);
console.log(`==> Starting test ${test.title}`);
}

onStdOut(chunk: string, test: TestCase, _: TestResult): void {
// eslint-disable-next-line no-console -- Helpful for debugging
console.log(
`[stdout] [${test ? test.title : "unknown"}]: ${chunk.replace(
/\n$/g,
"",
)}`,
);
onStdOut(chunk: string, test?: TestCase, _?: TestResult): void {
if (!test) {
for (const line of filteredServerLogLines(chunk)) {
console.log(`[stdout] ${line}`);
}
return;
}
this.testOutput.get(test.id)!.push([process.stdout, chunk]);
}

onStdErr(chunk: string, test: TestCase, _: TestResult): void {
// eslint-disable-next-line no-console -- Helpful for debugging
console.log(
`[stderr] [${test ? test.title : "unknown"}]: ${chunk.replace(
/\n$/g,
"",
)}`,
);
onStdErr(chunk: string, test?: TestCase, _?: TestResult): void {
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

We might be losing here output from coderd, which can be really useful during backend debugging. In the legacy version, it is logged like this:

[stderr] [unknown]: [WebServer] 2023-10-17 06:54:03.412 [info]  provisionerd.runner: apply successful  job_id=89020454-1bd8-4eed-a0c9-eb12fa532a92  template_name=68ac3052  template_version=hardcore_moser9  workspace_build_id=465c8cad-3fcb-42fb-b9bb-56007b4a1db3  workspace_id=74006ba8-82a8-4693-b971-f3da61ad02e0  workspace_name=d93260bd  workspace_owner=admin  workspace_transition=start  resource_count=1  resources="[name:\"example\" type:\"echo\"]"  state_len=0

It looks like the new reporter simply skips these log records.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

that was sort of intentional. it adds a lot of noise when trying to debug a frontend failure, and since it's not tied to a specific test case it's hard to buffer and display later in a way that makes sense.

I also added some logic for preserveOutput, but I just read the docs and it turns out it does something entirely different from what I expected, and can't even be set from the command line like I hoped 😵‍💫

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

the idea was supposed to be that backend peeps could set --preserveOutput=always when they ran the tests... I'd really like to find a compromise here to keep the output clean when possible. it's just always such a pain to find the actual error in all of the mountains of logs.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

example run, which now has 41 occurrences of the word "error" but succeeded https://github.com/coder/coder/actions/runs/6549912328/job/17787879014?pr=10304

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

A good compromise would be only filtering out audit_log entries, which do not bring a lot of value. 👍

I would leave coderd output as it is helpful with debugging the request flow or provisioner behavior, especially while dealing with flaky issues.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

if we can also ignore lines like echo: recv done on Session session_id= error=EOF then I'll be happy. :)

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Agree 👍

if (!test) {
for (const line of filteredServerLogLines(chunk)) {
console.error(`[stderr] ${line}`);
}
return;
}
this.testOutput.get(test.id)!.push([process.stderr, chunk]);
}

async onTestEnd(test: TestCase, result: TestResult) {
// eslint-disable-next-line no-console -- Helpful for debugging
console.log(`Finished test ${test.title}: ${result.status}`);
console.log(`==> Finished test ${test.title}: ${result.status}`);

if (result.status === "passed") {
this.passedCount++;
}

if (result.status === "failed") {
this.failedTests.push(test);
}

if (result.status === "timedOut") {
this.timedOutTests.push(test);
}

const fsTestTitle = test.title.replaceAll(" ", "-");
const outputFile = `test-results/debug-pprof-goroutine-${fsTestTitle}.txt`;
await exportDebugPprof(outputFile);

if (result.status !== "passed") {
// eslint-disable-next-line no-console -- Helpful for debugging
console.log("errors", result.errors, "attachments", result.attachments);
console.log(`Data from pprof has been saved to ${outputFile}`);
console.log("==> Output");
const output = this.testOutput.get(test.id)!;
for (const [target, chunk] of output) {
target.write(`${chunk.replace(/\n$/g, "")}\n`);
}

if (result.errors.length > 0) {
console.log("==> Errors");
for (const error of result.errors) {
reportError(error);
}
}

if (result.attachments.length > 0) {
console.log("==> Attachments");
for (const attachment of result.attachments) {
console.log(attachment);
}
}
}
await exportDebugPprof(test.title);
this.testOutput.delete(test.id);
}

onEnd(result: FullResult) {
// eslint-disable-next-line no-console -- Helpful for debugging
console.log(`Finished the run: ${result.status}`);
console.log(`==> Tests ${result.status}`);
console.log(`${this.passedCount} passed`);
if (this.failedTests.length > 0) {
console.log(`${this.failedTests.length} failed`);
for (const test of this.failedTests) {
console.log(` ${test.location.file} › ${test.title}`);
}
}
if (this.timedOutTests.length > 0) {
console.log(`${this.timedOutTests.length} timed out`);
for (const test of this.timedOutTests) {
console.log(` ${test.location.file} › ${test.title}`);
}
}
}
}

const exportDebugPprof = async (testName: string) => {
const url = "http://127.0.0.1:6060/debug/pprof/goroutine?debug=1";
const outputFile = `test-results/debug-pprof-goroutine-${testName}.txt`;
const shouldPrintLine = (line: string) =>
[" error=EOF", "coderd: audit_log"].every((noise) => !line.includes(noise));

await axios
.get(url)
.then((response) => {
if (response.status !== 200) {
throw new Error(`Error: Received status code ${response.status}`);
}
const filteredServerLogLines = (chunk: string): string[] =>
chunk.trimEnd().split("\n").filter(shouldPrintLine);

fs.writeFile(outputFile, response.data, (err) => {
if (err) {
throw new Error(`Error writing to ${outputFile}: ${err.message}`);
} else {
// eslint-disable-next-line no-console -- Helpful for debugging
console.log(`Data from ${url} has been saved to ${outputFile}`);
}
});
})
.catch((error) => {
throw new Error(`Error: ${error.message}`);
});
const exportDebugPprof = async (outputFile: string) => {
const response = await axios.get(
"http://127.0.0.1:6060/debug/pprof/goroutine?debug=1",
);
if (response.status !== 200) {
throw new Error(`Error: Received status code ${response.status}`);
}

await fs.writeFile(outputFile, response.data);
};

const reportError = (error: TestError) => {
if (error.location) {
console.log(`${error.location.file}:${error.location.line}:`);
}
if (error.snippet) {
console.log(error.snippet);
}

if (error.message) {
console.log(error.message);
} else {
console.log(error);
}
};

// eslint-disable-next-line no-unused-vars -- Playwright config uses it
Expand Down