Chore(feature)/add request and session logs #532 (#727)

* #532 Added session and request logging to each logger message using cls * #532 Fixxed errors in unit tests * #532 Updated cls service injection * #532 Added error handling for logger * #532 Updated yarn dependencies * #532 Add condition for user.lastActiveAt if its the first login so * #532 Added await in crisp service so error is caught in async function * Update package.json Fix syntax, missing comma --------- Co-authored-by: Kylee Fields <[email protected]>
chaynHQ · Jan 13, 2025 · 7a391af · 7a391af
1 parent 8746e54
commit 7a391af
Show file tree

Hide file tree

Showing 13 changed files with 127 additions and 15 deletions.
diff --git a/docker-compose.yml b/docker-compose.yml
@@ -7,7 +7,7 @@ services:
       context: .
       dockerfile: Dockerfile
     environment:
-      DATABASE_URL: postgres://postgres:postgres@host.docker.internal:35000/bloom
+      DATABASE_URL: postgres://postgres:postgres@db:5432/bloom
     ports:
       - 35001:35001
     depends_on:

diff --git a/package.json b/package.json
@@ -47,22 +47,25 @@
     "firebase": "^10.10.0",
     "firebase-admin": "^12.2.0",
     "lodash": "^4.17.21",
+    "nestjs-cls": "^4.4.1",
     "newrelic": "^12.5.1",
     "pg": "^8.11.5",
     "pg-connection-string": "^2.7.0",
     "reflect-metadata": "^0.2.1",
     "rimraf": "^6.0.1",
     "rollbar": "^2.26.4",
     "rxjs": "^7.8.1",
