Added file/json logging.

backend/nestjs-seshat-api/src/app.module.ts

@@ -1,13 +1,16 @@
+import pino from 'pino';
+import * as path from 'path';
 import { Module } from '@nestjs/common';
 import { AppController } from './app.controller';
 import { AppService } from './app.service';
 import { UsersService } from './users/users.service';
 import { TypeOrmModule } from '@nestjs/typeorm';
-import { ConfigModule } from '@nestjs/config';
+import { ConfigModule, ConfigService } from '@nestjs/config';
 import { DatabaseOptions } from './database-config/database.options';
 import { UsersModule } from './users/users.module';
 import { UserEntity } from './users/users.entity';
 import { AuthModule } from './auth/auth.module';
+import { LoggerModule } from 'nestjs-pino';
 
 @Module({
   imports: [
@@ -19,6 +22,23 @@ import { AuthModule } from './auth/auth.module';
     TypeOrmModule.forFeature([UserEntity]),
     UsersModule,
     AuthModule,
+    LoggerModule.forRootAsync({
+      imports: [ConfigModule],
+      inject: [ConfigService],
+      useFactory: async (config: ConfigService) => {
+        return {
+          pinoHttp: {
+            level: config.get('LOG_LEVEL') ?? 'info',
+            autoLogging: true,
+            stream: pino.destination({
+              dest: path.join(config.get('LOG_DIRECTORY') ?? 'logs', 'backend.api.log'),
+              minLength: 512,
+              sync: false,
+            }),
+          }
+        }
+      }
+    })
   ],
   controllers: [AppController],
   providers: [AppService, UsersService],

backend/nestjs-seshat-api/src/auth/auth.access.service.ts

@@ -3,12 +3,14 @@ import { Injectable } from '@nestjs/common';
 import { JwtService } from '@nestjs/jwt';
 import { UserEntity } from 'src/users/users.entity';
 import { ConfigService } from '@nestjs/config';
+import { PinoLogger } from 'nestjs-pino';
 
 @Injectable()
 export class AuthAccessService {
   constructor(
     private jwts: JwtService,
     private config: ConfigService,
+    private logger: PinoLogger,
   ) { }
 
   async generate(user: UserEntity) {
@@ -29,6 +31,13 @@ export class AuthAccessService {
       }
     );
 
+    this.logger.debug({
+      class: AuthAccessService.name,
+      method: this.generate.name,
+      user_login: user.userLogin,
+      msg: 'User generated an access token.',
+    });
+
     return {
       access_token: token,
       exp: expiration.getTime(),

backend/nestjs-seshat-api/src/auth/auth.controller.ts

@@ -8,10 +8,16 @@ import { JwtRefreshGuard } from './guards/jwt-refresh.guard';
 import { OfflineGuard } from './guards/offline.guard';
 import { UserEntity } from 'src/users/users.entity';
 import { QueryFailedError } from 'typeorm';
+import { PinoLogger } from 'nestjs-pino';
+import { JwtAccessGuard } from './guards/jwt-access.guard';
 
 @Controller('auth')
 export class AuthController {
-  constructor(private auth: AuthService, private users: UsersService) { }
+  constructor(
+    private auth: AuthService,
+    private users: UsersService,
+    private logger: PinoLogger,
+  ) { }
 
   @UseGuards(LoginAuthGuard)
   @Post('login')
@@ -19,57 +25,53 @@ export class AuthController {
     @Request() req,
     @Res({ passthrough: true }) response: Response,
   ) {
+    let data: AuthenticationDto | null;
     try {
-      let data: AuthenticationDto | null;
+      data = await this.auth.login(req.user);
-      try {
+      if (!data.access_token || !data.refresh_token || !data.refresh_exp) {
-        data = await this.auth.login(req.user);
-        if (!data.access_token || !data.refresh_token || !data.refresh_exp) {
-          return {
-            success: false,
-            error_message: 'Something went wrong with tokens while logging in.',
-          };
-        }
-      } catch (err) {
-        if (err instanceof QueryFailedError) {
-          if (err.message.includes('duplicate key value violates unique constraint "users_user_login_key"')) {
-            return {
-              success: false,
-              error_message: 'Username already exist.',
-            };
-          }
-        }
-        console.log('AuthController', typeof err, err);
         return {
           success: false,
-          error_message: 'Something went wrong while logging in.',
+          error_message: 'Something went wrong with tokens while logging in.',
         };
       }
-  
-      response.cookie('Authentication', data.access_token, {
-        httpOnly: true,
-        secure: true,
-        expires: new Date(data.exp),
-      });
-  
-      response.cookie('Refresh', data.refresh_token, {
-        httpOnly: true,
-        secure: true,
-        expires: new Date(data.refresh_exp),
-      });
-  
-      return {
-        success: true,
-      };
     } catch (err) {
-      console.log(err);
+      this.logger.error({
+        class: AuthController.name,
+        method: this.login.name,
+        msg: 'Failed to login.',
+        error: err,
+      });
       return {
         success: false,
-        error_message: 'Something went wrong.',
+        error_message: 'Something went wrong while logging in.',
       };
     }
+
+    response.cookie('Authentication', data.access_token, {
+      httpOnly: true,
+      secure: true,
+      expires: new Date(data.exp),
+    });
+
+    response.cookie('Refresh', data.refresh_token, {
+      httpOnly: true,
+      secure: true,
+      expires: new Date(data.refresh_exp),
+    });
+
+    this.logger.info({
+      class: AuthController.name,
+      method: this.login.name,
+      user_login: req.user.userLogin,
+      msg: 'User logged in.',
+    });
+
+    return {
+      success: true,
+    };
   }
 
-  @UseGuards(LoginAuthGuard)
+  @UseGuards(JwtAccessGuard)
   @Post('logout')
   async logout(
     @Request() req,
@@ -81,7 +83,14 @@ export class AuthController {
 
     response.clearCookie('Refresh');
     response.clearCookie('Authentication');
-    
+
+    this.logger.info({
+      class: AuthController.name,
+      method: this.logout.name,
+      user_login: req.user.userLogin,
+      msg: 'User logged off',
+    });
+
     return req.logout();
   }
 
@@ -100,6 +109,11 @@ export class AuthController {
         secure: true,
         expires: new Date(data.exp),
       });
+      this.logger.debug({
+        class: AuthController.name,
+        method: this.refresh.name,
+        msg: 'Updated Authentication cookie for access token.',
+      });
 
       if (data.refresh_token != refresh_token) {
         response.cookie('Refresh', data.refresh_token, {
@@ -107,11 +121,21 @@ export class AuthController {
           secure: true,
           expires: new Date(data.refresh_exp),
         });
+        this.logger.debug({
+          class: AuthController.name,
+          method: this.refresh.name,
+          msg: 'Updated Refresh cookie for refresh token.',
+        });
       }
 
       return { success: true };
     } catch (err) {
-      console.log(err);
+      this.logger.error({
+        class: AuthController.name,
+        method: this.refresh.name,
+        msg: 'Failed to refresh tokens.',
+        error: err,
+      });
       return {
         success: false,
         error_message: 'Something went wrong.',
@@ -131,16 +155,32 @@ export class AuthController {
     try {
       const { user_login, user_name, password } = body;
       user = await this.users.register(user_login.toLowerCase(), user_name, password, true);
+      this.logger.info({
+        class: AuthController.name,
+        method: this.register.name,
+        user_login: user.userLogin,
+        msg: 'User registered',
+      });
     } catch (err) {
       if (err instanceof QueryFailedError) {
         if (err.message.includes('duplicate key value violates unique constraint "users_user_login_key"')) {
+          this.logger.warn({
+            class: AuthController.name,
+            method: this.register.name,
+            msg: 'Failed to register due to duplicate userLogin.',
+          });
           return {
             success: false,
             error_message: 'Username already exist.',
           };
         }
       }
-      console.log('AuthController', err);
+      this.logger.error({
+        class: AuthController.name,
+        method: this.register.name,
+        msg: 'Failed to register.',
+        error: err,
+      });
       return {
         success: false,
         error_message: 'Something went wrong when creating user.',
@@ -156,7 +196,12 @@ export class AuthController {
         };
       }
     } catch (err) {
-      console.log('AuthController', err);
+      this.logger.error({
+        class: AuthController.name,
+        method: this.register.name,
+        msg: 'Failed to login after registering.',
+        error: err,
+      });
       return {
         success: false,
         error_message: 'Something went wrong while logging in.',
@@ -177,6 +222,6 @@ export class AuthController {
 
     return {
       success: true,
-    }
+    };
   }
 }

backend/nestjs-seshat-api/src/auth/auth.refresh.service.ts

@@ -8,6 +8,7 @@ import { UUID } from 'crypto';
 import { UserEntity } from 'src/users/users.entity';
 import { Repository } from 'typeorm';
 import { AuthRefreshTokenEntity } from './entities/auth.refresh-token.entity';
+import { PinoLogger } from 'nestjs-pino';
 
 @Injectable()
 export class AuthRefreshService {
@@ -15,7 +16,8 @@ export class AuthRefreshService {
     private jwts: JwtService,
     private config: ConfigService,
     @InjectRepository(AuthRefreshTokenEntity)
-    private authRefreshTokenRepository: Repository<AuthRefreshTokenEntity>
+    private authRefreshTokenRepository: Repository<AuthRefreshTokenEntity>,
+    private logger: PinoLogger,
   ) { }
 
 
@@ -23,7 +25,20 @@ export class AuthRefreshService {
     let expiration: Date | null = null;
     if (refreshToken) {
       const token = await this.get(refreshToken, user.userId);
+      if (!token) {
+        this.logger.warn({
+          class: AuthRefreshService.name,
+          method: this.generate.name,
+          msg: 'Refresh token given is invalid.',
+        });
+        throw new UnauthorizedException('Invalid refresh token.');
+      }
       if (token.exp.getTime() > new Date().getTime()) {
+        this.logger.warn({
+          class: AuthRefreshService.name,
+          method: this.generate.name,
+          msg: 'Refresh token given has expired.',
+        });
         throw new UnauthorizedException('Invalid refresh token.');
       }
 
@@ -36,7 +51,20 @@ export class AuthRefreshService {
     //  - token has expired.
     const now = new Date();
     const threshhold = parseInt(this.config.getOrThrow<string>('AUTH_JWT_REFRESH_TOKEN_EXPIRATION_THRESHHOLD_MS'));
-    if (!refreshToken || !expiration || now.getTime() - expiration.getTime() > threshhold) {
+    if (!refreshToken || now.getTime() - expiration.getTime() > threshhold) {
+      if (refreshToken) {
+        this.authRefreshTokenRepository.delete({
+          tokenHash: refreshToken,
+          userId: user.userId,
+        });
+
+        this.logger.debug({
+          class: AuthRefreshService.name,
+          method: this.generate.name,
+          msg: 'Deleted previous refresh token.',
+        });
+      }
+
       const limit = parseInt(this.config.getOrThrow<string>('AUTH_JWT_REFRESH_TOKEN_EXPIRATION_MS'));
       expiration = moment(now).add(limit, 'ms').toDate();
       refreshToken = await this.jwts.signAsync(
@@ -52,11 +80,23 @@ export class AuthRefreshService {
         }
       );
 
+      this.logger.debug({
+        class: AuthRefreshService.name,
+        method: this.generate.name,
+        msg: 'Generated a new refresh token.',
+      });
+
       this.authRefreshTokenRepository.insert({
         tokenHash: refreshToken,
         userId: user.userId,
         exp: expiration
       });
+
+      this.logger.debug({
+        class: AuthRefreshService.name,
+        method: this.generate.name,
+        msg: 'Inserted the new refresh token.',
+      });
     }
 
     return {

backend/nestjs-seshat-api/src/auth/strategies/jwt.strategy.ts

@@ -19,7 +19,6 @@ export class JwtStrategy extends PassportStrategy(Strategy, 'jwt') {
   }
 
   async validate(req: Request, payload: any) {
-    console.log('jwt payload', payload);
     const user = await this.users.findById(payload.sub);
     if (!user) {
       throw new UnauthorizedException();

backend/nestjs-seshat-api/src/main.ts

@@ -2,15 +2,18 @@ import * as cookieParser from 'cookie-parser';
 import { NestFactory } from '@nestjs/core';
 import { AppModule } from './app.module';
 import { ValidationPipe } from '@nestjs/common';
+import { Logger, LoggerErrorInterceptor } from 'nestjs-pino';
 
 async function bootstrap() {
-  const app = await NestFactory.create(AppModule);
+  const app = await NestFactory.create(AppModule, { bufferLogs: true });
   app.use(cookieParser());
   app.useGlobalPipes(new ValidationPipe({
     stopAtFirstError: true,
     whitelist: true,
     transform: true,
   }));
+  app.useLogger(app.get(Logger));
+  app.useGlobalInterceptors(new LoggerErrorInterceptor());
   await app.listen(process.env.PORT ?? 3001);
 }
 bootstrap();