From 267231983dddbeef941f6a31edbb52c6ea35e896 Mon Sep 17 00:00:00 2001 From: Krzysztof Platis Date: Fri, 27 Sep 2024 15:38:09 +0200 Subject: [PATCH] test: print SSR Logs as a context for failed tests to improve troubleshooting of SSR e2e (#19296) Wrapped each test function inside `it()` within an util function `LogUtils.attachLogsToErrors()`. Whenever an error happens inside such a function (e.g. due to a failing `expect()`, the Error is intercepted (via try-catch) and the SSR logs are attached to this error's `cause` property. Then the error is re-thrown. Thanks to this, JestJS will report this `cause` along with the main error message. Btw. made a refactor in various places related to logs: - removed custom function `expectLogMessages()` and custom matcher `.toContainLogs` with regular `expect(logMessages).toContain()` - to not obfuscate under the hood what is being expected and how - moved `LogUtils.clearSsrLogFile();` from top-level `beforeEach` to inside the util `SsrUtils.startSsrServer()` - to be less prone to refactoring mistake of re-ordering the execution of those events (i.e. clear log file VS. start new ssr writing to this file) - created separate functions to get logs: - `getRawLogs(): string[]` - gets raw content of the log file (both JSONs and raw strings like 'Node is listening on port 4000'. - `getRawLogsPretty(): string[]` - similar as above, but it parses single line JSON strings and pretty-prints them (Note: it's used in `LogUtils.attachLogsToErrors()` for making the logs more readable when we attach them as a context of the error). - `getLogsObjects(): object[]` - gets only JSON logs and parses them to JS objects. Raw strings from logs are skipped - `getLogsMessages(): string[]` - gets only JSON logs' `message` properties. Raw strings from logs are skipped **QA steps:** 1. Deliberately make one of the tests fail - e.g. change the expected HTTP status from `200` to `123`, e.g. in line 33, in the test `should receive success response with request` 1. Build libs, app and SSR (with localhost backend): `npm run build:libs && npm run build && build:ssr:local-http-backend` 2. Run ssr-tests: `npm run test:ssr` 3. Verify that the Error message printed by JestJS contains SSR logs as a context: ![image](https://github.com/user-attachments/assets/4c12588b-5ad1-4f99-a56c-67a213ff687b) ![image](https://github.com/user-attachments/assets/d7ae2d01-f853-49b2-8935-3ced99d4b8dd) fixes https://jira.tools.sap/browse/CXSPA-8564 --- projects/ssr-tests/src/matchers/matchers.ts | 50 ------- projects/ssr-tests/src/ssr-testing.spec.ts | 153 +++++++++++--------- projects/ssr-tests/src/utils/log.utils.ts | 133 ++++++++++++++--- projects/ssr-tests/src/utils/ssr.utils.ts | 6 +- projects/ssr-tests/tsconfig.json | 1 + 5 files changed, 200 insertions(+), 143 deletions(-) delete mode 100644 projects/ssr-tests/src/matchers/matchers.ts diff --git a/projects/ssr-tests/src/matchers/matchers.ts b/projects/ssr-tests/src/matchers/matchers.ts deleted file mode 100644 index f21d03ba33c..00000000000 --- a/projects/ssr-tests/src/matchers/matchers.ts +++ /dev/null @@ -1,50 +0,0 @@ -/* - * SPDX-FileCopyrightText: 2024 SAP Spartacus team - * - * SPDX-License-Identifier: Apache-2.0 - */ - -import { getLogMessages } from '../utils/log.utils'; - -expect.extend({ - toContainLogs(received: string[], expected: string[]) { - const receivedString = received.join('\n'); - const expectedString = Array.isArray(expected) - ? expected.join('\n') - : expected; - const pass = receivedString.includes(expectedString); - if (pass) { - return { - message: () => - `Expected log messages not to contain:\n${expectedString}`, - pass: true, - }; - } else { - return { - message: () => - `Expected log messages to contain:\n${expectedString}\n\nbut received:\n${receivedString}`, - pass: false, - }; - } - }, -}); - -interface CustomMatchers { - toContainLogs(expected: string[] | string): R; -} - -declare global { - namespace jest { - interface Expect extends CustomMatchers {} - interface Matchers extends CustomMatchers {} - interface InverseAsymmetricMatchers extends CustomMatchers {} - } -} - -/** - * Return a jest matcher that can be used to check log messages. - * @returns The jest matcher. - */ -export function expectLogMessages(): jest.JestMatchers { - return expect(getLogMessages()); -} diff --git a/projects/ssr-tests/src/ssr-testing.spec.ts b/projects/ssr-tests/src/ssr-testing.spec.ts index 5f58f5d0ffd..17985302569 100644 --- a/projects/ssr-tests/src/ssr-testing.spec.ts +++ b/projects/ssr-tests/src/ssr-testing.spec.ts @@ -1,11 +1,9 @@ import { TestConfig } from '@spartacus/core'; import { Server } from 'http'; -import { expectLogMessages } from './matchers/matchers'; import * as HttpUtils from './utils/http.utils'; import * as LogUtils from './utils/log.utils'; import * as ProxyUtils from './utils/proxy.utils'; import * as SsrUtils from './utils/ssr.utils'; - const BACKEND_BASE_URL: string = process.env.CX_BASE_URL || ''; jest.setTimeout(SsrUtils.DEFAULT_SSR_TIMEOUT); // set timeout to at least 1x DEFAULT_SSR_TIMEOUT seconds for each test in this file to increase stability of the tests @@ -14,10 +12,6 @@ describe('SSR E2E', () => { let backendProxy: Server; const REQUEST_PATH = '/contact'; // path to the page that is less "busy" than the homepage - beforeEach(() => { - LogUtils.clearSsrLogFile(); - }); - afterEach(async () => { backendProxy?.close(); await SsrUtils.killSsrServer(); @@ -29,60 +23,73 @@ describe('SSR E2E', () => { await SsrUtils.startSsrServer(); }); - it('should receive success response with request', async () => { - backendProxy = await ProxyUtils.startBackendProxyServer({ - target: BACKEND_BASE_URL, - }); - const response: any = await HttpUtils.sendRequestToSsrServer({ - path: REQUEST_PATH, - }); - expect(response.statusCode).toEqual(200); + it( + 'should receive success response with request', + LogUtils.attachLogsToErrors(async () => { + backendProxy = await ProxyUtils.startBackendProxyServer({ + target: BACKEND_BASE_URL, + }); + const response: any = await HttpUtils.sendRequestToSsrServer({ + path: REQUEST_PATH, + }); + expect(response.statusCode).toEqual(200); - expectLogMessages().toContainLogs([ - `Rendering started (${REQUEST_PATH})`, - `Request is waiting for the SSR rendering to complete (${REQUEST_PATH})`, - ]); - }); + const logsMessages = LogUtils.getLogsMessages(); + expect(logsMessages).toContain(`Rendering started (${REQUEST_PATH})`); + expect(logsMessages).toContain( + `Request is waiting for the SSR rendering to complete (${REQUEST_PATH})` + ); + }) + ); - it('should receive response with 404 when page does not exist', async () => { - backendProxy = await ProxyUtils.startBackendProxyServer({ - target: BACKEND_BASE_URL, - }); - const response = await HttpUtils.sendRequestToSsrServer({ - path: REQUEST_PATH + 'not-existing-page', - }); - expect(response.statusCode).toEqual(404); - }); + it( + 'should receive response with 404 when page does not exist', + LogUtils.attachLogsToErrors(async () => { + backendProxy = await ProxyUtils.startBackendProxyServer({ + target: BACKEND_BASE_URL, + }); + const response = await HttpUtils.sendRequestToSsrServer({ + path: REQUEST_PATH + 'not-existing-page', + }); + expect(response.statusCode).toEqual(404); + }) + ); - it('should receive response with status 404 if HTTP error occurred when calling cms/pages API URL', async () => { - backendProxy = await ProxyUtils.startBackendProxyServer({ - target: BACKEND_BASE_URL, - callback: (proxyRes, req) => { - if (req.url?.includes('cms/pages')) { - proxyRes.statusCode = 404; - } - }, - }); - const response = await HttpUtils.sendRequestToSsrServer({ - path: REQUEST_PATH, - }); - expect(response.statusCode).toEqual(404); - }); + it( + 'should receive response with status 404 if HTTP error occurred when calling cms/pages API URL', + LogUtils.attachLogsToErrors(async () => { + backendProxy = await ProxyUtils.startBackendProxyServer({ + target: BACKEND_BASE_URL, + callback: (proxyRes, req) => { + if (req.url?.includes('cms/pages')) { + proxyRes.statusCode = 404; + } + }, + }); + const response = await HttpUtils.sendRequestToSsrServer({ + path: REQUEST_PATH, + }); + expect(response.statusCode).toEqual(404); + }) + ); - it('should receive response with status 500 if HTTP error occurred when calling other than cms/pages API URL', async () => { - backendProxy = await ProxyUtils.startBackendProxyServer({ - target: BACKEND_BASE_URL, - callback: (proxyRes, req) => { - if (req.url?.includes('cms/components')) { - proxyRes.statusCode = 404; - } - }, - }); - const response = await HttpUtils.sendRequestToSsrServer({ - path: REQUEST_PATH, - }); - expect(response.statusCode).toEqual(500); - }); + it( + 'should receive response with status 500 if HTTP error occurred when calling other than cms/pages API URL', + LogUtils.attachLogsToErrors(async () => { + backendProxy = await ProxyUtils.startBackendProxyServer({ + target: BACKEND_BASE_URL, + callback: (proxyRes, req) => { + if (req.url?.includes('cms/components')) { + proxyRes.statusCode = 404; + } + }, + }); + const response = await HttpUtils.sendRequestToSsrServer({ + path: REQUEST_PATH, + }); + expect(response.statusCode).toEqual(500); + }) + ); }); describe('With caching enabled', () => { @@ -92,7 +99,7 @@ describe('SSR E2E', () => { it( 'should take the response from cache for the next request if previous render succeeded', - async () => { + LogUtils.attachLogsToErrors(async () => { backendProxy = await ProxyUtils.startBackendProxyServer({ target: BACKEND_BASE_URL, }); @@ -102,23 +109,27 @@ describe('SSR E2E', () => { }); expect(response.statusCode).toEqual(200); - expectLogMessages().toContainLogs([ - `Rendering started (${REQUEST_PATH})`, - `Request is waiting for the SSR rendering to complete (${REQUEST_PATH})`, - ]); + const logsMessages = LogUtils.getLogsMessages(); + expect(logsMessages).toContain(`Rendering started (${REQUEST_PATH})`); + expect(logsMessages).toContain( + `Request is waiting for the SSR rendering to complete (${REQUEST_PATH})` + ); response = await HttpUtils.sendRequestToSsrServer({ path: REQUEST_PATH, }); expect(response.statusCode).toEqual(200); - expectLogMessages().toContain(`Render from cache (${REQUEST_PATH})`); - }, + const logsMessages2 = LogUtils.getLogsMessages(); + expect(logsMessages2).toContain( + `Render from cache (${REQUEST_PATH})` + ); + }), 2 * SsrUtils.DEFAULT_SSR_TIMEOUT // increase timeout for this test as it calls the SSR server twice ); it( 'should render for the next request if previous render failed', - async () => { + LogUtils.attachLogsToErrors(async () => { backendProxy = await ProxyUtils.startBackendProxyServer({ target: BACKEND_BASE_URL, callback: (proxyRes, req) => { @@ -137,10 +148,11 @@ describe('SSR E2E', () => { path: REQUEST_PATH, }); expect(response.statusCode).toEqual(404); - expectLogMessages().not.toContain( + const logsMessages = LogUtils.getLogsMessages(); + expect(logsMessages).not.toContain( `Render from cache (${REQUEST_PATH})` ); - }, + }), 2 * SsrUtils.DEFAULT_SSR_TIMEOUT // increase timeout for this test as it calls the SSR server twice ); }); @@ -172,10 +184,11 @@ describe('SSR E2E', () => { }); expect(response.statusCode).toEqual(200); - expectLogMessages().toContainLogs([ - `Rendering started (${REQUEST_PATH})`, - `Request is waiting for the SSR rendering to complete (${REQUEST_PATH})`, - ]); + const logsMessages = LogUtils.getLogsMessages(); + expect(logsMessages).toContain(`Rendering started (${REQUEST_PATH})`); + expect(logsMessages).toContain( + `Request is waiting for the SSR rendering to complete (${REQUEST_PATH})` + ); }); it('should receive response with 200 even when page does not exist', async () => { diff --git a/projects/ssr-tests/src/utils/log.utils.ts b/projects/ssr-tests/src/utils/log.utils.ts index 91d03bcdfce..9ddc2c3a6cb 100644 --- a/projects/ssr-tests/src/utils/log.utils.ts +++ b/projects/ssr-tests/src/utils/log.utils.ts @@ -11,6 +11,7 @@ */ import * as fs from 'fs'; +import { inspect } from 'util'; /** * Path where SSR log file from server will be generated and read from. @@ -25,28 +26,86 @@ export function clearSsrLogFile(): void { } /** - * Returns all text in the log as a single string. + * Validates that all lines starting with `{` are valid JSON objects. + * Otherwise it throws an error. + * + * Note: multi-line JSONs (printed by SSR in dev mode) cannot be parsed by `JSON.parse`. + * That's why we need to to run SSR in prod mode to get single line JSON logs. */ -export function getLogText(): string { - return fs.readFileSync(SSR_LOG_PATH).toString(); +function validateJsonsInLogs(logs: string[]): void { + logs.forEach((text) => { + if (text.charAt(0) === '{') { + try { + JSON.parse(text); + } catch (error) { + throw new Error( + `Encountered in SSR Logs a line starting with \`{\` that could not be parsed as JSON. + Perhaps its a multi-line JSON log from SSR dev mode. + Please make sure to build Spartacus SSR in prod mode - to get single line JSONs that can be parsed in tests.` + ); + } + } + }); } /** - * Reads log and returns messages as string array. + * Returns raw logs as an array of strings. + * + * Note: Non-JSON log entries are also included in the returned array. + * + * It also validates whether each line starting with `{` is a valid JSON object. + * Otherwise it throws an error. */ -export function getLogMessages(): string[] { +export function getRawLogs(): string[] { const data = fs.readFileSync(SSR_LOG_PATH).toString(); - return ( - data - .toString() - .split('\n') - // We're interested only in JSON logs from Spartacus SSR app. - // We ignore plain text logs coming from other sources, like `Node Express server listening on http://localhost:4200` - .filter((text: string) => text.charAt(0) === '{') - .map((text: any) => { - return JSON.parse(text).message; - }) - ); + const logs = data.toString().split('\n'); + validateJsonsInLogs(logs); + return logs; +} + +/** + * Returns raw logs as an array of strings, with JSON objects pretty-printed. + * + * Note: Non-JSON log entries are also included in the returned array. + */ +export function getRawLogsPretty(): string[] { + return getRawLogs().map((line) => { + try { + const object = JSON.parse(line); + return inspect(object, { depth: null }); + } catch (_e) { + // If the line is not a valid JSON, return it as a string + return line; + } + }); +} + +/** + * Returns logs as an array of objects, parsed from JSON log entries. + * + * Note: Non-JSON log entries are skipped (e.g. 'Node is running on port 4000'). + */ +export function getLogsObjects(): object[] { + return getRawLogs() + .map((log) => { + try { + return JSON.parse(log); + } catch (_e) { + return undefined; + } + }) + .filter((x): x is object => x !== undefined); +} + +/** + * Returns logs as an array of strings, being the `message` field of each parsed JSON log entry. + * + * Note: Non-JSON log entries are skipped (e.g. 'Node is running on port 4000'). + */ +export function getLogsMessages(): string[] { + return getLogsObjects().map((log) => { + return (log as { message: string }).message; + }); } /** @@ -58,7 +117,7 @@ export async function waitUntilLogContainsText( checkInterval = 500 ): Promise { return new Promise((resolve) => { - if (doesLogContainText(text)) { + if (getRawLogs().some((log) => log.includes(text))) { return resolve(true); } return setTimeout( @@ -69,9 +128,41 @@ export async function waitUntilLogContainsText( } /** - * Returns true if log contains string. + * A higher-order function that wraps a test callback and includes SSR logs + * in any error thrown during the test execution. The logs are put into the `cause` + * property of the Error. + * + * @param testFn - The original test function to be wrapped. + * @returns A new function that can be passed to Jest's `it()` or `test()`. + * + * @example + * it('should perform SSR correctly', attachLogsToErrors(async () => { + * // Your test code here + * })); */ -export function doesLogContainText(text: string): boolean { - const data = fs.readFileSync(SSR_LOG_PATH).toString(); - return data.includes(text); +export function attachLogsToErrors( + testFn: () => Promise | void +): () => Promise { + return async () => { + try { + await testFn(); + } catch (error: unknown) { + const readableLogs = getRawLogsPretty().join('\n'); + const ssrLogs = `(more context below)\n--- SSR LOGS (with JSONs pretty-printed) ---\n${readableLogs}\n--- SSR LOGS END ---`; + + if (error instanceof Error) { + // Error's `cause` property is the only property printed by Jest + // besides `message` that we can utilize for attaching logs. + // No other custom properties are printed by Jest. + // See their source code of their function `formatExecError`: + // https://github.com/jestjs/jest/blob/bd1c6db7c15c23788ca3e09c919138e48dd3b28a/packages/jest-message-util/src/index.ts#L436 + + error.cause = ssrLogs; + } else { + throw new Error(error as string, { cause: ssrLogs }); + } + + throw error; + } + }; } diff --git a/projects/ssr-tests/src/utils/ssr.utils.ts b/projects/ssr-tests/src/utils/ssr.utils.ts index 7d3ff3af93f..93253e9bb96 100644 --- a/projects/ssr-tests/src/utils/ssr.utils.ts +++ b/projects/ssr-tests/src/utils/ssr.utils.ts @@ -10,7 +10,7 @@ */ import * as childProcess from 'child_process'; -import * as Log from './log.utils'; +import * as LogUtils from './log.utils'; /** * Default timeout for SSR rendering to happen. @@ -50,13 +50,15 @@ export async function startSsrServer({ cache = false, timeout = DEFAULT_SSR_TIMEOUT, }: SsrServerOptions = {}) { + LogUtils.clearSsrLogFile(); + child = childProcess.spawn( // `2>&1` - redirect stderr to stdout, so also `console.error` and `console.warn` messages are captured in the log file `NODE_TLS_REJECT_UNAUTHORIZED=0 SSR_CACHE=${cache} SSR_TIMEOUT=${timeout} PORT=${port} npm run serve:ssr --prefix ../../> .ssr.log 2>&1`, { detached: true, shell: true } ); - await Log.waitUntilLogContainsText(`Node Express server listening on `); + await LogUtils.waitUntilLogContainsText(`Node Express server listening on `); } /** diff --git a/projects/ssr-tests/tsconfig.json b/projects/ssr-tests/tsconfig.json index dad20eca34c..8e632f06fbe 100644 --- a/projects/ssr-tests/tsconfig.json +++ b/projects/ssr-tests/tsconfig.json @@ -3,6 +3,7 @@ "compilerOptions": { "module": "CommonJs", "types": ["jest"], + "lib": ["ES2023"], "declaration": true, "noEmitOnError": true, "noFallthroughCasesInSwitch": true,