+    "typeorm": "^0.3.20",
+    "uuid": "^11.0.3",
     "storyblok-js-client": "^6.10.6",
     "typeorm": "^0.3.20"
   },
   "devDependencies": {
     "@eslint/js": "^9.11.1",
     "@golevelup/ts-jest": "^0.5.0",
     "@nestjs/cli": "^10.3.2",
-    "@nestjs/testing": "^10.4.6",
     "@nestjs/schematics": "^10.2.3",
+    "@nestjs/testing": "^10.4.6",
     "@types/date-fns": "^2.6.0",
     "@types/express": "^5.0.0",
     "@types/jest": "^29.5.13",

diff --git a/src/app.module.ts b/src/app.module.ts
@@ -25,11 +25,22 @@ import { SessionModule } from './session/session.module';
 import { SubscriptionUserModule } from './subscription-user/subscription-user.module';
 import { UserModule } from './user/user.module';
 import { WebhooksModule } from './webhooks/webhooks.module';
+import { ClsModule } from 'nestjs-cls';
+import { v4 as uuidv4 } from 'uuid';
 
 @Module({
   imports: [
     ConfigModule.forRoot({ isGlobal: true }),
     TypeOrmModule.forRoot(dataSourceOptions as TypeOrmModuleOptions),
+    ClsModule.forRoot({
+      global: true,
+      middleware: {
+          mount: true,
+          generateId: true,
+          idGenerator: (req: Request) =>
+              req.headers['X-Request-Id'] ?? uuidv4(),
+      }
+    }),
     LoggerModule,
     PartnerAccessModule,
     AuthModule,

diff --git a/src/crisp/crisp.service.ts b/src/crisp/crisp.service.ts
@@ -112,7 +112,7 @@ export class CrispService {
 
   async deleteCrispProfile(email: string) {
     try {
-      CrispClient.website.removePeopleProfile(crispWebsiteId, email);
+      await CrispClient.website.removePeopleProfile(crispWebsiteId, email);
     } catch (error) {
       throw new Error(`Delete crisp profile API call failed: ${error}`);
     }

diff --git a/src/firebase/firebase-auth.guard.ts b/src/firebase/firebase-auth.guard.ts
@@ -8,11 +8,13 @@ import {
   UnauthorizedException,
 } from '@nestjs/common';
 import { Request } from 'express';
-
 import { AUTH_GUARD_ERRORS, FIREBASE_ERRORS } from 'src/utils/errors';
 import { AuthService } from '../auth/auth.service';
 import { UserService } from '../user/user.service';
 import { IFirebaseUser } from './firebase-user.interface';
+import { ClsService } from 'nestjs-cls';
+import { DecodedIdToken } from 'firebase-admin/lib/auth/token-verifier';
+import * as crypto from 'crypto';
 
 @Injectable()
 export class FirebaseAuthGuard implements CanActivate {
@@ -21,6 +23,7 @@ export class FirebaseAuthGuard implements CanActivate {
   constructor(
     private authService: AuthService,
     private userService: UserService,
+    private cls : ClsService,
   ) {}
 
   async canActivate(context: ExecutionContext): Promise<boolean> {
@@ -84,6 +87,15 @@ export class FirebaseAuthGuard implements CanActivate {
         HttpStatus.INTERNAL_SERVER_ERROR,
       );
     }
+    this.setSessionId(user);
     return true;
   }
+
+
+  private setSessionId(user :  DecodedIdToken) {
+    const uid = user.uid;
+    const authTime = user.auth_time;
+    const sessionId: string = crypto.createHash('sha256').update(`${uid}-${authTime}`).digest('hex');
+    this.cls.set('sessionId', sessionId);
+  }
 }
diff --git a/src/logger/logger.ts b/src/logger/logger.ts
@@ -3,23 +3,74 @@ import Rollbar from 'rollbar';
 import { FIREBASE_ERRORS } from 'src/utils/errors';
 import { isProduction, rollbarEnv, rollbarToken } from '../utils/constants';
 import { ErrorLog } from './utils';
+import { ClsService, ClsServiceManager } from 'nestjs-cls';
+
+interface LogMessage {
+  event: string;
+  userId: string;
+  fields?: string[];
+}
+
+interface RequestContext {
+  requestId: string;
+  sessionId: string;
+}
 
 export class Logger extends ConsoleLogger {
   private rollbar?: Rollbar;
+  private cls: ClsService;
 
   constructor(context?: string, isTimestampEnabled?) {
     super(context, isTimestampEnabled);
-
+    this.cls = ClsServiceManager.getClsService();
     this.initialiseRollbar();
   }
 
+  getRequestContext() : RequestContext
+  {
+    try{
+      return {
+        requestId: this.cls.getId(),
+        sessionId: this.cls.get('sessionId')
+      }
+    }catch{
+      console.log("Error getting request context");
+      return {
+        requestId: "not set",
+        sessionId: "not set"
+      }
+    }
+
+  }
+
+  log(message: string | LogMessage): void {
+    const formattedMessage = typeof message === 'string' ? message : JSON.stringify(message);
+    const requestContext = this.getRequestContext();
+    const decoratedMessage = `[Request ID: ${requestContext.requestId}, Session ID: ${requestContext.sessionId}] ${formattedMessage}`;
+    super.log(decoratedMessage);
+  }
+
+  warn(message: string | ErrorLog, trace?:string): void {
+    try {
+      const formattedMessage = typeof message === 'string' ? message : JSON.stringify(message);
+      const requestContext = this.getRequestContext();
+      const decoratedMessage = `[Request ID: ${requestContext.requestId}, Session ID: ${requestContext.sessionId}] ${formattedMessage}`;
+      const taggedMessage = `[warn] ${decoratedMessage}`;
+      super.warn(taggedMessage, trace);
+    }catch{
+      console.error("Error logging warning");
+    }
+  }
+
   error(message: string | ErrorLog, trace?: string): void {
     if (this.rollbar) {
       this.rollbar.error(message);
     }
     const formattedMessage = typeof message === 'string' ? message : JSON.stringify(message);
+    const requestContext = this.getRequestContext();
+    const decoratedMessage = `[Request ID: ${requestContext.requestId}, Session ID: ${requestContext.sessionId}] ${formattedMessage}`;
 
-    const taggedMessage = `[error] ${formattedMessage}`;
+    const taggedMessage = `[error] ${decoratedMessage}`;
     super.error(taggedMessage, trace);
   }
 

diff --git a/src/partner-access/partner-access.controller.spec.ts b/src/partner-access/partner-access.controller.spec.ts
@@ -1,3 +1,4 @@
+/* eslint-disable */
 import { createMock, DeepMocked } from '@golevelup/ts-jest';
 import { Test, TestingModule } from '@nestjs/testing';
 import { getRepositoryToken } from '@nestjs/typeorm';
@@ -10,6 +11,9 @@ import { UserService } from '../user/user.service';
 import { CreatePartnerAccessDto } from './dtos/create-partner-access.dto';
 import { PartnerAccessController } from './partner-access.controller';
 import { PartnerAccessService } from './partner-access.service';
+import { Logger } from '../logger/logger';
+import {mockClsService} from 'test/utils/mockedServices';
+import { ClsService } from 'nestjs-cls';
 
 const mockUserRepository = () => ({});
 
@@ -48,7 +52,8 @@ describe('PartnerAccessController', () => {
         } as unknown as PartnerAccessEntity);
       },
     };
-
+    const logger = (authGuard as any).logger as Logger;
+    (logger as any).cls = mockClsService;
     const module: TestingModule = await Test.createTestingModule({
       controllers: [PartnerAccessController],
       providers: [
@@ -59,6 +64,7 @@ describe('PartnerAccessController', () => {
           provide: getRepositoryToken(UserEntity),
           useFactory: mockUserRepository,
         },
+        {provide: ClsService, useValue: mockClsService},
       ],
     })
       .overrideGuard(PartnerAdminAuthGuard)

diff --git a/src/partner-access/partner-access.service.spec.ts b/src/partner-access/partner-access.service.spec.ts
@@ -1,3 +1,4 @@
+/* eslint-disable */
 import { createMock, DeepMocked } from '@golevelup/ts-jest';
 import { Test, TestingModule } from '@nestjs/testing';
 import { getRepositoryToken } from '@nestjs/typeorm';
@@ -17,15 +18,17 @@ import {
 import {
   mockPartnerAccessRepositoryMethods,
   mockPartnerRepositoryMethods,
+    mockClsService,
 } from 'test/utils/mockedServices';
-import { Repository } from 'typeorm';
+import {  Repository } from 'typeorm';
 import { createQueryBuilderMock } from '../../test/utils/mockUtils';
 import { PartnerAccessEntity } from '../entities/partner-access.entity';
 import { PartnerAccessCodeStatusEnum } from '../utils/constants';
 import { CreatePartnerAccessDto } from './dtos/create-partner-access.dto';
 import { GetPartnerAccessesDto } from './dtos/get-partner-access.dto';
 import { UpdatePartnerAccessDto } from './dtos/update-partner-access.dto';
 import { PartnerAccessService } from './partner-access.service';
+import {Logger} from '../logger/logger';
 
 const partnerId = 'partnerId1';
 const partnerAdminId = 'partnerAdminId1';
@@ -96,6 +99,8 @@ describe('PartnerAccessService', () => {
     }).compile();
 
     service = module.get<PartnerAccessService>(PartnerAccessService);
+    const logger = (service as any).logger as Logger;
+    (logger as any).cls = mockClsService;
     repo = module.get<Repository<PartnerAccessEntity>>(getRepositoryToken(PartnerAccessEntity));
   });
 

diff --git a/src/subscription-user/subscription-user.service.spec.ts b/src/subscription-user/subscription-user.service.spec.ts
@@ -1,3 +1,4 @@
+/* eslint-disable */
 import { DeepMocked, createMock } from '@golevelup/ts-jest/lib/mocks';
 import { Test, TestingModule } from '@nestjs/testing';
 import { getRepositoryToken } from '@nestjs/typeorm';
@@ -9,11 +10,13 @@ import { EventLoggerService } from 'src/event-logger/event-logger.service';
 import { SubscriptionService } from 'src/subscription/subscription.service';
 import { mockSubscriptionUserEntity, mockUserEntity } from 'test/utils/mockData';
 import {
+  mockClsService,
   mockSubscriptionUserRepositoryMethods,
   mockZapierWebhookClientMethods,
 } from 'test/utils/mockedServices';
 import { Repository } from 'typeorm/repository/Repository';
 import { SubscriptionUserService } from './subscription-user.service';
+import { Logger } from '@nestjs/common';
 
 describe('SubscriptionUserService', () => {
   let service: SubscriptionUserService;
@@ -58,6 +61,8 @@ describe('SubscriptionUserService', () => {
     }).compile();
 
     service = module.get<SubscriptionUserService>(SubscriptionUserService);
+    const logger = (service as any).logger as Logger;
+    (logger as any).cls = mockClsService;
   });
 
   it('should be defined', () => {

diff --git a/src/user/user.service.spec.ts b/src/user/user.service.spec.ts
@@ -26,6 +26,8 @@ import {
   mockPartnerAccessRepositoryMethods,
   mockPartnerRepositoryMethods,
   mockUserRepositoryMethodsFactory,
+  mockClsService,
+  mockUserRepositoryMethods,
 } from 'test/utils/mockedServices';
 import { Repository } from 'typeorm';
 import { createQueryBuilderMock } from '../../test/utils/mockUtils';
@@ -36,6 +38,7 @@ import { AdminUpdateUserDto } from './dtos/admin-update-user.dto';
 import { CreateUserDto } from './dtos/create-user.dto';
 import { UpdateUserDto } from './dtos/update-user.dto';
 import { UserService } from './user.service';
+import {Logger} from '../logger/logger';
 
 const createUserDto: CreateUserDto = {
   email: '[email protected]',
@@ -120,6 +123,8 @@ describe('UserService', () => {
     }).compile();
 
     service = module.get<UserService>(UserService);
+    const logger = (service as any).logger as Logger;
+    (logger as any).cls = mockClsService;
     repo = module.get<Repository<UserEntity>>(getRepositoryToken(UserEntity));
   });
 

diff --git a/src/user/user.service.ts b/src/user/user.service.ts
@@ -249,7 +249,7 @@ export class UserService {
 
     if (
       Object.keys(updateUserDto).length === 1 &&
-      !!updateUserDto.lastActiveAt &&
+      !!updateUserDto.lastActiveAt && !!user.lastActiveAt &&
       updateUserDto.lastActiveAt.getDate() === user.lastActiveAt.getDate()
     ) {
       // Do nothing, prevent unnecessay updates to service profiles when last active date is same date
@@ -302,16 +302,14 @@ export class UserService {
 
     while (startIndex < users.length) {
       const batch = users.slice(startIndex, startIndex + BATCH_SIZE);
-
       await Promise.all(
         batch.map(async (user) => {
           try {
             await this.crispService.deleteCrispProfile(user.email);
           } catch (error) {
             this.logger.warn(
               `deleteCypressTestUsers - unable to delete crisp profile for user ${user.id}`,
-              error,
-            );
+              error);
           }
           try {
             await deleteMailchimpProfile(user.email);
@@ -338,9 +336,8 @@ export class UserService {
               error,
             );
           }
-        }),
-      );
-
+        })
+      )
       startIndex += BATCH_SIZE;
       await new Promise((resolve) => setTimeout(resolve, INTERVAL)); // Wait before processing next batch
     }

diff --git a/test/utils/mockedServices.ts b/test/utils/mockedServices.ts
@@ -39,6 +39,7 @@ import {
   mockUserRecord,
 } from './mockData';
 import { createQueryBuilderMock } from './mockUtils';
+import { ClsService } from 'nestjs-cls';
 
 export const mockSlackMessageClientMethods: PartialFuncReturn<SlackMessageClient> = {
   sendMessageToTherapySlackChannel: async () => {
@@ -52,6 +53,11 @@ export const mockWebhooksServiceMethods: PartialFuncReturn<WebhooksService> = {
   },
 };
 
+export const mockClsService = {
+  getId: jest.fn().mockReturnValue('mockRequestId'),
+  get: jest.fn().mockReturnValue('mockSessionId'),
+} as Partial<jest.Mocked<ClsService>> as jest.Mocked<ClsService>;
+
 export const mockPartnerServiceMethods = {
   getPartnerById: async (arg): Promise<PartnerEntity> => {
     return { ...mockPartnerEntity, id: arg };
@@ -361,3 +367,4 @@ export const mockSubscriptionUserRepositoryMethods: PartialFuncReturn<
 };
 
 export const mockZapierWebhookClientMethods = {} as ZapierWebhookClient;
+
diff --git a/yarn.lock b/yarn.lock
@@ -5524,6 +5524,11 @@ neo-async@^2.6.2:
   resolved "https://registry.yarnpkg.com/neo-async/-/neo-async-2.6.2.tgz#b4aafb93e3aeb2d8174ca53cf163ab7d7308305f"
   integrity sha512-Yd3UES5mWCSqR+qNT93S3UoYUkqAZ9lLg8a7g9rimsWmYGK8cVToA4/sF3RrshdyV3sAGMXVUmpMYOw+dLpOuw==
 
+nestjs-cls@^4.4.1:
+  version "4.5.0"
+  resolved "https://registry.yarnpkg.com/nestjs-cls/-/nestjs-cls-4.5.0.tgz#c18914b35b808429b6974a197385aa28e11d8176"
+  integrity sha512-oi3GNCc5pnsnVI5WJKMDwmg4NP+JyEw+edlwgepyUba5+RGGtJzpbVaaxXGW1iPbDuQde3/fA8Jdjq9j88BVcQ==
+
 newrelic@^12.5.1:
   version "12.5.1"
   resolved "https://registry.yarnpkg.com/newrelic/-/newrelic-12.5.1.tgz#b1c391b15bc6c2b94e9dd02b34c45d79559bd21b"
@@ -7213,6 +7218,11 @@ uuid@^10.0.0:
   resolved "https://registry.yarnpkg.com/uuid/-/uuid-10.0.0.tgz#5a95aa454e6e002725c79055fd42aaba30ca6294"
   integrity sha512-8XkAphELsDnEGrDxUOHB3RGvXz6TeuYSGEZBOjtTtPm2lwhGBjLgOzLHB63IUWfBpNucQjND6d3AOudO+H3RWQ==
 
+uuid@^11.0.3:
+  version "11.0.3"
+  resolved "https://registry.yarnpkg.com/uuid/-/uuid-11.0.3.tgz#248451cac9d1a4a4128033e765d137e2b2c49a3d"
+  integrity sha512-d0z310fCWv5dJwnX1Y/MncBAqGMKEzlBb1AOf7z9K8ALnd0utBX/msg/fA0+sbyN1ihbMsLhrBlnl1ak7Wa0rg==
+
 uuid@^8.0.0:
   version "8.3.2"
   resolved "https://registry.yarnpkg.com/uuid/-/uuid-8.3.2.tgz#80d5b5ced271bb9af6c445f21a1a04c606cefbe2"