diff --git a/api/src/routes/auth.ts b/api/src/routes/auth.ts index 0c7724a..e892ed8 100644 --- a/api/src/routes/auth.ts +++ b/api/src/routes/auth.ts @@ -13,6 +13,8 @@ import { MemberState } from '@app/shared/types/member'; import { toDateTime } from '@app/shared/utils/time'; import { logger } from '../services/logging/logger'; const querystring = require('querystring'); +import { performance } from 'perf_hooks'; + function parseJwt(token) { return JSON.parse(Buffer.from(token.split('.')[1], 'base64').toString()); @@ -179,28 +181,75 @@ passport.serializeUser(function (user, cb) { }); passport.deserializeUser(function (user, cb) { + const start = performance.now(); + const timings: Record = {}; + process.nextTick(async function () { - const memberID = user.memberId as number; + let con; - - var userData: { id: number, name: string, roles: Role[], state: MemberState }; try { - var con = await pool.getConnection(); - let userResults = await con.query(`SELECT id, name FROM members WHERE id = ?;`, [memberID]) - userData = userResults[0]; - let userRoles = await getUserRoles(memberID); + let t; + + t = performance.now(); + con = await pool.getConnection(); + timings.getConnection = performance.now() - t; + + t = performance.now(); + const userResults = await con.query( + `SELECT id, name FROM members WHERE id = ?;`, + [memberID] + ); + timings.memberQuery = performance.now() - t; + + const userData: { + id: number; + name: string; + roles: Role[]; + state: MemberState; + } = userResults[0]; + + t = performance.now(); + const userRoles = await getUserRoles(memberID); + timings.roles = performance.now() - t; userData.roles = userRoles || []; + + t = performance.now(); userData.state = await getUserState(memberID); + timings.state = performance.now() - t; + + // 📊 PROFILING LOG + logger.info( + 'profiling', + 'passport.deserializeUser completed', + { + memberId: memberID, + total_ms: performance.now() - start, + breakdown_ms: timings, + }, + 'profiling' + ); + + return cb(null, userData); + } catch (error) { - console.error(error) + logger.error( + 'profiling', + 'passport.deserializeUser failed', + { + memberId: memberID, + error: error instanceof Error ? error.message : String(error), + } + ); + return cb(error); + } finally { - con.release(); + if (con) con.release(); } - return cb(null, userData); }); }); + declare global { namespace Express { interface Request { diff --git a/api/src/routes/members.ts b/api/src/routes/members.ts index 1bad565..4f590d2 100644 --- a/api/src/routes/members.ts +++ b/api/src/routes/members.ts @@ -9,6 +9,9 @@ import { getAllMembersLite, getMemberSettings, getMembersFull, getMembersLite, g import { getUserRoles } from '../services/db/rolesService'; import { memberSettings, MemberState, myData } from '@app/shared/types/member'; +import { Performance } from 'perf_hooks'; +import { logger } from '../services/logging/logger'; + //get all users router.get('/', [requireLogin, requireMemberState(MemberState.Member)], async (req, res) => { try { @@ -32,23 +35,56 @@ router.get('/', [requireLogin, requireMemberState(MemberState.Member)], async (r } }); -router.get('/me', [requireLogin], async (req, res) => { - if (req.user === undefined) - return res.sendStatus(401) +router.get('/me', [requireLogin], async (req: Request, res) => { + if (!req.user) return res.sendStatus(401); + + const routeStart = performance.now(); + const timings: Record = {}; try { - const memData = await getUserData(req.user.id); - const LOAData = await getUserActiveLOA(req.user.id); - const memState = await getUserState(req.user.id); - const roleData = await getUserRoles(req.user.id); + let t; + + t = performance.now(); + const memData = await getUserData(req.user.id); + timings.member = performance.now() - t; + + t = performance.now(); + const LOAData = await getUserActiveLOA(req.user.id); + timings.loa = performance.now() - t; + + t = performance.now(); + const memState = await getUserState(req.user.id); + timings.state = performance.now() - t; + + t = performance.now(); + const roleData = await getUserRoles(req.user.id); + timings.roles = performance.now() - t; + + const userDataFull: myData = { + member: memData, + LOAs: LOAData, + roles: roleData, + state: memState, + }; - const userDataFull: myData = { member: memData, LOAs: LOAData, roles: roleData, state: memState }; res.status(200).json(userDataFull); + + logger.info('profiling', 'GET /members/me completed', { + userId: req.user.id, + total_ms: performance.now() - routeStart, + breakdown_ms: timings, + }, 'profiling'); + } catch (error) { - console.error('Error fetching user data:', error); + logger.error('profiling', 'GET /members/me failed', { + userId: req.user?.id, + error: error instanceof Error ? error.message : String(error), + }); + return res.status(500).json({ error: 'Failed to fetch user data' }); } -}) +}); + router.get('/settings', [requireLogin], async (req: Request, res: Response) => { try { diff --git a/api/src/services/logging/logger.ts b/api/src/services/logging/logger.ts index d67b2c5..c0b075c 100644 --- a/api/src/services/logging/logger.ts +++ b/api/src/services/logging/logger.ts @@ -1,6 +1,6 @@ export type LogLevel = 'debug' | 'info' | 'warn' | 'error'; -export type LogDepth = 'normal' | 'verbose'; -export type LogType = 'http' | 'app' | 'auth'; +export type LogDepth = 'normal' | 'verbose' | 'profiling'; +export type LogType = 'http' | 'app' | 'auth' | 'profiling'; export interface LogHeader { timestamp: string; @@ -18,7 +18,7 @@ export interface LogPayload { // Environment defaults const CURRENT_DEPTH: LogDepth = (process.env.LOG_DEPTH as LogDepth) || 'normal'; -const DEPTH_ORDER: Record = { normal: 0, verbose: 1 }; +const DEPTH_ORDER: Record = { normal: 0, verbose: 1, profiling: 2 }; function shouldLog(depth: LogDepth) { let should = DEPTH_ORDER[depth] <= DEPTH_ORDER[CURRENT_DEPTH]