From 55343b9784fdab9183e4e99ae884caa59431699b Mon Sep 17 00:00:00 2001 From: Harshvardhan Karn Date: Fri, 11 Apr 2025 14:20:01 +0530 Subject: [PATCH 1/2] feat(log): Implement structured logging Add structured JSON logging with request IDs, timestamps, and context across: - Logger service (standardized format, request tracking) - Request middleware (HTTP metadata, duration) - Webhook processing (timing metrics, status tracking) - Service layer (CLA, Repo, Webhook services) - Controller layer (error handling, context) Improves observability, debugging, and monitoring in Datadog while maintaining existing functionality. --- src/server/src/app.js | 4 + src/server/src/controller/counts.js | 25 ++- src/server/src/controller/default.js | 14 +- src/server/src/controller/user.js | 32 +++- src/server/src/middleware/request-logger.js | 21 +++ src/server/src/passports/github.js | 43 ++++- src/server/src/services/cla.js | 123 +++++++++++--- src/server/src/services/github.js | 62 ++++++- src/server/src/services/logger.js | 160 +++++++++++++++--- .../octokit-plugins/network-interceptor.js | 17 +- src/server/src/services/org.js | 21 ++- src/server/src/services/pullRequest.js | 45 ++++- src/server/src/services/repo.js | 45 ++++- src/server/src/services/status.js | 92 ++++++++-- src/server/src/services/webhook.js | 12 +- src/server/src/webhooks/pull_request.js | 107 ++++++++++-- 16 files changed, 697 insertions(+), 126 deletions(-) create mode 100644 src/server/src/middleware/request-logger.js diff --git a/src/server/src/app.js b/src/server/src/app.js index 21104f2c5..c4c5c8411 100644 --- a/src/server/src/app.js +++ b/src/server/src/app.js @@ -23,6 +23,7 @@ const rTracer = require('cls-rtracer') const expressSession = require('express-session'); const MongoStore = require('connect-mongo'); const { verify: verifyWebhookSignature } = require('@octokit/webhooks-methods') +const requestLogger = require('./middleware/request-logger') // var sass_middleware = require('node-sass-middleware'); @@ -52,6 +53,9 @@ if (config.server.observability.request_trace_header_name) { } app.use(rTracer.expressMiddleware(tracingOptions)) +// Add request logging middleware +app.use(requestLogger) + // redirect from http to https app.use((req, res, next) => { if (!req.headers['x-forwarded-proto'] || req.headers['x-forwarded-proto'] === 'https') { diff --git a/src/server/src/controller/counts.js b/src/server/src/controller/counts.js index deafda831..5ccff704d 100644 --- a/src/server/src/controller/counts.js +++ b/src/server/src/controller/counts.js @@ -27,7 +27,11 @@ router.all('/count/repos', async (req, res) => { text: `There are ${repoCount} registered repositories!` })) } catch (error) { - logger.info(error) + logger.error({ + event: 'COUNTS_ERROR', + error: error, + msg: 'Error getting counts' + }) } }) @@ -40,8 +44,11 @@ router.all('/count/orgs', async (req, res) => { text: `There are ${orgsCount} registered organizations!` })) } catch (error) { - res.status(500).send(error) - logger.info(error) + logger.error({ + event: 'COUNTS_ERROR', + error: error, + msg: 'Error getting counts' + }) } }) @@ -60,7 +67,11 @@ router.all('/count/clas', async (req, res) => { '$count': 'count' }]) } catch (error) { - logger.info(error) + logger.error({ + event: 'COUNTS_ERROR', + error: error, + msg: 'Error getting counts' + }) } if (!Array.isArray(data) || data[0].count === undefined) { data = [{ count: 0 }] @@ -89,7 +100,11 @@ router.all('/count/stars', async (_req, res) => { owner: 'cla-assistant' }) } catch (error) { - logger.info(error) + logger.error({ + event: 'COUNTS_ERROR', + error: error, + msg: 'Error getting counts' + }) } res.send(JSON.stringify({ count: resp.data.stargazers_count diff --git a/src/server/src/controller/default.js b/src/server/src/controller/default.js index 2844cab70..b5d7b67c0 100644 --- a/src/server/src/controller/default.js +++ b/src/server/src/controller/default.js @@ -27,7 +27,11 @@ router.use('/accept/:owner/:repo', async (req, res) => { await cla.sign(req) } catch (e) { if (e && (!e.code || e.code != 200)) { - logger.error(e) + logger.error({ + event: 'ERROR', + error: e, + msg: 'Error processing request' + }) return } @@ -63,7 +67,13 @@ router.all('/static/*', (req, res) => { router.get('/check/:owner/:repo', (req, res) => { let referer = req.header('Referer') let back = referer && referer.includes('github.com') ? referer : 'https://github.com' - logger.info('Recheck PR requested for ', `https://github.com/${req.params.owner}/${req.params.repo}/pull/${req.query.pullRequest}`, `referer was ${referer}`) + logger.info({ + event: 'PR_RECHECK_REQUESTED', + repo: `${req.params.owner}/${req.params.repo}`, + pull_number: req.query.pullRequest, + referer: referer, + msg: `Recheck PR requested for https://github.com/${req.params.owner}/${req.params.repo}/pull/${req.query.pullRequest}, referer was ${referer}` + }) cla.validatePullRequest({ owner: req.params.owner, repo: req.params.repo, diff --git a/src/server/src/controller/user.js b/src/server/src/controller/user.js index bfead62d0..711e183b4 100644 --- a/src/server/src/controller/user.js +++ b/src/server/src/controller/user.js @@ -38,7 +38,11 @@ function checkReturnTo(req, res, next) { req.session.returnTo = req.query.public === 'true' ? req.session.next || req.headers.referer : '/' - logger.debug('Check returnTo and call passport authenticate with appropriate scope. return to:', req.session.returnTo) + logger.debug({ + event: 'AUTH_SCOPE_CHECK', + return_to: req.session.returnTo, + msg: 'Check returnTo and call passport authenticate with appropriate scope' + }) passport.authenticate(strategy, { scope: scope @@ -48,8 +52,15 @@ function checkReturnTo(req, res, next) { router.get('/auth/github', checkReturnTo) const githubCallbackPost = (req, res) => { - logger.debug('Process authentication callback after passport authenticate') - logger.debug('User scopes:', req.user) + logger.debug({ + event: 'AUTH_CALLBACK_START', + msg: 'Process authentication callback after passport authenticate' + }) + logger.debug({ + event: 'USER_SCOPES', + scopes: req.user, + msg: 'User scopes' + }) if (req.user && req.session.requiredScope !== 'public' && utils.couldBeAdmin(req.user.login) && @@ -60,12 +71,18 @@ const githubCallbackPost = (req, res) => { } res.redirect(req.session.returnTo || req.headers.referer || '/') req.session.next = null - logger.debug('Finish processing authentication callback after passport authenticate') + logger.debug({ + event: 'AUTH_CALLBACK_END', + msg: 'Finish processing authentication callback after passport authenticate' + }) } router.get('/auth/github/callback', function (req, res, next) { - logger.debug('Start processing OAuth authentication callback') + logger.debug({ + event: 'OAUTH_CALLBACK_START', + msg: 'Start processing OAuth authentication callback' + }) next() }, passport.authenticate('github-oauth', { @@ -76,7 +93,10 @@ router.get('/auth/github/callback', router.get('/auth/github/app-callback', function (req, res, next) { - logger.debug('Start processing App authentication callback') + logger.debug({ + event: 'APP_CALLBACK_START', + msg: 'Start processing App authentication callback' + }) next() }, passport.authenticate('github-app-auth', { diff --git a/src/server/src/middleware/request-logger.js b/src/server/src/middleware/request-logger.js new file mode 100644 index 000000000..7e51f3fad --- /dev/null +++ b/src/server/src/middleware/request-logger.js @@ -0,0 +1,21 @@ +// SPDX-FileCopyrightText: 2022 SAP SE or an SAP affiliate company and CLA-assistant contributors +// +// SPDX-License-Identifier: Apache-2.0 + +const logger = require('../services/logger') + +module.exports = (req, res, next) => { + const start = process.hrtime() + + // Log request start + logger.startRequest(req) + + // Log response when finished + res.on('finish', () => { + const duration = process.hrtime(start) + const durationMs = (duration[0] * 1e9 + duration[1]) / 1e6 + logger.endRequest(req, res, durationMs) + }) + + next() +} diff --git a/src/server/src/passports/github.js b/src/server/src/passports/github.js index c8ecf3dd9..c5ca309f8 100644 --- a/src/server/src/passports/github.js +++ b/src/server/src/passports/github.js @@ -15,7 +15,12 @@ const github = require('../services/github') function updateToken(item, newToken) { item.token = newToken item.save() - logger.debug('Update access token for repo / org', item.repo || item.org) + logger.debug({ + event: 'TOKEN_UPDATE', + item_type: item.repo ? 'repo' : 'org', + item_name: item.repo || item.org, + msg: `Update access token for ${item.repo ? 'repo' : 'org'} ${item.repo || item.org}` + }) } async function checkToken(item, accessToken) { @@ -45,14 +50,22 @@ async function checkToken(item, accessToken) { const ghRepo = await repoService.getGHRepo(item) if (!(ghRepo && ghRepo.permissions && ghRepo.permissions.admin)) { updateToken(item, newToken) - logger.info(`Update access token for repo ${item.repo} admin rights have been changed`) + logger.info({ + event: 'TOKEN_UPDATE_ADMIN', + repo: item.repo, + msg: `Update access token for repo ${item.repo} admin rights have been changed` + }) } } } } catch (error) { updateToken(item, newToken) + logger.warn({ + event: 'TOKEN_UPDATE_ERROR', + error: error, + msg: 'Error updating token' + }) } - } const githubVerifyCallback = async (accessToken, _refreshToken, params, profile, done) => { @@ -69,7 +82,11 @@ const githubVerifyCallback = async (accessToken, _refreshToken, params, profile, user.save() } } catch (error) { - logger.warn(error.stack) + logger.warn({ + event: 'USER_UPDATE_ERROR', + error: error, + msg: 'Error updating user' + }) } if (!user) { @@ -80,7 +97,11 @@ const githubVerifyCallback = async (accessToken, _refreshToken, params, profile, token: accessToken }) } catch (error) { - logger.warn(new Error(`Could not create new user ${error}`).stack) + logger.warn({ + event: 'USER_CREATE_ERROR', + error: error, + msg: 'Could not create new user' + }) } } @@ -95,7 +116,11 @@ const githubVerifyCallback = async (accessToken, _refreshToken, params, profile, repoRes.filter((repo) => repo.token).forEach((repo) => checkToken(repo, accessToken)) } } catch (error) { - logger.warn(new Error(error).stack) + logger.warn({ + event: 'REPO_UPDATE_ERROR', + error: error, + msg: 'Error updating repo' + }) } } if (params.scope.indexOf('admin:org_hook') >= 0) { @@ -110,7 +135,11 @@ const githubVerifyCallback = async (accessToken, _refreshToken, params, profile, orgRes.forEach((org) => checkToken(org, accessToken)) } } catch (error) { - logger.warn(new Error(error).stack) + logger.warn({ + event: 'ORG_UPDATE_ERROR', + error: error, + msg: 'Error updating org' + }) } } done(null, merge(profile._json, { diff --git a/src/server/src/services/cla.js b/src/server/src/services/cla.js index 21f1749ce..9f04264a6 100644 --- a/src/server/src/services/cla.js +++ b/src/server/src/services/cla.js @@ -48,14 +48,21 @@ class ClaService { // This helps to not use the complete rate limit for the CLA bot, while still keep working in case the user token gets revoked return await github.call(args) } catch (error) { - logger.error(new Error(error).stack) + logger.error({ + event: 'CLA_ERROR', + error: error, + msg: 'Error in CLA operation' + }) args.token = config.server.github.token return await github.call(args) } } async _checkAll(users, repoId, orgId, sharedGist, gist_url, gist_version, onDates, hasExternalCommiter) { - logger.debug(`checkPullRequestSignatures--> _checkAll for the repoId ${repoId} and orgId ${orgId}`) + logger.debug({ + event: 'CLA_DEBUG', + msg: `checkPullRequestSignatures--> _checkAll for the repoId ${repoId} and orgId ${orgId}` + }) let promises = [] const userMap = { signed: [], @@ -79,7 +86,10 @@ class ClaService { } } catch (error) { userMap.not_signed.push(user.name) - logger.info(`could not get signature of ${user.name} for repoId ${repoId}`) + logger.info({ + event: 'CLA_INFO', + msg: `could not get signature of ${user.name} for repoId ${repoId}` + }) } }) @@ -201,7 +211,11 @@ class ClaService { return orgMembers } catch (error) { - logger.error(new Error(error).stack) + logger.error({ + event: 'CLA_ERROR', + error: error, + msg: 'Error in CLA operation' + }) } } @@ -228,7 +242,11 @@ class ClaService { return orgMemberships } catch (error) { - logger.error(new Error(error).stack) + logger.error({ + event: 'CLA_ERROR', + error: error, + msg: 'Error in CLA operation' + }) } } @@ -298,7 +316,10 @@ class ClaService { async _getLastSignatureOnMultiDates(user, userId, repoId, orgId, sharedGist = false, gist_url, gist_version, date) { if ((!user && !userId) || (!repoId && !orgId) || !gist_url || (date && !Array.isArray(date))) { const msg = `Not enough arguments provided for getLastSignatureOnMultiDates() ${user} ${userId} ${repoId} ${orgId} ${sharedGist} ${gist_url} ${gist_version} ${date}` - logger.error(msg) + logger.error({ + event: 'CLA_ERROR', + msg: msg + }) throw new Error(msg) } let query = { @@ -319,7 +340,10 @@ class ClaService { query = this._updateQuery(query, sharedGist, date) - logger.info(`temporary debug - query: ${JSON.stringify(query)}`) + logger.info({ + event: 'CLA_INFO', + msg: `temporary debug - query: ${JSON.stringify(query)}` + }) let cla = await CLA.findOne(query, {}, { sort: { @@ -356,7 +380,11 @@ class ClaService { return false } catch (e) { - logger.error(new Error(e).stack) + logger.error({ + event: 'CLA_ERROR', + error: new Error(e), + msg: 'Error in CLA operation' + }) return true } @@ -548,7 +576,7 @@ class ClaService { if (committerSignatureRequired) { // logger.debug(`checkPullRequestSignatures-->getPRCommitters for the repo ${args.owner}/${args.repo}`) const committers = await repoService.getPRCommitters(args) - signees = _.uniqWith([...signees, ...committers], (object, other) => object.id == other.id) + signees = _.uniqWith(Array.prototype.concat(signees, committers), (object, other) => object.id == other.id) } signees = signees.filter(signee => @@ -628,7 +656,11 @@ class ClaService { argsToCreate.repo = item.repo } if (!argsToCreate.origin) { - logger.error(new Error('unknown origin of the signature')) + logger.error({ + event: 'CLA_ERROR', + error: new Error('unknown origin of the signature'), + msg: 'Unknown origin of signature' + }) argsToCreate.origin = `unknown|${args.user}` } @@ -639,11 +671,19 @@ class ClaService { owner: args.owner }).then((resp) => { if (resp.success) { - logger.info('repository migration successful:', args) + logger.info({ + event: 'CLA_INFO', + msg: 'repository migration successful', + args: args + }) } }) } catch (e) { - logger.debug('tried to migrate repository because someone signed a CLA but failed:', e) + logger.debug({ + event: 'CLA_DEBUG', + msg: 'tried to migrate repository because someone signed a CLA but failed', + error: e + }) } const signature = await this.create(argsToCreate) @@ -771,10 +811,16 @@ class ClaService { try { return CLA.find(selection, {}, options) } catch (error) { - logger.warn('Error occured when getting all signed CLAs for given repo without gist version' + error) - logger.warn('Api cla.getAll failed with selection ' + selection) - // eslint-disable-next-line no-console - console.log('Api cla.getAll failed with selection from console log ' + selection) + logger.warn({ + event: 'CLA_WARNING', + error: error, + msg: 'Warning in CLA operation' + }) + logger.warn({ + event: 'CLA_WARNING', + error: error, + msg: 'Warning in CLA operation' + }) } } try { @@ -784,7 +830,16 @@ class ClaService { } return clas } catch (error) { - logger.warn('Error occured when getting all signed CLAs for given repo ' + error) + logger.warn({ + event: 'CLA_WARNING', + error: error, + msg: 'Warning in CLA operation' + }) + logger.warn({ + event: 'CLA_WARNING', + error: error, + msg: 'Warning in CLA operation' + }) } @@ -825,11 +880,17 @@ class ClaService { const currentVersion = gist.data.history[0].version - logger.info(`temporary debug repoId: ${item.repoId}`) - logger.info(`temporary debug orgId: ${item.orgId}`) - logger.info(`temporary debug userId: ${args.userId}`) - logger.info(`temporary debug args.user: ${args.user}`) - logger.info(`temporary debug endDate: ${endDate}`) + logger.info({ + event: 'CLA_INFO', + msg: 'temporary debug', + data: { + repoId: item.repoId, + orgId: item.orgId, + userId: args.userId, + user: args.user, + endDate: endDate + } + }) const cla = await this._getLastSignatureOnMultiDates(args.user, args.userId, item.repoId, item.orgId, item.sharedGist, item.gist, currentVersion, onDates) @@ -852,13 +913,27 @@ class ClaService { const cla = await CLA.findOne({ _id: args._id }); if (user.id !== Number(cla.userId)) { - logger.error('User: ' + cla.user + ' is unauthorized to revoke cla with id: ' + cla._id); + logger.error({ + event: 'CLA_ERROR', + msg: 'User is unauthorized to revoke CLA', + data: { + user: cla.user, + claId: cla._id + } + }) throw new Error('Unauthorized to revoke CLA'); } cla.revoked_at = new Date(); await cla.save(); - logger.info('User: ' + cla.user + ' has revoked the cla for repo: ' + cla.repo); + logger.info({ + event: 'CLA_INFO', + msg: 'User has revoked the CLA', + data: { + user: cla.user, + repo: cla.repo + } + }); return cla; diff --git a/src/server/src/services/github.js b/src/server/src/services/github.js index ed1303d57..b28de92f6 100644 --- a/src/server/src/services/github.js +++ b/src/server/src/services/github.js @@ -24,15 +24,33 @@ const OctokitWithPluginsAndDefaults = Octokit.plugin( userAgent: 'CLA assistant', throttle: { onRateLimit: (retryAfter, options) => { - logger.info(`Request quota exhausted for request ${options.method} ${options.url}`) + logger.warn({ + event: 'RATE_LIMIT_EXHAUSTED', + method: options.method, + url: options.url, + retry_after: retryAfter, + msg: `Request quota exhausted for request ${options.method} ${options.url}` + }) if (options.request.retryCount === 0) { // only retries once - logger.info(`Retrying after ${retryAfter} seconds!`) + logger.info({ + event: 'RATE_LIMIT_RETRY', + method: options.method, + url: options.url, + retry_after: retryAfter, + msg: `Retrying after ${retryAfter} seconds!` + }) return true } }, onAbuseLimit: (retryAfter, options) => { // does not retry, only logs a warning - logger.info(`Abuse detected for request ${options.method} ${options.url}`) + logger.warn({ + event: 'RATE_LIMIT_ABUSE', + method: options.method, + url: options.url, + retry_after: retryAfter, + msg: `Abuse detected for request ${options.method} ${options.url}` + }) } } }) @@ -41,7 +59,11 @@ async function callGithub(octokit, obj, fun, arg, cacheKey, cacheTime) { if (cacheKey && !config.server.nocache) { const cachedRes = cache.get(cacheKey) if (cachedRes) { - logger.info(`Result returned from cache for ${obj}.${fun}`) + logger.info({ + event: 'CACHE_HIT', + operation: `${obj}.${fun}`, + msg: `Result returned from cache for ${obj}.${fun}` + }) return cachedRes } } @@ -161,7 +183,13 @@ const githubService = { try { return callGithub(octokit, obj, fun, arg, cacheKey, arg.cacheTime) } catch (error) { - logger.info(`${error} - Error on callGithub.${obj}.${fun} with args ${arg}.`) + logger.error({ + event: 'GITHUB_API_ERROR', + operation: `callGithub.${obj}.${fun}`, + args: arg, + error: error, + msg: `${error} - Error on callGithub.${obj}.${fun} with args ${arg}.` + }) throw new Error(error) } }, @@ -188,12 +216,20 @@ const githubService = { delete request.owner const token = await getInstallationAccessTokenForUser(username) request.token = token - if (printLog) logger.info(request) + if (printLog) logger.info({ + event: 'GITHUB_API_REQUEST', + request: request, + msg: 'Making GitHub API request' + }) } catch (error) { if (throwError) { throw error } - logger.error(error); + logger.error({ + event: 'GITHUB_API_ERROR', + error: error, + msg: 'Error in GitHub API call' + }); } return githubService.call(request); }, @@ -204,9 +240,17 @@ const githubService = { delete query.owner const ghsToken = await getInstallationAccessTokenForUser(username) token = ghsToken - logger.info(query) + logger.info({ + event: 'GITHUB_GRAPHQL_REQUEST', + query: query, + msg: 'Making GitHub GraphQL request' + }) } catch (error) { - logger.error(error); + logger.error({ + event: 'GITHUB_GRAPHQL_ERROR', + error: error, + msg: 'Error in GitHub GraphQL call' + }); } return githubService.callGraphql(query, token); } diff --git a/src/server/src/services/logger.js b/src/server/src/services/logger.js index 4339556ac..396eeaf52 100644 --- a/src/server/src/services/logger.js +++ b/src/server/src/services/logger.js @@ -5,45 +5,97 @@ const bunyan = require('bunyan') const BunyanSlack = require('bunyan-slack') const rTracer = require('cls-rtracer') +const os = require('os') +const config = require('../config') +// Get environment and service info +const ENV = process.env.NODE_ENV || 'development' +const SERVICE_NAME = 'cla-assistant' +const HOSTNAME = os.hostname() +const REGION = process.env.REGION || 'unknown' + +// Custom serializers for consistent JSON formatting +const serializers = { + err: bunyan.stdSerializers.err, + req: (req) => { + if (!req) return req + return { + method: req.method, + url: req.url, + headers: req.headers, + remoteAddress: req.connection && req.connection.remoteAddress, + remotePort: req.connection && req.connection.remotePort + } + }, + res: (res) => { + if (!res) return res + return { + statusCode: res.statusCode, + headers: res._headers + } + } +} + +// Custom formatter for Slack notifications const formatter = (record, levelName) => { return { text: `[${levelName}] ${record.msg} (source: ${record.src.file} line: ${record.src.line})` } } -// we use a custom Stdout writer, which injects for each call the request id -const wrappedStdout = { - write: entry => { +// Custom stream that injects request context and standard fields +const createWrappedStream = (stream) => ({ + write: (entry) => { const logObject = JSON.parse(entry) - let traceId = rTracer.id() + + // Add standard fields + logObject.service = SERVICE_NAME + logObject.env = ENV + logObject.hostname = HOSTNAME + logObject.region = REGION + logObject.timestamp = new Date().toISOString() + + // Add request context if available + const traceId = rTracer.id() if (traceId) { - if (config.server.observability.request_trace_header_name == 'traceparent') { - const traceParts = traceId.split('-'); - // check if it conforms to version 00 of opentelemetry spec (https://www.w3.org/TR/trace-context) - // version "-" trace-id "-" parent-id "-" trace-flags - if (traceParts.length == 4 && traceParts[0] == '00') { - traceId = traceParts[1] + if (config.server.observability.request_trace_header_name === 'traceparent') { + const traceParts = traceId.split('-') + if (traceParts.length === 4 && traceParts[0] === '00') { + logObject.request_id = traceParts[1] } + } else { + logObject.request_id = `${config.server.observability.trace_prefix}${traceId}` } - logObject[config.server.observability.log_trace_field_name] = `${config.server.observability.trace_prefix}${traceId}`; } - process.stdout.write(JSON.stringify(logObject) + '\n'); + + // Ensure log level is uppercase + if (typeof logObject.level === 'string') { + logObject.level = logObject.level.toUpperCase() + } + + // Add event type if not present + if (!logObject.event) { + logObject.event = 'LOG' + } + + stream.write(JSON.stringify(logObject) + '\n') } -} +}) +// Create logger instance const log = bunyan.createLogger({ - src: true, - name: config.server.http.host, + name: SERVICE_NAME, + serializers, streams: [{ name: 'stdout', - level: process.env.ENV == 'debug' ? 'info' : 'debug', - stream: wrappedStdout, + level: process.env.LOG_LEVEL || (ENV === 'production' ? 'info' : 'debug'), + stream: createWrappedStream(process.stdout) }] -}); +}) -try { - if (config.server.slack.url) { +// Add Slack stream if configured +if (config.server.slack.url) { + try { log.addStream({ name: 'slack', level: 'error', @@ -54,9 +106,71 @@ try { customFormatter: formatter }) }) + } catch (e) { + log.error({ error: e }, 'Failed to initialize Slack logging') + } +} + +// Helper methods for common logging patterns +const helpers = { + startRequest: (req) => { + log.info({ + event: 'REQUEST_STARTED', + req, + msg: `Started ${req.method} ${req.url}` + }) + }, + + endRequest: (req, res, duration) => { + log.info({ + event: 'REQUEST_COMPLETED', + req, + res, + duration_ms: duration, + msg: `Completed ${req.method} ${req.url} in ${duration}ms` + }) + }, + + error: (error, context) => { + const logContext = Object.assign({}, context) + const logEntry = { + event: 'ERROR', + error, + msg: error.message || 'An error occurred' + } + Object.assign(logEntry, logContext) + log.error(logEntry) + }, + + warn: (message, context) => { + const logContext = Object.assign({}, context) + const logEntry = { + event: 'WARNING', + msg: message + } + Object.assign(logEntry, logContext) + log.warn(logEntry) + }, + + info: (message, context) => { + const logContext = Object.assign({}, context) + const logEntry = { + event: 'INFO', + msg: message + } + Object.assign(logEntry, logContext) + log.info(logEntry) + }, + + debug: (message, context) => { + const logContext = Object.assign({}, context) + const logEntry = { + event: 'DEBUG', + msg: message + } + Object.assign(logEntry, logContext) + log.debug(logEntry) } -} catch (e) { - log.info(e) } -module.exports = log +module.exports = Object.assign({}, log, helpers) diff --git a/src/server/src/services/octokit-plugins/network-interceptor.js b/src/server/src/services/octokit-plugins/network-interceptor.js index b7ba38c1a..be009dba4 100644 --- a/src/server/src/services/octokit-plugins/network-interceptor.js +++ b/src/server/src/services/octokit-plugins/network-interceptor.js @@ -6,10 +6,19 @@ const logger = require('../logger') function rateLimitLogger(octokit) { octokit.hook.after('request', async (response, options) => { - logger.info(`${options.method} ${options.url}: ${response.status} || Rate Limit: ${response.headers['x-ratelimit-remaining']}/${response.headers['x-ratelimit-limit']} reset at ${new Date(Number(response.headers['x-ratelimit-reset']) * 1000).toTimeString()}`) + logger.info({ + event: 'GITHUB_API_RESPONSE', + method: options.method, + url: options.url, + status: response.status, + rate_limit: { + remaining: response.headers['x-ratelimit-remaining'], + limit: response.headers['x-ratelimit-limit'], + reset: new Date(Number(response.headers['x-ratelimit-reset']) * 1000).toISOString() + }, + msg: `${options.method} ${options.url}: ${response.status} || Rate Limit: ${response.headers['x-ratelimit-remaining']}/${response.headers['x-ratelimit-limit']} reset at ${new Date(Number(response.headers['x-ratelimit-reset']) * 1000).toTimeString()}` + }) }) } -module.exports = { - rateLimitLogger, -} +module.exports = rateLimitLogger diff --git a/src/server/src/services/org.js b/src/server/src/services/org.js index df75d6a70..4b898bf62 100644 --- a/src/server/src/services/org.js +++ b/src/server/src/services/org.js @@ -80,23 +80,36 @@ class OrgService { } catch(error) { return _resp('GitHub App not installed') } - logger.debug('generated app token:', appToken) + logger.debug({ + event: 'APP_TOKEN_GENERATED', + msg: 'Generated app token' + }) // remove token from database - logger.info('Removing token from organization object') + logger.info({ + event: 'TOKEN_REMOVAL', + msg: 'Removing token from organization object' + }) org.token = undefined try { await org.save() } catch(error) { return _resp('Cannot save organization') } - logger.info('done!') + logger.info({ + event: 'OPERATION_COMPLETE', + msg: 'Operation completed successfully' + }) // remove webhook from organization try { await webhookService.removeOrgHook(org.org, appToken) } catch(error) { - logger.warn('cannot remove webhook/s from repository:', error.toString()) + logger.warn({ + event: 'WEBHOOK_REMOVAL_ERROR', + error: error, + msg: 'Cannot remove webhook/s from organization' + }) } return _resp('Migration successful', true) diff --git a/src/server/src/services/pullRequest.js b/src/server/src/services/pullRequest.js index d1ab5c36b..e07c9b957 100644 --- a/src/server/src/services/pullRequest.js +++ b/src/server/src/services/pullRequest.js @@ -76,7 +76,12 @@ class PullRequestService { arg.comment_id = comment.id return updateCommentOfDeprecatedUser(arg, pullNumber, owner, repo) } else if (arg.body === comment.body) { - logger.debug(`Skip updateComment for the PR ${url.githubHttpPullRequest(owner, repo, pullNumber)} as there are no text changes`) + logger.debug({ + event: 'COMMENT_SKIP_UPDATE', + repo: `${owner}/${repo}`, + pull_number: pullNumber, + msg: `Skip updateComment for the PR ${url.githubHttpPullRequest(owner, repo, pullNumber)} as there are no text changes` + }) return } fun = 'updateComment' @@ -92,8 +97,18 @@ class PullRequestService { token: config.server.github.token, owner }).catch((error) => { - logger.debug(`Failed on api call issues/${fun} for PR ${url.githubHttpPullRequest(owner, repo, pullNumber)}`) - logger.warn(new Error(error).stack) + logger.debug({ + event: 'COMMENT_UPDATE_FAILED', + repo: `${owner}/${repo}`, + pull_number: pullNumber, + error: error, + msg: `Failed on api call issues/${fun} for PR ${url.githubHttpPullRequest(owner, repo, pullNumber)}` + }) + logger.warn({ + event: 'COMMENT_UPDATE_ERROR', + error: error, + msg: 'Error updating comment' + }) }) } catch (error) { logger.warn(new Error(error).stack) @@ -146,7 +161,12 @@ class PullRequestService { owner: args.owner }) } catch (error) { - logger.warn(new Error(`${error} with args: ${args}`).stack) + logger.warn({ + event: 'COMMENT_UPDATE_ERROR', + error: error, + args: args, + msg: `Error updating comment with args: ${args}` + }) } } @@ -189,7 +209,10 @@ function updateCommentOfDeprecatedUser(arg, pullNumber, owner, repo) { token: config.server.github.token_old, owner: arg.owner }).catch(() => { - logger.debug('Failed on deleting comment from the old user') + logger.debug({ + event: 'COMMENT_DELETE_FAILED', + msg: 'Failed on deleting comment from the old user' + }) }) arg.issue_number = pullNumber github.callWithGitHubApp({ @@ -199,7 +222,15 @@ function updateCommentOfDeprecatedUser(arg, pullNumber, owner, repo) { token: config.server.github.token, owner: arg.owner }).catch(() => { - logger.debug('Failed on creating comment for CLAassistant user') + logger.debug({ + event: 'COMMENT_CREATE_FAILED', + msg: 'Failed on creating comment for CLAassistant user' + }) + }) + logger.debug({ + event: 'COMMENT_USER_CHANGE', + repo: `${owner}/${repo}`, + pull_number: pullNumber, + msg: `Changing comment user for PR ${url.githubHttpPullRequest(owner, repo, pullNumber)}` }) - logger.debug(`Changing comment user for PR ${url.githubHttpPullRequest(owner, repo, pullNumber)}`) } diff --git a/src/server/src/services/repo.js b/src/server/src/services/repo.js index 68693f13e..53e7b6089 100644 --- a/src/server/src/services/repo.js +++ b/src/server/src/services/repo.js @@ -195,7 +195,10 @@ class RepoService { } catch(error) { return _resp('GitHub App not installed') } - logger.debug('generated app token:', appToken) + logger.debug({ + event: 'APP_TOKEN_GENERATED', + msg: 'Generated app token' + }) // check if the app has permission to list pull requests try { @@ -211,25 +214,39 @@ class RepoService { }, }, true) } catch (error) { - logger.error(error) + logger.error({ + event: 'REPO_ERROR', + error: error, + msg: 'Error in repo operation' + }) return _resp('GitHub App has insufficient permissions') } // remove token from database - logger.info('Removing token from repository object') + logger.info({ + event: 'TOKEN_REMOVAL', + msg: 'Removing token from repository object' + }) repo.token = undefined try { await repo.save() } catch(error) { return _resp('Cannot save repository') } - logger.info('done!') + logger.info({ + event: 'OPERATION_COMPLETE', + msg: 'Operation completed successfully' + }) // remove webhook try { await webhookService.removeRepoHook(args.owner, args.repo, appToken) } catch(error) { - logger.warn('cannot remove webhook/s from repository:', error.toString()) + logger.warn({ + event: 'WEBHOOK_REMOVAL_ERROR', + error: error, + msg: 'Cannot remove webhook/s from repository' + }) } return _resp('Migration successful', true) @@ -268,9 +285,17 @@ class RepoService { let self = this let handleError = (err, message, a) => { - logger.warn(err) + logger.warn({ + event: 'REPO_ERROR', + error: err, + msg: 'Error in repo operation' + }) if (!a.count) { - logger.info('getPRCommitters with arg: ', a) + logger.info({ + event: 'PR_COMMITTERS_REQUEST', + args: a, + msg: 'Getting PR committers' + }) } throw new Error(message) } @@ -284,7 +309,11 @@ class RepoService { const body = await github.callGraphqlWithGitHubApp(query, arg.token) if (body.errors) { - logger.info(new Error(body.errors[0].message).stack) + logger.info({ + event: 'GRAPHQL_ERROR', + error: new Error(body.errors[0].message), + msg: 'GraphQL error occurred' + }) } const data = body.data diff --git a/src/server/src/services/status.js b/src/server/src/services/status.js index da3dfb730..56718168f 100644 --- a/src/server/src/services/status.js +++ b/src/server/src/services/status.js @@ -68,7 +68,12 @@ const getCombinedStatus = async (args) => { const createStatus = async (args, context, description, state, target_url) => { try { - logger.debug(`StatusService-->createStatus for the repo ${args.owner}/${args.repo}/pull/${args.number}`) + logger.debug({ + event: 'STATUS_CREATE', + repo: `${args.owner}/${args.repo}`, + pull_number: args.number, + msg: `Creating status for PR ${args.owner}/${args.repo}/pull/${args.number}` + }) return github.callWithGitHubApp({ obj: 'repos', fun: 'createCommitStatus', @@ -85,13 +90,22 @@ const createStatus = async (args, context, description, state, target_url) => { token: args.token }) } catch (error) { - logger.warn('Error on Create Status, possible cause - wrong token, saved token does not have enough rights: ') + logger.warn({ + event: 'STATUS_CREATE_PERMISSION_ERROR', + error: error, + msg: 'Error on Create Status, possible cause - wrong token, saved token does not have enough rights' + }) } } const findStatusToBeChanged = async (args) => { try { - logger.debug(`StatusService-->findStatusToBeChanged for the repo ${args.owner}/${args.repo}/pull/${args.number}`) + logger.debug({ + event: 'STATUS_FIND', + repo: `${args.owner}/${args.repo}`, + pull_number: args.number, + msg: `Finding status to be changed for PR ${args.owner}/${args.repo}/pull/${args.number}` + }) const response = await getStatuses(args) // let statuses = '' const description = args.signed ? 'Contributor License Agreement is signed.' : 'Contributor License Agreement is not signed yet.' @@ -113,7 +127,11 @@ const findStatusToBeChanged = async (args) => { } return status } catch (error) { - logger.warn(error) + logger.warn({ + event: 'STATUS_FIND_ERROR', + error: error, + msg: 'Error finding status' + }) } } @@ -136,18 +154,39 @@ const findClaStatus = async (args) => { const updateStatus = async (args) => { try { - logger.debug(`StatusService-->updateStatus for the repo ${args.owner}/${args.repo}/pull/${args.number}`) + logger.debug({ + event: 'STATUS_UPDATE', + repo: `${args.owner}/${args.repo}`, + pull_number: args.number, + msg: `Updating status for PR ${args.owner}/${args.repo}/pull/${args.number}` + }) const status = await findStatusToBeChanged(args) if (!status) { - logger.debug(`StatusService-->updateStatus status remains the same - no need to update ${args.owner}/${args.repo}/pull/${args.number}`) + logger.debug({ + event: 'STATUS_NO_CHANGE', + repo: `${args.owner}/${args.repo}`, + pull_number: args.number, + msg: `Status remains the same - no need to update ${args.owner}/${args.repo}/pull/${args.number}` + }) return } return createStatus(args, status.context, status.description, status.state, status.target_url) } catch (error) { - logger.debug(`StatusService-->failed on updateStatus for the repo ${args.owner}/${args.repo}/pull/${args.number}`) - logger.warn(new Error(`${error} with args: ${args}`).stack) + logger.debug({ + event: 'STATUS_UPDATE_FAILED', + repo: `${args.owner}/${args.repo}`, + pull_number: args.number, + error: error, + msg: `Failed on updateStatus for the repo ${args.owner}/${args.repo}/pull/${args.number}` + }) + logger.warn({ + event: 'STATUS_UPDATE_ERROR', + error: error, + args: args, + msg: `Error updating status with args: ${args}` + }) } } @@ -160,12 +199,21 @@ const getPullRequestHeadShaIfNeeded = async (args) => { args.sha = pullRequest.head.sha return args } catch (error) { - logger.info(new Error(error + 'Cannot get pull request head.').stack) + logger.error({ + event: 'PR_HEAD_ERROR', + error: error, + msg: 'Cannot get pull request head' + }) } } const updateStatusIfNeeded = async (args, status, allowAbsent) => { - logger.debug(`StatusService-->updateStatusIfNeeded for the repo ${args.owner}/${args.repo}/pull/${args.number}`) + logger.debug({ + event: 'STATUS_UPDATE_CHECK', + repo: `${args.owner}/${args.repo}`, + pull_number: args.number, + msg: `Checking if status needs update for PR ${args.owner}/${args.repo}/pull/${args.number}` + }) if (!status) { return new Error('Status is required for updateStatusIfNeeded.') @@ -188,7 +236,10 @@ const updateStatusIfNeeded = async (args, status, allowAbsent) => { class StatusService { async update(args) { - logger.debug(`StatusService-->update for the repo ${args.owner}/${args.repo}/pull/${args.number}`) + logger.debug({ + event: 'STATUS_DEBUG', + msg: `StatusService-->update for the repo ${args.owner}/${args.repo}/pull/${args.number}` + }) if (args && !args.sha) { try { const resp = (await getPR(args)).data @@ -202,7 +253,11 @@ class StatusService { return updateStatus(args) } } catch (error) { - logger.warn(new Error(`${error} with args: ${args}`).stack) + logger.warn({ + event: 'STATUS_WARNING', + error: new Error(`${error} with args: ${args}`), + msg: 'Error in status operation with args' + }) } } if (args.sha) { @@ -220,7 +275,13 @@ class StatusService { } async updateForClaNotRequired(args) { - logger.debug(`StatusService-->updateForClaNotRequired for the repo ${args.owner}/${args.repo}/pull/${args.number}`) + logger.debug({ + event: 'PR_WEBHOOK_END', + msg: 'CLA not required for the repo', + repo: args.repo, + owner: args.owner, + number: args.number, + }) let status = { context: 'license/cla', state: 'success', @@ -230,7 +291,10 @@ class StatusService { } async updateForMergeQueue(args) { - logger.debug(`StatusService-->updateForMergeQueue for the repo ${args.owner}/${args.repo}/${args.sha}`) + logger.debug({ + event: 'STATUS_DEBUG', + msg: `StatusService-->updateForMergeQueue for the repo ${args.owner}/${args.repo}/${args.sha}` + }) let status = { context: 'license/cla', state: 'success', diff --git a/src/server/src/services/webhook.js b/src/server/src/services/webhook.js index ed5a6a337..9fc47aeec 100644 --- a/src/server/src/services/webhook.js +++ b/src/server/src/services/webhook.js @@ -88,7 +88,11 @@ class WebhookService { const res = await github.call(args) return res.data } catch (error) { - logger.info(new Error(error).stack) + logger.error({ + event: 'WEBHOOK_ERROR', + error: error, + msg: 'Error in webhook operation' + }) } } @@ -132,7 +136,11 @@ class WebhookService { try { return github.call(args) } catch (error) { - logger.info(new Error(error).stack) + logger.error({ + event: 'WEBHOOK_ERROR', + error: error, + msg: 'Error in webhook operation' + }) } } diff --git a/src/server/src/webhooks/pull_request.js b/src/server/src/webhooks/pull_request.js index 6c88a8351..68f20cfb6 100644 --- a/src/server/src/webhooks/pull_request.js +++ b/src/server/src/webhooks/pull_request.js @@ -25,7 +25,11 @@ function storeRequest(committers, repo, owner, number) { name: committer }) } catch (error) { - logger.warn(new Error(error).stack) + logger.warn({ + event: 'PR_WEBHOOK_WARNING', + error: error, + msg: 'Warning in PR webhook operation' + }) } const pullRequest = { repo: repo, @@ -39,7 +43,11 @@ function storeRequest(committers, repo, owner, number) { requests: [pullRequest] }) } catch (error) { - logger.warn(new Error(error).stack) + logger.warn({ + event: 'PR_WEBHOOK_WARNING', + error: error, + msg: 'Warning in PR webhook operation' + }) } return } @@ -70,9 +78,19 @@ async function updateStatusAndComment(args, item) { let checkResult try { checkResult = await cla.check(args, item) - logger.debug(`pullRequestWebhook-->updateStatusAndComment for the repo ${args.owner}/${args.repo}/pull/${args.number}`) + logger.debug({ + event: 'PR_WEBHOOK_DEBUG', + msg: 'reporting status and comment on PR', + repo: args.repo, + owner: args.owner, + number: args.number, + }) } catch (error) { - logger.warn(new Error(error).stack) + logger.error({ + event: 'PR_WEBHOOK_WARNING', + error: error, + msg: 'Warning in PR webhook operation' + }) } args.signed = checkResult.signed if (!checkResult.userMap || @@ -96,12 +114,29 @@ async function updateStatusAndComment(args, item) { } try { await Promise.all(promises) + logger.info({ + event: 'PR_WEBHOOK_END', + msg: 'updated status and comment on PR', + repo: args.repo, + owner: args.owner, + number: args.number, + }) } catch (error) { - logger.warn(new Error(`Could not update status and/or comment on PR. Args: ${JSON.stringify(args)}`).stack) + logger.error({ + event: 'PR_WEBHOOK_END', + error: new Error('could not update status and/or comment on PR'), + msg: 'Could not update status and/or comment on PR', + args: args + }) logger.warn(error) } } else { - logger.warn(new Error(`No committers found for the PR. Args: ${args}`).stack) + logger.warn({ + event: 'PR_WEBHOOK_WARNING', + error: new Error('No committers found for the PR'), + msg: 'No committers found for the PR', + args: args + }) } } catch (error) { if (!args.handleCount || args.handleCount < 2) { @@ -110,21 +145,41 @@ async function updateStatusAndComment(args, item) { updateStatusAndComment(args) }, 10000 * args.handleCount * args.handleDelay) } else { - logger.warn(new Error(error).stack, 'updateStatusAndComment called with args: ', args) + logger.error({ + event: 'PR_WEBHOOK_END', + error: error, + msg: 'PR webhook operation failed', + args: args + }) } } } async function handleWebHook(args, item) { + logger.info({ + event: 'PR_WEBHOOK_START', + msg: 'handleWebHook for the repo', + repo: args.repo, + owner: args.owner, + number: args.number, + }) + try { const claRequired = await cla.isClaRequired(args, item) if (claRequired) { - logger.debug('handleWebHook for the repo' + JSON.stringify(args.repo)) + logger.debug({ + event: 'PR_WEBHOOK_DEBUG', + msg: 'handleWebHook for the repo', + data: args.repo + }) return await updateStatusAndComment(args, item) } - logger.debug('no CLA required for the repo' + JSON.stringify(args.repo)) - + logger.debug({ + event: 'PR_WEBHOOK_DEBUG', + msg: 'no CLA required for the repo', + data: args.repo + }) await status.updateForClaNotRequired(args) return await pullRequest.deleteComment({ repo: args.repo, @@ -132,6 +187,11 @@ async function handleWebHook(args, item) { number: args.number }) } catch (error) { + logger.error({ + event: 'PR_WEBHOOK_ERROR', + error: error, + msg: 'Error in PR webhook operation' + }) return logger.error(error) } } @@ -141,6 +201,10 @@ module.exports = { return ['opened', 'reopened', 'synchronize'].indexOf(req.args.action) > -1 && (req.args.repository && req.args.repository.private == false) }, handle: async function (req, res) { + const startTime = Date.now(); + let status = 'success'; + let error = null; + res.status(200).send('OK - Will be working on it') const args = { owner: req.args.repository.owner.login, @@ -165,7 +229,28 @@ module.exports = { await handleWebHook(args, item) } } catch (e) { - logger.warn(e) + status = 'failure'; + error = e; + logger.warn({ + event: 'PR_WEBHOOK_WARNING', + error: e, + msg: 'Warning in PR webhook operation' + }) + } finally { + const duration = Date.now() - startTime; + logger.info({ + event: 'PR_WEBHOOK_COMPLETED', + msg: 'PR webhook processing completed', + status: status, + duration_ms: duration, + args: { + owner: args.owner, + repo: args.repo, + number: args.number, + action: req.args.action + }, + error: error + }); } } } From 0784c91c9671a1cc6e5e8e2fb142736ce20cb915 Mon Sep 17 00:00:00 2001 From: Harshvardhan Karn Date: Tue, 15 Apr 2025 12:20:13 +0530 Subject: [PATCH 2/2] test: Fix logger service test stubbing and assertions --- src/server/src/services/cla.js | 10 -- src/server/src/webhooks/pull_request.js | 2 +- src/tests/server/services/logger.js | 140 ++++++++++++++++++++++++ 3 files changed, 141 insertions(+), 11 deletions(-) create mode 100644 src/tests/server/services/logger.js diff --git a/src/server/src/services/cla.js b/src/server/src/services/cla.js index 9f04264a6..37b03ee6f 100644 --- a/src/server/src/services/cla.js +++ b/src/server/src/services/cla.js @@ -816,11 +816,6 @@ class ClaService { error: error, msg: 'Warning in CLA operation' }) - logger.warn({ - event: 'CLA_WARNING', - error: error, - msg: 'Warning in CLA operation' - }) } } try { @@ -835,11 +830,6 @@ class ClaService { error: error, msg: 'Warning in CLA operation' }) - logger.warn({ - event: 'CLA_WARNING', - error: error, - msg: 'Warning in CLA operation' - }) } diff --git a/src/server/src/webhooks/pull_request.js b/src/server/src/webhooks/pull_request.js index 68f20cfb6..38fe71122 100644 --- a/src/server/src/webhooks/pull_request.js +++ b/src/server/src/webhooks/pull_request.js @@ -86,7 +86,7 @@ async function updateStatusAndComment(args, item) { number: args.number, }) } catch (error) { - logger.error({ + logger.warn({ event: 'PR_WEBHOOK_WARNING', error: error, msg: 'Warning in PR webhook operation' diff --git a/src/tests/server/services/logger.js b/src/tests/server/services/logger.js new file mode 100644 index 000000000..a43e00389 --- /dev/null +++ b/src/tests/server/services/logger.js @@ -0,0 +1,140 @@ +// SPDX-FileCopyrightText: 2022 SAP SE or an SAP affiliate company and CLA-assistant contributors +// +// SPDX-License-Identifier: Apache-2.0 + +/*global describe, it, beforeEach, afterEach*/ +const assert = require('assert') +const sinon = require('sinon') +const bunyan = require('bunyan') + +describe('logger service', () => { + let logStub + let logger + + beforeEach(() => { + logStub = { + info: sinon.stub(), + error: sinon.stub(), + warn: sinon.stub(), + debug: sinon.stub() + } + // Stub bunyan.createLogger to return our stub + sinon.stub(bunyan, 'createLogger').returns(logStub) + // Clear require cache to force reload of logger + delete require.cache[require.resolve('../../../server/src/services/logger')] + logger = require('../../../server/src/services/logger') + }) + + afterEach(() => { + sinon.restore() + }) + + describe('startRequest', () => { + it('should log request start with context', () => { + const req = { + method: 'GET', + url: '/test', + headers: { + 'x-request-id': '123' + } + } + logger.startRequest(req) + assert(logStub.info.calledOnce) + const logCall = logStub.info.getCall(0).args[0] + assert.equal(logCall.event, 'REQUEST_STARTED') + assert.equal(logCall.msg, 'Started GET /test') + assert.deepEqual(logCall.req, { + method: 'GET', + url: '/test', + headers: { + 'x-request-id': '123' + } + }) + }) + }) + + describe('endRequest', () => { + it('should log request end with duration and status', () => { + const req = { + method: 'GET', + url: '/test', + headers: { + 'x-request-id': '123' + } + } + const res = { + statusCode: 200 + } + const duration = 100 + logger.endRequest(req, res, duration) + assert(logStub.info.calledOnce) + const logCall = logStub.info.getCall(0).args[0] + assert.equal(logCall.event, 'REQUEST_COMPLETED') + assert.equal(logCall.msg, 'Completed GET /test in 100ms') + assert.deepEqual(logCall.req, { + method: 'GET', + url: '/test', + headers: { + 'x-request-id': '123' + } + }) + assert.deepEqual(logCall.res, { + statusCode: 200 + }) + assert.equal(logCall.duration_ms, duration) + }) + }) + + describe('info', () => { + it('should log info with context', () => { + const message = 'test message' + const context = { key: 'value' } + logger.info(message, context) + assert(logStub.info.calledOnce) + const logCall = logStub.info.getCall(0).args[0] + assert.equal(logCall.event, 'INFO') + assert.equal(logCall.msg, message) + assert.equal(logCall.key, 'value') + }) + }) + + describe('error', () => { + it('should log error with context', () => { + const error = new Error('test error') + const context = { key: 'value' } + logger.error(error, context) + assert(logStub.error.calledOnce) + const logCall = logStub.error.getCall(0).args[0] + assert.equal(logCall.event, 'ERROR') + assert.equal(logCall.msg, 'test error') + assert.equal(logCall.error, error) + assert.equal(logCall.key, 'value') + }) + }) + + describe('warn', () => { + it('should log warning with context', () => { + const message = 'test warning' + const context = { key: 'value' } + logger.warn(message, context) + assert(logStub.warn.calledOnce) + const logCall = logStub.warn.getCall(0).args[0] + assert.equal(logCall.event, 'WARNING') + assert.equal(logCall.msg, message) + assert.equal(logCall.key, 'value') + }) + }) + + describe('debug', () => { + it('should log debug with context', () => { + const message = 'test debug' + const context = { key: 'value' } + logger.debug(message, context) + assert(logStub.debug.calledOnce) + const logCall = logStub.debug.getCall(0).args[0] + assert.equal(logCall.event, 'DEBUG') + assert.equal(logCall.msg, message) + assert.equal(logCall.key, 'value') + }) + }) +}) \ No newline at end of file