Skip to content

Commit

Permalink
fix: in dev mode pretty-print multi-line strings in logs (#19266)
Browse files Browse the repository at this point in the history 
Now in dev mode we're using `formatWithOptions()` instead of `JSON.stringify()`. So now the output in the console in dev mode is more human-readable (including multi-line strings).

**QA steps**:
1. in app.module.ts provide the following config chunk (causing HTTP call to backend to fail):
   ```ts
    provideConfig({
      backend: {
        occ: {
          endpoints: {
            components: 'some-fake-endpoint',
          },
        },
      },
    }),
   ```
2. start SSR server - run `npm run dev:ssr` 
3. in another terminal `curl http://localhost:4200`
4. In the logs of the SSR server, see the error message is now multi-line human-readable format. Also function's definitions in the `[spartacus] SSR optimization engine initialized` are also multi-line.

BEFORE (dev mode only screenshots):
![image](https://github.com/user-attachments/assets/ab8f02a6-5f26-4605-8f96-5a7d8ad91f11)

![image](https://github.com/user-attachments/assets/fb9f192f-f3c4-43c3-998e-9481c8bf86e2)

![image](https://github.com/user-attachments/assets/4bb7f5c1-410d-4f5d-b9cb-75a7998953fb)


AFTER:

a) DEV MODE:
![image](https://github.com/user-attachments/assets/c419fef7-60ef-4981-8eff-d206ef8e8226)

![image](https://github.com/user-attachments/assets/5243ea4e-c108-42fc-87c0-5388527f1e04)

![image](https://github.com/user-attachments/assets/e17b071e-fce0-4a8e-a543-bcd3463c1f10)

b) PROD MODE:
![image](https://github.com/user-attachments/assets/a1e3c104-2232-4d4d-a7ea-c7ade59f2d71)

![image](https://github.com/user-attachments/assets/039d079f-891d-436d-9d99-e8aacd9df10f)

![image](https://github.com/user-attachments/assets/031668b9-0451-48d6-ad97-596c2417bfb1)



fixes https://jira.tools.sap/browse/CXSPA-8385
  • Loading branch information
@Platonn
Platonn authored Sep 20, 2024
1 parent 06f08ae commit 356a370
Show file tree
Hide file tree
Showing 3 changed files with 129 additions and 139 deletions.
217 changes: 105 additions & 112 deletions core-libs/setup/ssr/logger/loggers/default-express-server-logger.spec.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -125,7 +125,6 @@ describe('DefaultExpressServerLogger', () => {
const error = new Error('test error');
logger.log('test', { error });

expect(debugSpy.mock.lastCall?.[0]).not.toContain(`"error":{}`);
expect(debugSpy.mock.lastCall?.[0]).toContain(
`"error":"Error: test error` // deliberate no closing double quote, because there goes the stacktrace
);
Expand Down Expand Up @@ -159,11 +158,8 @@ describe('DefaultExpressServerLogger', () => {
});
logger.log('test', { error });

expect(debugSpy.mock.lastCall?.[0]).not.toContain(
`[cause]: { level2: { level3: [Object] } }`
);
expect(debugSpy.mock.lastCall?.[0]).toContain(
`[cause]: {\\n level2: {\\n level3: {\\n level4: {\\n level5: {\\n level6: {\\n level7: { level8: { level9: { level10string: 'level10string' } } }\\n }\\n }\\n }\\n }\\n }\\n }\\n}`
`{ level10string: 'level10string' }`
);
});
});
Expand All @@ -181,26 +177,26 @@ describe('DefaultExpressServerLogger', () => {
logger.log('test', { request });

expect(debugSpy.mock.lastCall).toMatchInlineSnapshot(`
[
"{
"message": "test",
"context": {
"timestamp": "2023-05-26T00:00:00.000Z",
"request": {
"url": "test",
"uuid": "test",
"timeReceived": "2023-05-26T00:00:00.000Z",
"traceContext": {
"version": "00",
"traceId": "d745f6735b44e81c0ae5410cb1fc8a0c",
"parentId": "1b527c3828976b39",
"traceFlags": "01"
}
}
}
}",
]
`);
[
"{
message: 'test',
context: {
timestamp: '2023-05-26T00:00:00.000Z',
request: {
url: 'test',
uuid: 'test',
timeReceived: 2023-05-26T00:00:00.000Z,
traceContext: {
version: '00',
traceId: 'd745f6735b44e81c0ae5410cb1fc8a0c',
parentId: '1b527c3828976b39',
traceFlags: '01'
}
}
}
}",
]
`);
});

it('should warn proper shape of the JSON', () => {
Expand All @@ -211,26 +207,26 @@ describe('DefaultExpressServerLogger', () => {
logger.warn('test', { request });

expect(debugSpy.mock.lastCall).toMatchInlineSnapshot(`
[
"{
"message": "test",
"context": {
"timestamp": "2023-05-26T00:00:00.000Z",
"request": {
"url": "test",
"uuid": "test",
"timeReceived": "2023-05-26T00:00:00.000Z",
"traceContext": {
"version": "00",
"traceId": "d745f6735b44e81c0ae5410cb1fc8a0c",
"parentId": "1b527c3828976b39",
"traceFlags": "01"
}
}
}
}",
]
`);
[
"{
message: 'test',
context: {
timestamp: '2023-05-26T00:00:00.000Z',
request: {
url: 'test',
uuid: 'test',
timeReceived: 2023-05-26T00:00:00.000Z,
traceContext: {
version: '00',
traceId: 'd745f6735b44e81c0ae5410cb1fc8a0c',
parentId: '1b527c3828976b39',
traceFlags: '01'
}
}
}
}",
]
`);
});

it('should error proper shape of the JSON', () => {
Expand All @@ -241,26 +237,26 @@ describe('DefaultExpressServerLogger', () => {
logger.error('test', { request });

expect(debugSpy.mock.lastCall).toMatchInlineSnapshot(`
[
"{
"message": "test",
"context": {
"timestamp": "2023-05-26T00:00:00.000Z",
"request": {
"url": "test",
"uuid": "test",
"timeReceived": "2023-05-26T00:00:00.000Z",
"traceContext": {
"version": "00",
"traceId": "d745f6735b44e81c0ae5410cb1fc8a0c",
"parentId": "1b527c3828976b39",
"traceFlags": "01"
}
}
}
}",
]
`);
[
"{
message: 'test',
context: {
timestamp: '2023-05-26T00:00:00.000Z',
request: {
url: 'test',
uuid: 'test',
timeReceived: 2023-05-26T00:00:00.000Z,
traceContext: {
version: '00',
traceId: 'd745f6735b44e81c0ae5410cb1fc8a0c',
parentId: '1b527c3828976b39',
traceFlags: '01'
}
}
}
}",
]
`);
});

it('should info proper shape of the JSON', () => {
Expand All @@ -271,26 +267,26 @@ describe('DefaultExpressServerLogger', () => {
logger.info('test', { request });

expect(debugSpy.mock.lastCall).toMatchInlineSnapshot(`
[
"{
"message": "test",
"context": {
"timestamp": "2023-05-26T00:00:00.000Z",
"request": {
"url": "test",
"uuid": "test",
"timeReceived": "2023-05-26T00:00:00.000Z",
"traceContext": {
"version": "00",
"traceId": "d745f6735b44e81c0ae5410cb1fc8a0c",
"parentId": "1b527c3828976b39",
"traceFlags": "01"
}
}
}
}",
]
`);
[
"{
message: 'test',
context: {
timestamp: '2023-05-26T00:00:00.000Z',
request: {
url: 'test',
uuid: 'test',
timeReceived: 2023-05-26T00:00:00.000Z,
traceContext: {
version: '00',
traceId: 'd745f6735b44e81c0ae5410cb1fc8a0c',
parentId: '1b527c3828976b39',
traceFlags: '01'
}
}
}
}",
]
`);
});

it('should debug proper shape of the JSON', () => {
Expand All @@ -299,28 +295,27 @@ describe('DefaultExpressServerLogger', () => {
.mockImplementation(() => {});

logger.debug('test', { request });

expect(debugSpy.mock.lastCall).toMatchInlineSnapshot(`
[
"{
"message": "test",
"context": {
"timestamp": "2023-05-26T00:00:00.000Z",
"request": {
"url": "test",
"uuid": "test",
"timeReceived": "2023-05-26T00:00:00.000Z",
"traceContext": {
"version": "00",
"traceId": "d745f6735b44e81c0ae5410cb1fc8a0c",
"parentId": "1b527c3828976b39",
"traceFlags": "01"
}
}
}
}",
]
`);
[
"{
message: 'test',
context: {
timestamp: '2023-05-26T00:00:00.000Z',
request: {
url: 'test',
uuid: 'test',
timeReceived: 2023-05-26T00:00:00.000Z,
traceContext: {
version: '00',
traceId: 'd745f6735b44e81c0ae5410cb1fc8a0c',
parentId: '1b527c3828976b39',
traceFlags: '01'
}
}
}
}",
]
`);
});

it('should stringify Error instance passed as context', () => {
Expand All @@ -331,9 +326,8 @@ describe('DefaultExpressServerLogger', () => {
const error = new Error('test error');
logger.log('test', { error });

expect(debugSpy.mock.lastCall?.[0]).not.toContain(`"error": {}`);
expect(debugSpy.mock.lastCall?.[0]).toContain(
`"error": "Error: test error` // deliberate no closing double quote, because there goes the stacktrace
`error: Error: test error`
);
});

Expand Down Expand Up @@ -365,11 +359,10 @@ describe('DefaultExpressServerLogger', () => {
});
logger.log('test', { error });

expect(debugSpy.mock.lastCall?.[0]).not.toContain(
`[cause]: { level2: { level3: [Object] } }`
);
expect(debugSpy.mock.lastCall?.[0]).toContain(
`[cause]: {\\n level2: {\\n level3: {\\n level4: {\\n level5: {\\n level6: {\\n level7: {\\n level8: { level9: { level10string: 'level10string' } }\\n }\\n }\\n }\\n }\\n }\\n }\\n }\\n}`
// Note: The "error" property is already nested within the "context" property,
// That's why effectively 9 levels of nesting inside the Error object are shown in the output
`level9: [Object]`
);
});
});
Expand Down
6 changes: 2 additions & 4 deletions core-libs/setup/ssr/logger/loggers/default-express-server-logger.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -66,11 +66,10 @@ export class DefaultExpressServerLogger implements ExpressServerLogger {
): string {
const logObject = { message, context: this.mapContext(context) };

let indentation = 0;
if (isDevMode()) {
// In dev mode, we want a *human-readable* string representation of the log object
// that can be printed in the console.
indentation = 2;
return formatWithOptions(getLoggerInspectOptions(), logObject);
}

// In prod mode, we want a *single-line* JSON which is machine-readable - easy to parse for monitoring tools.
Expand All @@ -82,8 +81,7 @@ export class DefaultExpressServerLogger implements ExpressServerLogger {
*/
(_key: string, value: any) => {
return value instanceof Error ? this.stringifyError(value) : value;
},
indentation
}
);
}

