diff --git a/api/package.json b/api/package.json index e8c4232e667..75461e6817a 100644 --- a/api/package.json +++ b/api/package.json @@ -16,6 +16,7 @@ "@growthbook/growthbook": "1.3.1", "@prisma/client": "5.5.2", "@sentry/node": "9.1.0", + "@types/pino": "^7.0.5", "ajv": "8.12.0", "ajv-formats": "2.1.1", "date-fns": "2.30.0", @@ -30,6 +31,7 @@ "nanoid": "3", "no-profanity": "1.5.1", "nodemailer": "6.9.10", + "pino": "^9.6.0", "pino-pretty": "10.2.3", "query-string": "7.1.3", "stripe": "16.0.0", diff --git a/api/src/app.ts b/api/src/app.ts index 43177afe14a..8476a9facb3 100644 --- a/api/src/app.ts +++ b/api/src/app.ts @@ -1,5 +1,4 @@ import { randomBytes } from 'crypto'; -import { isEmpty } from 'lodash'; import fastifyAccepts from '@fastify/accepts'; import fastifySwagger from '@fastify/swagger'; import fastifySwaggerUI from '@fastify/swagger-ui'; @@ -11,7 +10,6 @@ import Fastify, { FastifyBaseLogger, FastifyHttpOptions, FastifyInstance, - FastifyRequest, RawReplyDefaultExpression, RawRequestDefaultExpression, RawServerDefault @@ -45,11 +43,10 @@ import { FCC_ENABLE_EXAM_ENVIRONMENT, FCC_ENABLE_SENTRY_ROUTES, GROWTHBOOK_FASTIFY_API_HOST, - GROWTHBOOK_FASTIFY_CLIENT_KEY, - FREECODECAMP_NODE_ENV, - FCC_API_LOG_LEVEL + GROWTHBOOK_FASTIFY_CLIENT_KEY } from './utils/env'; import { isObjectID } from './utils/validation'; +import { getLogger } from './utils/logger'; import { examEnvironmentMultipartRoutes, examEnvironmentOpenRoutes, @@ -83,63 +80,8 @@ ajv.addFormat('objectid', { validate: (str: string) => isObjectID(str) }); -const requestSerializer = (req: FastifyRequest) => { - const method = req.method || 'METHOD not found'; - const url = req.url || 'URL not found'; - const headers = req.headers || 'HEADERS not found'; - const xForwardedFor = Array.isArray(req.headers['x-forwarded-for']) - ? req.headers['x-forwarded-for'][0] - : req.headers['x-forwarded-for']; - const ip = - xForwardedFor || req.headers['x-real-ip'] || req.ip || 'IP not found'; - const query = isEmpty(req.query) ? 'QUERY not found' : req.query; - const hostname = req.hostname || 'HOSTNAME not found'; - const remotePort = req.socket.remotePort || 'REMOTE_PORT not found'; - - return { - REQ_ID: req.id, - METHOD: method, - URL: url, - IP: ip, - HOSTNAME: hostname, - REMOTE_PORT: remotePort, - QUERY: query, - HEADERS: headers - }; -}; - -const envToLogger = { - development: { - transport: { - target: 'pino-pretty', - options: { - singleLine: true, - translateTime: 'HH:MM:ss Z', - ignore: 'pid,hostname' - } - }, - level: FCC_API_LOG_LEVEL || 'info', - serializers: { - req: (req: FastifyRequest) => { - return { - method: req.method, - url: req.url - }; - } - } - // No need to redact in development - }, - production: { - level: FCC_API_LOG_LEVEL || 'info', - serializers: { - req: requestSerializer - }, - redact: ['req.HEADERS.cookie'] - } -}; - export const buildOptions = { - logger: envToLogger[FREECODECAMP_NODE_ENV] ?? true, + logger: getLogger(), genReqId: () => randomBytes(8).toString('hex'), disableRequestLogging: true }; diff --git a/api/src/plugins/auth0.ts b/api/src/plugins/auth0.ts index eb17ccd2e18..541531ac249 100644 --- a/api/src/plugins/auth0.ts +++ b/api/src/plugins/auth0.ts @@ -79,7 +79,7 @@ export const auth0Client: FastifyPluginCallbackTypebox = fp( // TODO: use a schema to validate the query params. fastify.get('/auth/auth0/callback', async function (req, reply) { - const logger = fastify.log.child({ req }); + const logger = fastify.log.child({ req, res: reply }); const { error, error_description } = req.query as Record; if (error === 'access_denied') { diff --git a/api/src/plugins/bouncer.ts b/api/src/plugins/bouncer.ts index a7598ddcd29..f7707e2d377 100644 --- a/api/src/plugins/bouncer.ts +++ b/api/src/plugins/bouncer.ts @@ -19,7 +19,7 @@ const plugin: FastifyPluginCallback = (fastify, _options, done) => { 'send401IfNoUser', async function (req: FastifyRequest, reply: FastifyReply) { if (!req.user) { - const logger = fastify.log.child({ req }); + const logger = fastify.log.child({ req, res: reply }); logger.trace( 'Protected route accessed by unauthenticated user. Sent 401.' @@ -36,7 +36,7 @@ const plugin: FastifyPluginCallback = (fastify, _options, done) => { fastify.decorate( 'redirectIfNoUser', async function (req: FastifyRequest, reply: FastifyReply) { - const logger = fastify.log.child({ req }); + const logger = fastify.log.child({ req, res: reply }); if (!req.user) { logger.trace( 'Protected route accessed by unauthenticated user. Redirecting to login.' @@ -55,7 +55,7 @@ const plugin: FastifyPluginCallback = (fastify, _options, done) => { 'redirectIfSignedIn', async function (req: FastifyRequest, reply: FastifyReply) { if (req.user) { - const logger = fastify.log.child({ req }); + const logger = fastify.log.child({ req, res: reply }); const { returnTo } = getRedirectParams(req); diff --git a/api/src/plugins/cors.ts b/api/src/plugins/cors.ts index c41a155f5a7..0b7f8b715d2 100644 --- a/api/src/plugins/cors.ts +++ b/api/src/plugins/cors.ts @@ -10,7 +10,7 @@ const cors: FastifyPluginCallback = (fastify, _options, done) => { }); fastify.addHook('onRequest', async (req, reply) => { - const logger = fastify.log.child({ req }); + const logger = fastify.log.child({ req, res: reply }); const origin = req.headers.origin; if (origin && allowedOrigins.includes(origin)) { // Do we want to log allowed origins? diff --git a/api/src/plugins/csrf.ts b/api/src/plugins/csrf.ts index 39407cf824e..2065348e6ac 100644 --- a/api/src/plugins/csrf.ts +++ b/api/src/plugins/csrf.ts @@ -28,7 +28,7 @@ const csrf: FastifyPluginCallback = (fastify, _options, done) => { // All routes except signout should add a CSRF token to the response fastify.addHook('onRequest', (req, reply, done) => { - const logger = fastify.log.child({ req }); + const logger = fastify.log.child({ req, res: reply }); const isSignout = req.url === '/signout' || req.url === '/signout/'; if (!isSignout) { diff --git a/api/src/plugins/not-found.ts b/api/src/plugins/not-found.ts index 152646da902..19f4928646c 100644 --- a/api/src/plugins/not-found.ts +++ b/api/src/plugins/not-found.ts @@ -15,7 +15,7 @@ const fourOhFour: FastifyPluginCallback = (fastify, _options, done) => { // If the request accepts JSON and does not specifically prefer text/html, // this will return a 404 JSON response. Everything else will be redirected. fastify.setNotFoundHandler((req, reply) => { - const logger = fastify.log.child({ req }); + const logger = fastify.log.child({ req, res: reply }); logger.info('User requested path that does not exist'); const accepted = req.accepts().type(['json', 'html']); diff --git a/api/src/routes/protected/certificate.ts b/api/src/routes/protected/certificate.ts index de20494dcb8..0e1ea1d2c1a 100644 --- a/api/src/routes/protected/certificate.ts +++ b/api/src/routes/protected/certificate.ts @@ -266,7 +266,7 @@ export const protectedCertificateRoutes: FastifyPluginCallbackTypebox = ( } }, async (req, reply) => { - const logger = fastify.log.child({ req }); + const logger = fastify.log.child({ req, res: reply }); const { certSlug } = req.body; if (!isKnownCertSlug(certSlug) || !isCertAllowed(certSlug)) { diff --git a/api/src/routes/protected/challenge.ts b/api/src/routes/protected/challenge.ts index 2bec33749a8..cba143eb682 100644 --- a/api/src/routes/protected/challenge.ts +++ b/api/src/routes/protected/challenge.ts @@ -68,7 +68,7 @@ export const challengeRoutes: FastifyPluginCallbackTypebox = ( { schema: schemas.coderoadChallengeCompleted, errorHandler(error, req, reply) { - const logger = fastify.log.child({ req }); + const logger = fastify.log.child({ req, res: reply }); if (error.validation) { logger.warn({ validationError: error.validation }); void reply.code(400); @@ -79,7 +79,7 @@ export const challengeRoutes: FastifyPluginCallbackTypebox = ( } }, async (req, reply) => { - const logger = fastify.log.child({ req }); + const logger = fastify.log.child({ req, res: reply }); logger.info( { userId: req.user?.id }, 'User submitted a coderoad challenge' @@ -207,7 +207,7 @@ export const challengeRoutes: FastifyPluginCallbackTypebox = ( { schema: schemas.projectCompleted, errorHandler(error, req, reply) { - const logger = fastify.log.child({ req }); + const logger = fastify.log.child({ req, res: reply }); if (error.validation) { logger.warn({ validationError: error.validation }); void reply.code(400); @@ -310,8 +310,8 @@ export const challengeRoutes: FastifyPluginCallbackTypebox = ( } } }, - async req => { - const logger = fastify.log.child({ req }); + async (req, reply) => { + const logger = fastify.log.child({ req, res: reply }); logger.info( { userId: req.user?.id }, `User submitted a backend challenge` @@ -353,7 +353,7 @@ export const challengeRoutes: FastifyPluginCallbackTypebox = ( schema: schemas.modernChallengeCompleted, errorHandler(error, req, reply) { if (error.validation) { - const logger = fastify.log.child({ req }); + const logger = fastify.log.child({ req, res: reply }); // This is another highly used route, so debug log level is used to // avoid excessive logging logger.debug({ validationError: error.validation }); @@ -364,8 +364,8 @@ export const challengeRoutes: FastifyPluginCallbackTypebox = ( } } }, - async req => { - const logger = fastify.log.child({ req }); + async (req, reply) => { + const logger = fastify.log.child({ req, res: reply }); // This is another highly used route, so debug log level is used to // avoid excessive logging logger.debug( @@ -420,7 +420,7 @@ export const challengeRoutes: FastifyPluginCallbackTypebox = ( { schema: schemas.saveChallenge, errorHandler(error, req, reply) { - const logger = fastify.log.child({ req }); + const logger = fastify.log.child({ req, res: reply }); if (error.validation) { logger.warn({ validationError: error.validation }); void reply.code(400); @@ -431,7 +431,7 @@ export const challengeRoutes: FastifyPluginCallbackTypebox = ( } }, async (req, reply) => { - const logger = fastify.log.child({ req }); + const logger = fastify.log.child({ req, res: reply }); logger.info({ userId: req.user?.id }, 'User saved a challenge'); const { files, id: challengeId } = req.body; @@ -480,7 +480,7 @@ export const challengeRoutes: FastifyPluginCallbackTypebox = ( { schema: schemas.exam, errorHandler(error, req, reply) { - const logger = fastify.log.child({ req }); + const logger = fastify.log.child({ req, res: reply }); if (error.validation) { logger.warn({ validationError: error.validation }); void reply.code(400); @@ -491,7 +491,7 @@ export const challengeRoutes: FastifyPluginCallbackTypebox = ( } }, async (req, reply) => { - const logger = fastify.log.child({ req }); + const logger = fastify.log.child({ req, res: reply }); logger.info( { userId: req.user?.id, examId: req.params.id }, 'User requested an exam' @@ -580,7 +580,7 @@ export const challengeRoutes: FastifyPluginCallbackTypebox = ( { schema: schemas.msTrophyChallengeCompleted, errorHandler(error, req, reply) { - const logger = fastify.log.child({ req }); + const logger = fastify.log.child({ req, res: reply }); if (error.validation) { logger.warn({ validationError: error.validation }); void reply.code(400); @@ -591,7 +591,7 @@ export const challengeRoutes: FastifyPluginCallbackTypebox = ( } }, async (req, reply) => { - const logger = fastify.log.child({ req }); + const logger = fastify.log.child({ req, res: reply }); logger.info( { userId: req.user?.id }, 'User submitted a Microsoft trophy challenge' @@ -685,7 +685,7 @@ export const challengeRoutes: FastifyPluginCallbackTypebox = ( { schema: schemas.examChallengeCompleted, errorHandler(error, req, reply) { - const logger = fastify.log.child({ req }); + const logger = fastify.log.child({ req, res: reply }); if (error.validation) { logger.warn({ validationError: error.validation }); void reply.code(400); @@ -698,7 +698,7 @@ export const challengeRoutes: FastifyPluginCallbackTypebox = ( } }, async (req, reply) => { - const logger = fastify.log.child({ req }); + const logger = fastify.log.child({ req, res: reply }); logger.info({ userId: req.user?.id }, 'User submitted an exam challenge'); @@ -899,7 +899,7 @@ export const challengeRoutes: FastifyPluginCallbackTypebox = ( { schema: schemas.submitQuizAttempt, errorHandler(error, req, reply) { - const logger = fastify.log.child({ req }); + const logger = fastify.log.child({ req, res: reply }); if (error.validation) { logger.warn({ validationError: error.validation }); void reply.code(400); diff --git a/api/src/routes/protected/donate.ts b/api/src/routes/protected/donate.ts index 887b454784d..3533d69e6f5 100644 --- a/api/src/routes/protected/donate.ts +++ b/api/src/routes/protected/donate.ts @@ -28,8 +28,8 @@ export const donateRoutes: FastifyPluginCallbackTypebox = ( { schema: schemas.updateStripeCard }, - async req => { - const logger = fastify.log.child({ req }); + async (req, reply) => { + const logger = fastify.log.child({ req, res: reply }); const donation = await fastify.prisma.donation.findFirst({ where: { userId: req.user?.id, provider: 'stripe' } }); @@ -62,7 +62,7 @@ export const donateRoutes: FastifyPluginCallbackTypebox = ( schema: schemas.addDonation }, async (req, reply) => { - const logger = fastify.log.child({ req }); + const logger = fastify.log.child({ req, res: reply }); try { const user = await fastify.prisma.user.findUnique({ where: { id: req.user?.id } @@ -107,7 +107,7 @@ export const donateRoutes: FastifyPluginCallbackTypebox = ( schema: schemas.chargeStripeCard }, async (req, reply) => { - const logger = fastify.log.child({ req }); + const logger = fastify.log.child({ req, res: reply }); try { const { paymentMethodId, amount, duration } = req.body; const id = req.user!.id; diff --git a/api/src/routes/protected/settings.ts b/api/src/routes/protected/settings.ts index c6936f4ed40..d2428b3ec36 100644 --- a/api/src/routes/protected/settings.ts +++ b/api/src/routes/protected/settings.ts @@ -113,7 +113,7 @@ export const settingRoutes: FastifyPluginCallbackTypebox = ( schema: schemas.updateMyProfileUI }, async (req, reply) => { - const logger = fastify.log.child({ req }); + const logger = fastify.log.child({ req, res: reply }); try { await fastify.prisma.user.update({ where: { id: req.user?.id }, @@ -167,7 +167,7 @@ Happy coding! attachValidation: true }, async (req, reply) => { - const logger = fastify.log.child({ req }); + const logger = fastify.log.child({ req, res: reply }); if (req.validationError) { logger.warn(`Invalid email ${req.body.email}`); void reply.code(400); @@ -308,7 +308,7 @@ ${isLinkSentWithinLimitTTL}` schema: schemas.updateMyTheme }, async (req, reply) => { - const logger = fastify.log.child({ req }); + const logger = fastify.log.child({ req, res: reply }); try { await fastify.prisma.user.update({ where: { id: req.user?.id }, @@ -337,7 +337,7 @@ ${isLinkSentWithinLimitTTL}` schema: schemas.updateMySocials }, async (req, reply) => { - const logger = fastify.log.child({ req }); + const logger = fastify.log.child({ req, res: reply }); const socials = { twitter: req.body.twitter, @@ -391,7 +391,7 @@ ${isLinkSentWithinLimitTTL}` attachValidation: true }, async (req, reply) => { - const logger = fastify.log.child({ req }); + const logger = fastify.log.child({ req, res: reply }); try { const user = await fastify.prisma.user.findFirstOrThrow({ @@ -482,7 +482,7 @@ ${isLinkSentWithinLimitTTL}` schema: schemas.updateMyAbout }, async (req, reply) => { - const logger = fastify.log.child({ req }); + const logger = fastify.log.child({ req, res: reply }); const hasProtocol = isPictureWithProtocol(req.body.picture); try { @@ -515,7 +515,7 @@ ${isLinkSentWithinLimitTTL}` schema: schemas.updateMyKeyboardShortcuts }, async (req, reply) => { - const logger = fastify.log.child({ req }); + const logger = fastify.log.child({ req, res: reply }); try { await fastify.prisma.user.update({ where: { id: req.user?.id }, @@ -543,7 +543,7 @@ ${isLinkSentWithinLimitTTL}` schema: schemas.updateMyQuincyEmail }, async (req, reply) => { - const logger = fastify.log.child({ req }); + const logger = fastify.log.child({ req, res: reply }); try { await fastify.prisma.user.update({ where: { id: req.user?.id }, @@ -571,7 +571,7 @@ ${isLinkSentWithinLimitTTL}` schema: schemas.updateMyHonesty }, async (req, reply) => { - const logger = fastify.log.child({ req }); + const logger = fastify.log.child({ req, res: reply }); try { await fastify.prisma.user.update({ where: { id: req.user?.id }, @@ -599,7 +599,7 @@ ${isLinkSentWithinLimitTTL}` schema: schemas.updateMyPrivacyTerms }, async (req, reply) => { - const logger = fastify.log.child({ req }); + const logger = fastify.log.child({ req, res: reply }); try { await fastify.prisma.user.update({ where: { id: req.user?.id }, @@ -628,7 +628,7 @@ ${isLinkSentWithinLimitTTL}` schema: schemas.updateMyPortfolio }, async (req, reply) => { - const logger = fastify.log.child({ req }); + const logger = fastify.log.child({ req, res: reply }); try { // TODO(Post-MVP): make all properties required in the schema and use // req.body.portfolio directly. @@ -667,7 +667,7 @@ ${isLinkSentWithinLimitTTL}` schema: schemas.updateMyClassroomMode }, async (req, reply) => { - const logger = fastify.log.child({ req }); + const logger = fastify.log.child({ req, res: reply }); try { const classroomMode = req.body.isClassroomAccount; @@ -764,7 +764,7 @@ export const settingRedirectRoutes: FastifyPluginCallbackTypebox = ( } }, async (req, reply) => { - const logger = fastify.log.child({ req }); + const logger = fastify.log.child({ req, res: reply }); const email = Buffer.from(req.query.email, 'base64').toString(); const { origin } = getRedirectParams(req); diff --git a/api/src/routes/protected/user.ts b/api/src/routes/protected/user.ts index c783599e9b5..3c6898a3be5 100644 --- a/api/src/routes/protected/user.ts +++ b/api/src/routes/protected/user.ts @@ -64,7 +64,7 @@ export const userRoutes: FastifyPluginCallbackTypebox = ( schema: schemas.deleteMyAccount }, async (req, reply) => { - const logger = fastify.log.child({ req }); + const logger = fastify.log.child({ req, res: reply }); logger.info(`User ${req.user?.id} requested account deletion`); await fastify.prisma.userToken.deleteMany({ where: { userId: req.user!.id } @@ -89,8 +89,8 @@ export const userRoutes: FastifyPluginCallbackTypebox = ( { schema: schemas.resetMyProgress }, - async req => { - const logger = fastify.log.child({ req }); + async (req, reply) => { + const logger = fastify.log.child({ req, res: reply }); logger.info(`User ${req.user?.id} requested progress reset`); await fastify.prisma.userToken.deleteMany({ where: { userId: req.user!.id } @@ -110,8 +110,8 @@ export const userRoutes: FastifyPluginCallbackTypebox = ( } ); // TODO(Post-MVP): POST -> PUT - fastify.post('/user/user-token', async req => { - const logger = fastify.log.child({ req }); + fastify.post('/user/user-token', async (req, reply) => { + const logger = fastify.log.child({ req, res: reply }); logger.info(`User ${req.user?.id} requested a new user token`); await fastify.prisma.userToken.deleteMany({ @@ -139,7 +139,7 @@ export const userRoutes: FastifyPluginCallbackTypebox = ( schema: schemas.deleteUserToken }, async (req, reply) => { - const logger = fastify.log.child({ req }); + const logger = fastify.log.child({ req, res: reply }); logger.info(`User ${req.user?.id} requested token deletion`); const { count } = await fastify.prisma.userToken.deleteMany({ @@ -168,7 +168,7 @@ export const userRoutes: FastifyPluginCallbackTypebox = ( } }, async (req, reply) => { - const logger = fastify.log.child({ req }); + const logger = fastify.log.child({ req, res: reply }); logger.info(`User ${req.user?.id} reported user ${req.body.username}`); const user = await fastify.prisma.user.findUniqueOrThrow({ @@ -231,7 +231,7 @@ export const userRoutes: FastifyPluginCallbackTypebox = ( schema: schemas.deleteMsUsername }, async (req, reply) => { - const logger = fastify.log.child({ req }); + const logger = fastify.log.child({ req, res: reply }); logger.info(`User ${req.user?.id} requested unlinking of msUsername`); try { @@ -258,7 +258,7 @@ export const userRoutes: FastifyPluginCallbackTypebox = ( { schema: schemas.postMsUsername, errorHandler(error, req, reply) { - const logger = fastify.log.child({ req }); + const logger = fastify.log.child({ req, res: reply }); if (error.validation) { logger.warn({ validationError: error.validation }); void reply.code(400).send({ @@ -271,7 +271,7 @@ export const userRoutes: FastifyPluginCallbackTypebox = ( } }, async (req, reply) => { - const logger = fastify.log.child({ req }); + const logger = fastify.log.child({ req, res: reply }); logger.info(`User ${req.user?.id} requested linking of msUsername`); try { @@ -367,7 +367,7 @@ export const userRoutes: FastifyPluginCallbackTypebox = ( } }, async (req, reply) => { - const logger = fastify.log.child({ req }); + const logger = fastify.log.child({ req, res: reply }); logger.info(`User ${req.user?.id} submitted a survey`); try { const user = await fastify.prisma.user.findUniqueOrThrow({ @@ -490,7 +490,7 @@ export const userGetRoutes: FastifyPluginCallbackTypebox = ( schema: schemas.getSessionUser }, async (req, res) => { - const logger = fastify.log.child({ req }); + const logger = fastify.log.child({ req, res }); // This is one of the most requested routes. To avoid spamming the logs // with this route, we'll log requests at the debug level. logger.debug({ userId: req.user?.id }); diff --git a/api/src/routes/public/auth.ts b/api/src/routes/public/auth.ts index b4d31d94541..545b51086ac 100644 --- a/api/src/routes/public/auth.ts +++ b/api/src/routes/public/auth.ts @@ -43,7 +43,7 @@ export const mobileAuth0Routes: FastifyPluginCallback = ( fastify.get('/mobile-login', async (req, reply) => { const email = await getEmailFromAuth0(req); - const logger = fastify.log.child({ req }); + const logger = fastify.log.child({ req, res: reply }); logger.info('Mobile app login attempt'); diff --git a/api/src/routes/public/certificate.ts b/api/src/routes/public/certificate.ts index 62c252ec08d..4e1360bb95c 100644 --- a/api/src/routes/public/certificate.ts +++ b/api/src/routes/public/certificate.ts @@ -32,7 +32,7 @@ export const unprotectedCertificateRoutes: FastifyPluginCallbackTypebox = ( schema: schemas.certSlug }, async (req, reply) => { - const logger = fastify.log.child({ req }); + const logger = fastify.log.child({ req, res: reply }); const username = req.params.username.toLowerCase(); const certSlug = req.params.certSlug; diff --git a/api/src/routes/public/signout.ts b/api/src/routes/public/signout.ts index d9cf18da3d0..4958c9d31d3 100644 --- a/api/src/routes/public/signout.ts +++ b/api/src/routes/public/signout.ts @@ -16,7 +16,7 @@ export const signoutRoute: FastifyPluginCallback = ( done ) => { fastify.get('/signout', async (req, reply) => { - const logger = fastify.log.child({ req }); + const logger = fastify.log.child({ req, res: reply }); void reply.clearOurCookies(); logger.info('User signed out'); diff --git a/api/src/routes/public/status.ts b/api/src/routes/public/status.ts index b5b21089507..a9b9c05567e 100644 --- a/api/src/routes/public/status.ts +++ b/api/src/routes/public/status.ts @@ -15,13 +15,13 @@ export const statusRoute: FastifyPluginCallbackTypebox = ( _options, done ) => { - fastify.get('/status/ping', async (req, _reply) => { - fastify.log.child({ req }).debug('pong'); + fastify.get('/status/ping', async (req, res) => { + fastify.log.child({ req, res }).debug('Replying to ping'); return { msg: 'pong' }; }); - fastify.get('/status/version', async (req, _reply) => { - fastify.log.child({ req }).debug('version'); + fastify.get('/status/version', async (req, res) => { + fastify.log.child({ req, res }).debug('Sending version'); return { version: DEPLOYMENT_VERSION }; }); diff --git a/api/src/routes/public/user.ts b/api/src/routes/public/user.ts index 872110cf417..934b679e486 100644 --- a/api/src/routes/public/user.ts +++ b/api/src/routes/public/user.ts @@ -120,7 +120,7 @@ export const userPublicGetRoutes: FastifyPluginCallbackTypebox = ( } }, async (req, reply) => { - const logger = fastify.log.child({ req }); + const logger = fastify.log.child({ req, reply }); logger.info({ username: req.query.username }); // TODO(Post-MVP): look for duplicates unless we can make username unique in the db. const user = await fastify.prisma.user.findFirst({ @@ -219,10 +219,12 @@ export const userPublicGetRoutes: FastifyPluginCallbackTypebox = ( attachValidation: true }, async (req, reply) => { - const logger = fastify.log.child({ req }); + const logger = fastify.log.child({ req, res: reply }); if (req.validationError) { - logger.warn({ validationError: req.validationError }); + logger.warn('Validation error', { + validationError: req.validationError + }); void reply.code(400); return await reply.send({ type: 'danger', diff --git a/api/src/utils/env.ts b/api/src/utils/env.ts index 9aade11ee63..ca956ee6598 100644 --- a/api/src/utils/env.ts +++ b/api/src/utils/env.ts @@ -72,12 +72,18 @@ function isLogLevel(level: string): level is LogLevel { } const _FCC_API_LOG_LEVEL = process.env.FCC_API_LOG_LEVEL || 'info'; +const _FCC_API_LOG_TRANSPORT = process.env.FCC_API_LOG_TRANSPORT || 'default '; assert.ok( isLogLevel(_FCC_API_LOG_LEVEL), `FCC_API_LOG_LEVEL must be one of ${LOG_LEVELS.join(', ')}. Found ${_FCC_API_LOG_LEVEL}` ); +assert.ok( + _FCC_API_LOG_TRANSPORT === 'pretty' || _FCC_API_LOG_TRANSPORT === 'default', + `FCC_API_LOG_TRANSPORT must be one of 'pretty' or 'default'. Found ${_FCC_API_LOG_TRANSPORT}` +); + if (process.env.FREECODECAMP_NODE_ENV !== 'development') { assert.ok(process.env.SES_ID); assert.ok(process.env.SES_SECRET); @@ -178,6 +184,7 @@ export const FCC_ENABLE_SWAGGER_UI = undefinedOrBool( export const FCC_ENABLE_DEV_LOGIN_MODE = process.env.FCC_ENABLE_DEV_LOGIN_MODE === 'true'; export const FCC_API_LOG_LEVEL = _FCC_API_LOG_LEVEL; +export const FCC_API_LOG_TRANSPORT = _FCC_API_LOG_TRANSPORT; export const FCC_ENABLE_SHADOW_CAPTURE = undefinedOrBool( process.env.FCC_ENABLE_SHADOW_CAPTURE ); diff --git a/api/src/utils/logger.ts b/api/src/utils/logger.ts new file mode 100644 index 00000000000..ba3fb919998 --- /dev/null +++ b/api/src/utils/logger.ts @@ -0,0 +1,74 @@ +import pino, { TransportTargetOptions } from 'pino'; +import { FastifyRequest, FastifyReply } from 'fastify'; +import { isEmpty } from 'lodash'; +import { FCC_API_LOG_LEVEL, FCC_API_LOG_TRANSPORT } from './env'; + +const transportOptionsPretty: TransportTargetOptions = { + target: 'pino-pretty', + options: { + singleLine: true, + translateTime: 'HH:MM:ss Z', + ignore: 'pid,hostname', + colorize: true + } +}; + +const serializersPretty = { + req: (req: FastifyRequest) => { + return { + REQ_METHOD: req.method, + REQ_URL: req.url + }; + } +}; + +const serializersDefault = { + req: (req: FastifyRequest) => { + const method = req.method || 'METHOD not found'; + const url = req.url || 'URL not found'; + const xForwardedFor = Array.isArray(req.headers['x-forwarded-for']) + ? req.headers['x-forwarded-for'][0] + : req.headers['x-forwarded-for']; + const ip = + req.headers['cf-connecting-ip'] || + xForwardedFor || + req.headers['x-real-ip'] || + req.ip || + 'IP not found'; + const userAgent = req.headers['user-agent'] || 'USER_AGENT not found'; + const country = req.headers['cf-ipcountry'] || 'COUNTRY not found'; + const query = isEmpty(req.query) ? 'QUERY not found' : req.query; + + return { + REQ_METHOD: method, + REQ_URL: url, + REQ_IP: ip, + REQ_USER_AGENT: userAgent, + REQ_COUNTRY: country, + REQ_QUERY: query + }; + }, + res: (reply: FastifyReply) => { + return { + RES_STATUS_CODE: reply.statusCode, + RES_RESPONSE_TIME: reply.elapsedTime + }; + } +}; + +/** + * Get a logger instance with the default options. + * + * @returns A logger instance with the default options. + */ +export const getLogger = () => { + const isPretty = FCC_API_LOG_TRANSPORT === 'pretty'; + const options = { + level: FCC_API_LOG_LEVEL || 'info', + serializers: isPretty ? serializersPretty : serializersDefault + }; + + return isPretty + ? pino({ ...options, transport: transportOptionsPretty }) + : pino(options); +}; diff --git a/pnpm-lock.yaml b/pnpm-lock.yaml index 1e7d46b4e65..3ab79ac27f8 100644 --- a/pnpm-lock.yaml +++ b/pnpm-lock.yaml @@ -194,6 +194,9 @@ importers: '@sentry/node': specifier: 9.1.0 version: 9.1.0 + '@types/pino': + specifier: ^7.0.5 + version: 7.0.5 ajv: specifier: 8.12.0 version: 8.12.0 @@ -236,6 +239,9 @@ importers: nodemailer: specifier: 6.9.10 version: 6.9.10 + pino: + specifier: ^9.6.0 + version: 9.6.0 pino-pretty: specifier: 10.2.3 version: 10.2.3 @@ -5134,6 +5140,10 @@ packages: '@types/pg@8.6.1': resolution: {integrity: sha512-1Kc4oAGzAl7uqUStZCDvaLFqZrW9qWSjXOmBfdgyBP5La7Us6Mg4GBvRlSoaZMhQF/zSj1C8CtKMBkoiT8eL8w==} + '@types/pino@7.0.5': + resolution: {integrity: sha512-wKoab31pknvILkxAF8ss+v9iNyhw5Iu/0jLtRkUD74cNfOOLJNnqfFKAv0r7wVaTQxRZtWrMpGfShwwBjOcgcg==} + deprecated: This is a stub types definition. pino provides its own type definitions, so you do not need this installed. + '@types/prismjs@1.26.0': resolution: {integrity: sha512-ZTaqn/qSqUuAq1YwvOFQfVW1AR/oQJlLSZVustdjwI+GZ8kr0MSHBj0tsXPW1EqHubx50gtBEjbPGsdZwQwCjQ==} @@ -8526,6 +8536,7 @@ packages: formidable@2.1.2: resolution: {integrity: sha512-CM3GuJ57US06mlpQ47YcunuUZ9jpm8Vx+P2CGt2j7HpgkKZO/DJYQ0Bobim8G6PFQmK5lOqOOdUXboU+h73A4g==} + deprecated: 'ACTION REQUIRED: SWITCH TO v3 - v1 and v2 are VULNERABLE! v1 is DEPRECATED FOR OVER 2 YEARS! Use formidable@latest or try formidable-mini for fresh projects' forwarded-parse@2.1.2: resolution: {integrity: sha512-alTFZZQDKMporBH77856pXgzhEzaUVmLCDk+egLgIgHst3Tpndzz8MnKe+GzRJRfvVdn69HhpW7cmXzvtLvJAw==} @@ -15351,6 +15362,7 @@ packages: yurnalist@2.1.0: resolution: {integrity: sha512-PgrBqosQLM3gN2xBFIMDLACRTV9c365VqityKKpSTWpwR+U4LAFR3rSVyEoscWlu3EzX9+Y0I86GXUKxpHFl6w==} engines: {node: '>=4.0.0'} + deprecated: Package no longer supported. Contact Support at https://www.npmjs.com/support for more info. zod@3.23.8: resolution: {integrity: sha512-XBx9AXhXktjUqnepgTiE5flcKIYWi/rme0Eaj+5Y0lftuGBq+jyRu/md4WnuxqgP1ubdpNCsYEYPxrzVHD8d6g==} @@ -21569,6 +21581,10 @@ snapshots: pg-protocol: 1.8.0 pg-types: 2.2.0 + '@types/pino@7.0.5': + dependencies: + pino: 9.6.0 + '@types/prismjs@1.26.0': {} '@types/prop-types@15.7.8': {} @@ -32595,7 +32611,7 @@ snapshots: send@1.2.0: dependencies: - debug: 4.3.7 + debug: 4.4.0 encodeurl: 2.0.0 escape-html: 1.0.3 etag: 1.8.1 diff --git a/sample.env b/sample.env index a6444055945..fbed968b62c 100644 --- a/sample.env +++ b/sample.env @@ -74,6 +74,7 @@ FCC_ENABLE_SHADOW_CAPTURE=false FCC_ENABLE_EXAM_ENVIRONMENT=false FCC_ENABLE_SENTRY_ROUTES=false FCC_API_LOG_LEVEL=info +FCC_API_LOG_TRANSPORT=pretty # Email # use ses in production