@squiz/component-logger-lib - npm Package Compare versions

Comparing version 1.70.0 to 1.71.0

CHANGELOG.md

 # @squiz/component-logger-lib
 
+## 1.71.0
+
+### Minor Changes
+
+- 0d445ab: Avoid waiting for logging request to complete, parallelize more work when saving a content page.
+
+### Patch Changes
+
+- 0d445ab: Added spans to more easily identify different portions of the request which relate to saving a content page
+
 ## 1.70.0
@@ -4,0 +14,0 @@

jest.integration.config.ts

 import type { Config } from 'jest';
 import { config as dotEnvConfig } from 'dotenv';
+import { defaultIntegrationConfig } from '../../jest.config';
 
@@ -8,6 +9,3 @@ dotEnvConfig();
 const config: Config = {
-  preset: 'ts-jest',
-  testTimeout: 60_000,
-  testEnvironment: 'node',
-  testRegex: '.*\\.integration\\.spec\\.ts$',
+  ...defaultIntegrationConfig,
   maxWorkers: 1,
@@ -14,0 +12,0 @@ };

lib/component-logger.d.ts

 import { ComponentLogLevel } from './component-log-message';
 import { ComponentLoggerConfig } from './component-logger-config';
+export declare const MAX_MESSAGE_LENGTH = 200000;
 export declare const MAX_TAG_LENGTH = 200;
 export declare class ComponentLogger {
-    readonly config: ComponentLoggerConfig;
+    private readonly config;
     private batch;
@@ -14,3 +15,4 @@ constructor(config: ComponentLoggerConfig);
     private cleanTags;
-    flush(): Promise<void>;
+    flush(background?: boolean): Promise<void>;
+    private flushInternal;
 }

lib/component-logger.integration.spec.js

@@ -5,3 +5,3 @@ "use strict";
 const _1 = require(".");