Expand Down
45 changes: 22 additions & 23 deletions core-libs/setup/ssr/optimized-engine/optimized-ssr-engine.spec.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -182,29 +182,28 @@ describe('OptimizedSsrEngine', () => {
});

expect(consoleLogSpy.mock.lastCall).toMatchInlineSnapshot(`
[
"{
"message": "[spartacus] SSR optimization engine initialized",
"context": {
"timestamp": "2023-01-01T00:00:00.000Z",
"options": {
"cacheSize": 3000,
"concurrency": 10,
"timeout": 50,
"forcedSsrTimeout": 60000,
"maxRenderTime": 300000,
"reuseCurrentRendering": true,
"renderingStrategyResolver": "() => ssr_optimization_options_1.RenderingStrategy.ALWAYS_SSR",
"logger": "DefaultExpressServerLogger",
"shouldCacheRenderingResult": "({ options, entry }) => !(options.ssrFeatureToggles?.avoidCachingErrors === true &&\\n Boolean(entry.err))",
"ssrFeatureToggles": {
"avoidCachingErrors": false
}
}
}
}",
]
`);
[
"{
message: '[spartacus] SSR optimization engine initialized',
context: {
timestamp: '2023-01-01T00:00:00.000Z',
options: {
cacheSize: 3000,
concurrency: 10,
timeout: 50,
forcedSsrTimeout: 60000,
maxRenderTime: 300000,
reuseCurrentRendering: true,
renderingStrategyResolver: '() => ssr_optimization_options_1.RenderingStrategy.ALWAYS_SSR',
logger: 'DefaultExpressServerLogger',
shouldCacheRenderingResult: '({ options, entry }) => !(options.ssrFeatureToggles?.avoidCachingErrors === true &&\\n' +
' Boolean(entry.err))',
ssrFeatureToggles: { avoidCachingErrors: false }
}
}
}",
]
`);
});
});

Expand Down

0 comments on commit 356a370

Please sign in to comment.