fix(timer): also works with ecs fields

AUT-2249

Co-authored-by: Daniel Gergacz <[email protected]>

Author: akapa

package.json

@@ -28,6 +28,7 @@
   ],
   "devDependencies": {
     "@types/chai": "4.3.3",
+    "@types/lodash": "4.14.198",
     "@types/mocha": "10.0.0",
     "@types/node": "18.7.23",
     "@types/sinon": "10.0.13",
@@ -59,5 +60,8 @@
   "bugs": {
     "url": "https://github.com/emartech/json-logger-js/issues"
   },
-  "homepage": "https://github.com/emartech/json-logger-js#readme"
+  "homepage": "https://github.com/emartech/json-logger-js#readme",
+  "dependencies": {
+    "lodash": "4.17.21"
+  }
 }

src/logger/logger.spec.ts

@@ -65,15 +65,15 @@ describe('Logger', () => {
     expect(Logger.config.output).not.to.have.been.called;
   });
 
-  it('should not call log info method when disabled', () => {
+  it('should not call log info method when disabled (timer)', () => {
     logger = new Logger('mongo', false);
     const timer = logger.timer();
     const infoStub = sinon.stub(logger, 'info');
 
     clock.tick(100);
     timer.info('hi');
 
-    expect(infoStub).to.have.been.calledWith('hi', { duration: 100 });
+    expect(infoStub).to.have.been.calledWith('hi', { event: { duration: 100 } });
   });
 
   it('should log error with action (legacy format)', () => {

src/timer/timer.spec.ts

@@ -12,40 +12,95 @@ describe('Timer', () => {
 
   afterEach(() => {
     clock.restore();
+    Logger.configure({ outputFormat: 'ecs' });
   });
 
-  it('should log elapsed time', () => {
-    const logger = new Logger('test', false);
-    const infoStub = stub(logger, 'info');
-    const timer = new Timer(logger);
+  describe('legacy format', () => {
+    beforeEach(() => {
+      Logger.configure({ outputFormat: 'legacy' });
+    });
 
-    clock.tick(100);
-    timer.info('time', { customer_id: 10 });
+    it('should log elapsed time (legacy format)', () => {
+      const logger = new Logger('test', false);
+      const infoStub = stub(logger, 'info');
+      const timer = new Timer(logger);
 
-    expect(infoStub).to.have.been.calledWith('time', { customer_id: 10, duration: 100 });
-  });
+      clock.tick(100);
+      timer.info('time', { customer_id: 10 });
+
+      expect(infoStub).to.have.been.calledWith('time', { customer_id: 10, duration: 100 });
+    });
+
+    it('should log elapsed time with error', () => {
+      const logger = new Logger('test', false);
+      const errorStub = stub(logger, 'fromError');
+      const timer = new Timer(logger);
+      const error = new Error('intended');
+
+      clock.tick(100);
+      timer.fromError('time', error, { customer_id: 10 });
 
-  it('should log elapsed time with error', () => {
-    const logger = new Logger('test', false);
-    const errorStub = stub(logger, 'fromError');
-    const timer = new Timer(logger);
-    const error = new Error('intended');
+      expect(errorStub).to.have.been.calledWith('time', error, { customer_id: 10, duration: 100 });
+    });
 
-    clock.tick(100);
-    timer.fromError('time', error, { customer_id: 10 });
+    it('should log elapsed time with error', () => {
+      const logger = new Logger('test', false);
+      const errorStub = stub(logger, 'warnFromError');
+      const timer = new Timer(logger);
+      const error = new Error('intended');
 
-    expect(errorStub).to.have.been.calledWith('time', error, { customer_id: 10, duration: 100 });
+      clock.tick(100);
+      timer.warnFromError('time', error, { customer_id: 10 });
+
+      expect(errorStub).to.have.been.calledWith('time', error, { customer_id: 10, duration: 100 });
+    });
   });
 
-  it('should log elapsed time with error', () => {
-    const logger = new Logger('test', false);
-    const errorStub = stub(logger, 'warnFromError');
-    const timer = new Timer(logger);
-    const error = new Error('intended');
+  describe('ecs format', () => {
+    it('should log elapsed time (legacy format)', () => {
+      const logger = new Logger('test', false);
+      const infoStub = stub(logger, 'info');
+      const timer = new Timer(logger);
+
+      clock.tick(100);
+      timer.info('time', { customer_id: 10 });
+
+      expect(infoStub).to.have.been.calledWith('time', { customer_id: 10, event: { duration: 100 } });
+    });
+
+    it('should log elapsed time with error', () => {
+      const logger = new Logger('test', false);
+      const errorStub = stub(logger, 'fromError');
+      const timer = new Timer(logger);
+      const error = new Error('intended');
+
+      clock.tick(100);
+      timer.fromError('time', error, { customer_id: 10 });
+
+      expect(errorStub).to.have.been.calledWith('time', error, { customer_id: 10, event: { duration: 100 } });
+    });
+
+    it('should log elapsed time with error', () => {
+      const logger = new Logger('test', false);
+      const errorStub = stub(logger, 'warnFromError');
+      const timer = new Timer(logger);
+      const error = new Error('intended');
+
+      clock.tick(100);
+      timer.warnFromError('time', error, { customer_id: 10 });
+
+      expect(errorStub).to.have.been.calledWith('time', error, { customer_id: 10, event: { duration: 100 } });
+    });
+
+    it('should not overwrite ecs fields', () => {
+      const logger = new Logger('test', false);
+      const logStub = stub(logger, 'warn');
+      const timer = new Timer(logger);
 
-    clock.tick(100);
-    timer.warnFromError('time', error, { customer_id: 10 });
+      clock.tick(100);
+      timer.warn('time', { event: { majomkutya: 1 } });
 
-    expect(errorStub).to.have.been.calledWith('time', error, { customer_id: 10, duration: 100 });
+      expect(logStub).to.have.been.calledWith('time', { event: { duration: 100, majomkutya: 1 } });
+    });
   });
 });

src/timer/timer.ts

@@ -1,4 +1,5 @@
 import { Logger } from '../logger/logger';
+import { merge } from 'lodash';
 
 export class Timer {
   private readonly start: number;
@@ -10,35 +11,43 @@ export class Timer {
   }
 
   trace(action: string, data: unknown = {}) {
-    this.logger.trace(action, Object.assign({ duration: this.duration() }, data));
+    this.logger.trace(action, this.getData(data));
   }
 
   debug(action: string, data: unknown = {}) {
-    this.logger.debug(action, Object.assign({ duration: this.duration() }, data));
+    this.logger.debug(action, this.getData(data));
   }
 
   info(action: string, data: unknown = {}) {
-    this.logger.info(action, Object.assign({ duration: this.duration() }, data));
+    this.logger.info(action, this.getData(data));
   }
 
   warn(action: string, data: unknown = {}) {
-    this.logger.warn(action, Object.assign({ duration: this.duration() }, data));
+    this.logger.warn(action, this.getData(data));
   }
 
   error(action: string, data: unknown = {}) {
-    this.logger.error(action, Object.assign({ duration: this.duration() }, data));
+    this.logger.error(action, this.getData(data));
   }
 
   fatal(action: string, data: unknown = {}) {
-    this.logger.fatal(action, Object.assign({ duration: this.duration() }, data));
+    this.logger.fatal(action, this.getData(data));
   }
 
   fromError(action: string, error: unknown, data: unknown = {}) {
-    this.logger.fromError(action, error, Object.assign({ duration: this.duration() }, data));
+    this.logger.fromError(action, error, this.getData(data));
   }
 
   warnFromError(action: string, error: unknown, data: unknown = {}) {
-    this.logger.warnFromError(action, error, Object.assign({ duration: this.duration() }, data));
+    this.logger.warnFromError(action, error, this.getData(data));
+  }
+
+  private getData(data: unknown): Record<string, any> {
+    if (Logger.config.outputFormat === 'legacy') {
+      return Object.assign({ duration: this.duration() }, data);
+    }
+
+    return merge({ event: { duration: this.duration() } }, data);
   }
 
   private duration(): number {