-describe('ComponentLogger', () => {
+describe.skip('ComponentLogger', () => {
     it('should sending log messages', async () => {
@@ -8,0 +8,0 @@ const logger = await (0, _1.getComponentLogger)({

lib/component-logger.js

@@ -6,6 +6,9 @@ "use strict";
 Object.defineProperty(exports, "__esModule", { value: true });
-exports.ComponentLogger = exports.MAX_TAG_LENGTH = void 0;
+exports.ComponentLogger = exports.MAX_TAG_LENGTH = exports.MAX_MESSAGE_LENGTH = void 0;
 const superagent_1 = __importDefault(require("superagent"));
+const api_1 = require("@opentelemetry/api");
 const MESSAGE_BATCH_SIZE = 100;
+exports.MAX_MESSAGE_LENGTH = 200000;
 exports.MAX_TAG_LENGTH = 200;
+const tracer = api_1.trace.getTracer('component-logger-lib:ComponentLogger');
 class ComponentLogger {
@@ -46,3 +49,3 @@ constructor(config) {
             timestamp: new Date().toISOString(),
-            message: payload,
+            message: payload.slice(0, exports.MAX_MESSAGE_LENGTH),
             traceid: traceId,
@@ -74,4 +77,20 @@ userid: userId,
     }
-    async flush() {
-        if (this.config.enabled && this.batch.length > 0) {
+    async flush(background = true) {
+        const promise = this.flushInternal();
+        // avoid holding up requests by default, don't await completion.
+        if (!background) {
+            await promise;
+        }
+    }
+    async flushInternal() {
+        if (!this.config.enabled || this.batch.length === 0) {
+            return;
+        }
+        return tracer.startActiveSpan('flush', {
+            attributes: {
+                'batch.length': this.batch.length,
+            },
+        }, async (span) => {
+            const logs = this.batch;
+            this.batch = [];
             try {
@@ -85,9 +104,12 @@ const url = `${this.config.logUrl.replace(/\/+$/, '')}`;
                 })
-                    .send(this.batch);
-                this.batch = [];
+                    .send(logs);
             }
             catch (err) {
+                this.batch.push(...logs);
                 console.error(err);
             }
-        }
+            finally {
+                span.end();
+            }
+        });
     }
@@ -94,0 +116,0 @@ }

lib/component-logger.spec.js

@@ -8,2 +8,3 @@ "use strict";
 const superagent_1 = __importDefault(require("superagent"));
+const timers_1 = require("timers");
 const postSetMock = {
@@ -336,2 +337,13 @@ send: jest.fn(),
     });
+    it('should truncate long messages', async () => {
+        const logger = new component_logger_1.ComponentLogger(loggerConfig);
+        const message = 'a'.repeat(component_logger_1.MAX_MESSAGE_LENGTH + 1);
+        await logger.info(message);
+        await logger.flush();
+        expect(postSetMock.send).toHaveBeenCalledWith([
+            expect.objectContaining({
+                message: message.slice(0, -1),
+            }),
+        ]);
+    });
     it('should not throw error if logging API fails', async () => {
@@ -351,3 +363,59 @@ const loggerConfig = {
     });
+    it.each([
+        ['background flush', true, ['flush resolved']],
+        ['foreground flush', false, ['send resolved', 'flush resolved']],
+    ])('should not await the promise if flush is performed in the background - %s', async (description, background, expectedResolveSequence) => {
+        const resolveSequence = [];
+        const resolver = jest.fn();
+        postSetMock.send.mockImplementation(async () => {
+            return new Promise((resolve) => {
+                resolver.mockImplementation(() => {
+                    resolveSequence.push('send resolved');
+                    resolve(null);
+                });
+            });
+        });
+        const logger = new component_logger_1.ComponentLogger(loggerConfig);
+        await logger.error('error message');
+        const flushPromise = logger.flush(background).then(() => resolveSequence.push('flush resolved'));
+        (0, timers_1.setImmediate)(() => {
+            resolver();
+        });
+        await flushPromise;
+        expect(resolveSequence).toEqual(expectedResolveSequence);
+    });
+    it('should not flush the same log entry multiple times if called concurrently', async () => {
+        const logger = new component_logger_1.ComponentLogger(loggerConfig);
+        const resolvers = [];
+        postSetMock.send.mockImplementation(async () => {
+            return new Promise((resolve) => {
+                resolvers.push(() => {
+                    resolve(null);
+                });
+            });
+        });
+        await logger.error('error message 1');
+        await logger.flush();
+        await logger.error('error message 2');
+        await logger.flush();
+        resolvers.map((resolver) => resolver());
+        expect(postSetMock.send).toHaveBeenCalledTimes(2);
+        expect(postSetMock.send).toHaveBeenCalledWith([expect.objectContaining({ message: 'error message 1' })]);
+        expect(postSetMock.send).toHaveBeenCalledWith([expect.objectContaining({ message: 'error message 2' })]);
+    });
+    it('should flush logs on next attempt if they failed to flush', async () => {
+        const logger = new component_logger_1.ComponentLogger(loggerConfig);
+        postSetMock.send.mockRejectedValueOnce(new Error('Log submission failed.')).mockResolvedValue(postSetMock);
+        await logger.error('error message 1');
+        await logger.flush();
+        await logger.error('error message 2');
+        await logger.flush();
+        expect(postSetMock.send).toHaveBeenCalledTimes(2);
+        expect(postSetMock.send).toHaveBeenCalledWith([expect.objectContaining({ message: 'error message 1' })]);
+        expect(postSetMock.send).toHaveBeenCalledWith([
+            expect.objectContaining({ message: 'error message 1' }),
+            expect.objectContaining({ message: 'error message 2' }),
+        ]);
+    });
 });
 //# sourceMappingURL=component-logger.spec.js.map

package.json

 {
   "name": "@squiz/component-logger-lib",
-  "version": "1.70.0",
+  "version": "1.71.0",
   "description": "",
@@ -18,2 +18,3 @@ "main": "lib/index.js",
   "dependencies": {
+    "@opentelemetry/api": "^1.6.0",
     "superagent": "^8.0.9"
@@ -23,8 +24,8 @@ },
     "@squiz/dx-common-lib": "^1.64.0",
-    "@types/node": "20.12.4",
+    "@types/node": "20.12.12",
     "dotenv": "^16.0.3",
     "jest": "29.4.1",
     "ts-jest": "29.0.5",
-    "ts-node": "10.9.1"
+    "ts-node": "10.9.2"
   }
 }

src/component-logger.integration.spec.ts

 import { parseEnvVarForVar } from '@squiz/dx-common-lib';
 import { getComponentLogger } from '.';
 
-describe('ComponentLogger', () => {
+describe.skip('ComponentLogger', () => {
   it('should sending log messages', async () => {
@@ -6,0 +6,0 @@ const logger = await getComponentLogger({

src/component-logger.spec.ts

@@ -1,4 +0,5 @@
-import { ComponentLogger, MAX_TAG_LENGTH } from './component-logger';
+import { ComponentLogger, MAX_MESSAGE_LENGTH, MAX_TAG_LENGTH } from './component-logger';
 import { ComponentLoggerConfig } from './component-logger-config';
 import superagent from 'superagent';
+import { setImmediate } from 'timers';
 
@@ -389,2 +390,16 @@ const postSetMock = {
 
+  it('should truncate long messages', async () => {
+    const logger = new ComponentLogger(loggerConfig);
+    const message = 'a'.repeat(MAX_MESSAGE_LENGTH + 1);
+
+    await logger.info(message);
+    await logger.flush();
+
+    expect(postSetMock.send).toHaveBeenCalledWith([
+      expect.objectContaining({
+        message: message.slice(0, -1),
+      }),
+    ]);
+  });
+
   it('should not throw error if logging API fails', async () => {
@@ -406,2 +421,74 @@ const loggerConfig = <ComponentLoggerConfig>{
   });
+
+  it.each([
+    ['background flush', true, ['flush resolved']],
+    ['foreground flush', false, ['send resolved', 'flush resolved']],
+  ])(
+    'should not await the promise if flush is performed in the background - %s',
+    async (description: string, background: boolean, expectedResolveSequence: string[]) => {
+      const resolveSequence: string[] = [];
+      const resolver = jest.fn();
+
+      postSetMock.send.mockImplementation(async () => {
+        return new Promise((resolve) => {
+          resolver.mockImplementation(() => {
+            resolveSequence.push('send resolved');
+            resolve(null);
+          });
+        });
+      });
+
+      const logger = new ComponentLogger(loggerConfig);
+      await logger.error('error message');
+      const flushPromise = logger.flush(background).then(() => resolveSequence.push('flush resolved'));
+
+      setImmediate(() => {
+        resolver();
+      });
+      await flushPromise;
+
+      expect(resolveSequence).toEqual(expectedResolveSequence);
+    },
+  );
+
+  it('should not flush the same log entry multiple times if called concurrently', async () => {
+    const logger = new ComponentLogger(loggerConfig);
+    const resolvers: (() => void)[] = [];
+
+    postSetMock.send.mockImplementation(async () => {
+      return new Promise((resolve) => {
+        resolvers.push(() => {
+          resolve(null);
+        });
+      });
+    });
+
+    await logger.error('error message 1');
+    await logger.flush();
+    await logger.error('error message 2');
+    await logger.flush();
+    resolvers.map((resolver) => resolver());
+
+    expect(postSetMock.send).toHaveBeenCalledTimes(2);
+    expect(postSetMock.send).toHaveBeenCalledWith([expect.objectContaining({ message: 'error message 1' })]);
+    expect(postSetMock.send).toHaveBeenCalledWith([expect.objectContaining({ message: 'error message 2' })]);
+  });
+
+  it('should flush logs on next attempt if they failed to flush', async () => {
+    const logger = new ComponentLogger(loggerConfig);
+
+    postSetMock.send.mockRejectedValueOnce(new Error('Log submission failed.')).mockResolvedValue(postSetMock);
+
+    await logger.error('error message 1');
+    await logger.flush();
+    await logger.error('error message 2');
+    await logger.flush();
+
+    expect(postSetMock.send).toHaveBeenCalledTimes(2);
+    expect(postSetMock.send).toHaveBeenCalledWith([expect.objectContaining({ message: 'error message 1' })]);
+    expect(postSetMock.send).toHaveBeenCalledWith([
+      expect.objectContaining({ message: 'error message 1' }),
+      expect.objectContaining({ message: 'error message 2' }),
+    ]);
+  });
 });

src/component-logger.ts

 import superagent from 'superagent';
 import { ComponentLogLevel, ComponentLogMessage } from './component-log-message';
 import { ComponentLoggerConfig } from './component-logger-config';
+import { trace } from '@opentelemetry/api';
 
 const MESSAGE_BATCH_SIZE = 100;
+export const MAX_MESSAGE_LENGTH = 200000;
 export const MAX_TAG_LENGTH = 200;
+const tracer = trace.getTracer('component-logger-lib:ComponentLogger');
 
@@ -11,3 +14,3 @@ export class ComponentLogger {
 
-  constructor(readonly config: ComponentLoggerConfig) {
+  constructor(private readonly config: ComponentLoggerConfig) {
     if (config.enabled) {
@@ -54,3 +57,3 @@ if (!config.logUrl) {
       timestamp: new Date().toISOString(),
-      message: payload,
+      message: payload.slice(0, MAX_MESSAGE_LENGTH),
       traceid: traceId,
@@ -85,19 +88,45 @@ userid: userId,
 
-  async flush(): Promise<void> {
-    if (this.config.enabled && this.batch.length > 0) {
-      try {
-        const url = `${this.config.logUrl.replace(/\/+$/, '')}`;
-        await superagent
-          .post(url)
-          .set({
-            'x-dxp-tenant': this.config.tenantId,
-            'x-api-key': this.config.key,
-          })
-          .send(this.batch);
-        this.batch = [];
-      } catch (err) {
-        console.error(err);
-      }
+  async flush(background: boolean = true): Promise<void> {
+    const promise = this.flushInternal();
+
+    // avoid holding up requests by default, don't await completion.
+    if (!background) {
+      await promise;
     }
   }
+
+  private async flushInternal(): Promise<void> {
+    if (!this.config.enabled || this.batch.length === 0) {
+      return;
+    }
+
+    return tracer.startActiveSpan(
+      'flush',
+      {
+        attributes: {
+          'batch.length': this.batch.length,
+        },
+      },
+      async (span) => {
+        const logs = this.batch;
+        this.batch = [];
+
+        try {
+          const url = `${this.config.logUrl.replace(/\/+$/, '')}`;
+          await superagent
+            .post(url)
+            .set({
+              'x-dxp-tenant': this.config.tenantId,
+              'x-api-key': this.config.key,
+            })
+            .send(logs);
+        } catch (err) {
+          this.batch.push(...logs);
+          console.error(err);
+        } finally {
+          span.end();
+        }
+      },
+    );
+  }
 }

New alerts

License Policy Violation

License

This package is not allowed per your license policy. Review the package's license to ensure compliance.

Found 1 instance in 1 package

Fixed alerts

License Policy Violation

License

This package is not allowed per your license policy. Review the package's license to ensure compliance.

Found 1 instance in 1 package

Improved metrics

Lines of code

1364

increased by15.79%

Worsened metrics

Total package byte prevSize

157993

decreased by-9.96%

Dependency count

2

increased by100%

Dependency changes

• + Added@opentelemetry/api@^1.6.0

• + Added@opentelemetry/api@1.9.0(transitive)