From abb8bec0cfc4128488e843dfa9b3ca1f2a431815 Mon Sep 17 00:00:00 2001 From: Tom Date: Wed, 12 Feb 2025 20:29:15 +0000 Subject: [PATCH] Added file/json logging. --- backend/nestjs-seshat-api/src/app.module.ts | 22 ++- .../src/auth/auth.access.service.ts | 9 ++ .../src/auth/auth.controller.ts | 135 ++++++++++++------ .../src/auth/auth.refresh.service.ts | 44 +++++- .../src/auth/strategies/jwt.strategy.ts | 1 - backend/nestjs-seshat-api/src/main.ts | 5 +- 6 files changed, 166 insertions(+), 50 deletions(-) diff --git a/backend/nestjs-seshat-api/src/app.module.ts b/backend/nestjs-seshat-api/src/app.module.ts index b0b65b8..d550cf3 100644 --- a/backend/nestjs-seshat-api/src/app.module.ts +++ b/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], diff --git a/backend/nestjs-seshat-api/src/auth/auth.access.service.ts b/backend/nestjs-seshat-api/src/auth/auth.access.service.ts index d20cd62..73cef35 100644 --- a/backend/nestjs-seshat-api/src/auth/auth.access.service.ts +++ b/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(), diff --git a/backend/nestjs-seshat-api/src/auth/auth.controller.ts b/backend/nestjs-seshat-api/src/auth/auth.controller.ts index afa3263..ea6f7b7 100644 --- a/backend/nestjs-seshat-api/src/auth/auth.controller.ts +++ b/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; - try { - 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); + 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 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, - } + }; } } \ No newline at end of file diff --git a/backend/nestjs-seshat-api/src/auth/auth.refresh.service.ts b/backend/nestjs-seshat-api/src/auth/auth.refresh.service.ts index 03ac12f..f1b9e77 100644 --- a/backend/nestjs-seshat-api/src/auth/auth.refresh.service.ts +++ b/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 + private authRefreshTokenRepository: Repository, + 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('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('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 { diff --git a/backend/nestjs-seshat-api/src/auth/strategies/jwt.strategy.ts b/backend/nestjs-seshat-api/src/auth/strategies/jwt.strategy.ts index 0a2cf93..2105a6a 100644 --- a/backend/nestjs-seshat-api/src/auth/strategies/jwt.strategy.ts +++ b/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(); diff --git a/backend/nestjs-seshat-api/src/main.ts b/backend/nestjs-seshat-api/src/main.ts index 1cd9128..c2f0de1 100644 --- a/backend/nestjs-seshat-api/src/main.ts +++ b/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();