Skip to content

Commit 55343b9

Browse files
ibreakthecloudibreakthecloud
committed
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.
1 parent 9517715 commit 55343b9

File tree

16 files changed

+697
-126
lines changed

16 files changed

+697
-126
lines changed

‎src/server/src/app.js

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -23,6 +23,7 @@ const rTracer = require('cls-rtracer')
2323
const expressSession = require('express-session');
2424
const MongoStore = require('connect-mongo');
2525
const { verify: verifyWebhookSignature } = require('@octokit/webhooks-methods')
26+
const requestLogger = require('./middleware/request-logger')
2627

2728
// var sass_middleware = require('node-sass-middleware');
2829

@@ -52,6 +53,9 @@ if (config.server.observability.request_trace_header_name) {
5253
}
5354
app.use(rTracer.expressMiddleware(tracingOptions))
5455

56+
// Add request logging middleware
57+
app.use(requestLogger)
58+
5559
// redirect from http to https
5660
app.use((req, res, next) => {
5761
if (!req.headers['x-forwarded-proto'] || req.headers['x-forwarded-proto'] === 'https') {

‎src/server/src/controller/counts.js

Lines changed: 20 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -27,7 +27,11 @@ router.all('/count/repos', async (req, res) => {
2727
text: `There are ${repoCount} registered repositories!`
2828
}))
2929
} catch (error) {
30-
logger.info(error)
30+
logger.error({
31+
event: 'COUNTS_ERROR',
32+
error: error,
33+
msg: 'Error getting counts'
34+
})
3135
}
3236
})
3337

@@ -40,8 +44,11 @@ router.all('/count/orgs', async (req, res) => {
4044
text: `There are ${orgsCount} registered organizations!`
4145
}))
4246
} catch (error) {
43-
res.status(500).send(error)
44-
logger.info(error)
47+
logger.error({
48+
event: 'COUNTS_ERROR',
49+
error: error,
50+
msg: 'Error getting counts'
51+
})
4552
}
4653
})
4754

@@ -60,7 +67,11 @@ router.all('/count/clas', async (req, res) => {
6067
'$count': 'count'
6168
}])
6269
} catch (error) {
63-
logger.info(error)
70+
logger.error({
71+
event: 'COUNTS_ERROR',
72+
error: error,
73+
msg: 'Error getting counts'
74+
})
6475
}
6576
if (!Array.isArray(data) || data[0].count === undefined) {
6677
data = [{ count: 0 }]
@@ -89,7 +100,11 @@ router.all('/count/stars', async (_req, res) => {
89100
owner: 'cla-assistant'
90101
})
91102
} catch (error) {
92-
logger.info(error)
103+
logger.error({
104+
event: 'COUNTS_ERROR',
105+
error: error,
106+
msg: 'Error getting counts'
107+
})
93108
}
94109
res.send(JSON.stringify({
95110
count: resp.data.stargazers_count

‎src/server/src/controller/default.js

Lines changed: 12 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -27,7 +27,11 @@ router.use('/accept/:owner/:repo', async (req, res) => {
2727
await cla.sign(req)
2828
} catch (e) {
2929
if (e && (!e.code || e.code != 200)) {
30-
logger.error(e)
30+
logger.error({
31+
event: 'ERROR',
32+
error: e,
33+
msg: 'Error processing request'
34+
})
3135

3236
return
3337
}
@@ -63,7 +67,13 @@ router.all('/static/*', (req, res) => {
6367
router.get('/check/:owner/:repo', (req, res) => {
6468
let referer = req.header('Referer')
6569
let back = referer && referer.includes('github.com') ? referer : 'https://github.com'
66-
logger.info('Recheck PR requested for ', `https://github.com/${req.params.owner}/${req.params.repo}/pull/${req.query.pullRequest}`, `referer was ${referer}`)
70+
logger.info({
71+
event: 'PR_RECHECK_REQUESTED',
72+
repo: `${req.params.owner}/${req.params.repo}`,
73+
pull_number: req.query.pullRequest,
74+
referer: referer,
75+
msg: `Recheck PR requested for https://github.com/${req.params.owner}/${req.params.repo}/pull/${req.query.pullRequest}, referer was ${referer}`
76+
})
6777
cla.validatePullRequest({
6878
owner: req.params.owner,
6979
repo: req.params.repo,

‎src/server/src/controller/user.js

Lines changed: 26 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -38,7 +38,11 @@ function checkReturnTo(req, res, next) {
3838

3939
req.session.returnTo = req.query.public === 'true' ? req.session.next || req.headers.referer : '/'
4040

41-
logger.debug('Check returnTo and call passport authenticate with appropriate scope. return to:', req.session.returnTo)
41+
logger.debug({
42+
event: 'AUTH_SCOPE_CHECK',
43+
return_to: req.session.returnTo,
44+
msg: 'Check returnTo and call passport authenticate with appropriate scope'
45+
})
4246

4347
passport.authenticate(strategy, {
4448
scope: scope
@@ -48,8 +52,15 @@ function checkReturnTo(req, res, next) {
4852
router.get('/auth/github', checkReturnTo)
4953

5054
const githubCallbackPost = (req, res) => {
51-
logger.debug('Process authentication callback after passport authenticate')
52-
logger.debug('User scopes:', req.user)
55+
logger.debug({
56+
event: 'AUTH_CALLBACK_START',
57+
msg: 'Process authentication callback after passport authenticate'
58+
})
59+
logger.debug({
60+
event: 'USER_SCOPES',
61+
scopes: req.user,
62+
msg: 'User scopes'
63+
})
5364
if (req.user &&
5465
req.session.requiredScope !== 'public' &&
5566
utils.couldBeAdmin(req.user.login) &&
@@ -60,12 +71,18 @@ const githubCallbackPost = (req, res) => {
6071
}
6172
res.redirect(req.session.returnTo || req.headers.referer || '/')
6273
req.session.next = null
63-
logger.debug('Finish processing authentication callback after passport authenticate')
74+
logger.debug({
75+
event: 'AUTH_CALLBACK_END',
76+
msg: 'Finish processing authentication callback after passport authenticate'
77+
})
6478
}
6579

6680
router.get('/auth/github/callback',
6781
function (req, res, next) {
68-
logger.debug('Start processing OAuth authentication callback')
82+
logger.debug({
83+
event: 'OAUTH_CALLBACK_START',
84+
msg: 'Start processing OAuth authentication callback'
85+
})
6986
next()
7087
},
7188
passport.authenticate('github-oauth', {
@@ -76,7 +93,10 @@ router.get('/auth/github/callback',
7693

7794
router.get('/auth/github/app-callback',
7895
function (req, res, next) {
79-
logger.debug('Start processing App authentication callback')
96+
logger.debug({
97+
event: 'APP_CALLBACK_START',
98+
msg: 'Start processing App authentication callback'
99+
})
80100
next()
81101
},
82102
passport.authenticate('github-app-auth', {

‎src/server/src/middleware/request-logger.js

Lines changed: 21 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,21 @@
1+
// SPDX-FileCopyrightText: 2022 SAP SE or an SAP affiliate company and CLA-assistant contributors
2+
//
3+
// SPDX-License-Identifier: Apache-2.0
4+
5+
const logger = require('../services/logger')
6+
7+
module.exports = (req, res, next) => {
8+
const start = process.hrtime()
9+
10+
// Log request start
11+
logger.startRequest(req)
12+
13+
// Log response when finished
14+
res.on('finish', () => {
15+
const duration = process.hrtime(start)
16+
const durationMs = (duration[0] * 1e9 + duration[1]) / 1e6
17+
logger.endRequest(req, res, durationMs)
18+
})
19+
20+
next()
21+
}

‎src/server/src/passports/github.js

Lines changed: 36 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -15,7 +15,12 @@ const github = require('../services/github')
1515
function updateToken(item, newToken) {
1616
item.token = newToken
1717
item.save()
18-
logger.debug('Update access token for repo / org', item.repo || item.org)
18+
logger.debug({
19+
event: 'TOKEN_UPDATE',
20+
item_type: item.repo ? 'repo' : 'org',
21+
item_name: item.repo || item.org,
22+
msg: `Update access token for ${item.repo ? 'repo' : 'org'} ${item.repo || item.org}`
23+
})
1924
}
2025

2126
async function checkToken(item, accessToken) {
@@ -45,14 +50,22 @@ async function checkToken(item, accessToken) {
4550
const ghRepo = await repoService.getGHRepo(item)
4651
if (!(ghRepo && ghRepo.permissions && ghRepo.permissions.admin)) {
4752
updateToken(item, newToken)
48-
logger.info(`Update access token for repo ${item.repo} admin rights have been changed`)
53+
logger.info({
54+
event: 'TOKEN_UPDATE_ADMIN',
55+
repo: item.repo,
56+
msg: `Update access token for repo ${item.repo} admin rights have been changed`
57+
})
4958
}
5059
}
5160
}
5261
} catch (error) {
5362
updateToken(item, newToken)
63+
logger.warn({
64+
event: 'TOKEN_UPDATE_ERROR',
65+
error: error,
66+
msg: 'Error updating token'
67+
})
5468
}
55-
5669
}
5770

5871
const githubVerifyCallback = async (accessToken, _refreshToken, params, profile, done) => {
@@ -69,7 +82,11 @@ const githubVerifyCallback = async (accessToken, _refreshToken, params, profile,
6982
user.save()
7083
}
7184
} catch (error) {
72-
logger.warn(error.stack)
85+
logger.warn({
86+
event: 'USER_UPDATE_ERROR',
87+
error: error,
88+
msg: 'Error updating user'
89+
})
7390
}
7491

7592
if (!user) {
@@ -80,7 +97,11 @@ const githubVerifyCallback = async (accessToken, _refreshToken, params, profile,
8097
token: accessToken
8198
})
8299
} catch (error) {
83-
logger.warn(new Error(`Could not create new user ${error}`).stack)
100+
logger.warn({
101+
event: 'USER_CREATE_ERROR',
102+
error: error,
103+
msg: 'Could not create new user'
104+
})
84105
}
85106
}
86107

@@ -95,7 +116,11 @@ const githubVerifyCallback = async (accessToken, _refreshToken, params, profile,
95116
repoRes.filter((repo) => repo.token).forEach((repo) => checkToken(repo, accessToken))
96117
}
97118
} catch (error) {
98-
logger.warn(new Error(error).stack)
119+
logger.warn({
120+
event: 'REPO_UPDATE_ERROR',
121+
error: error,
122+
msg: 'Error updating repo'
123+
})
99124
}
100125
}
101126
if (params.scope.indexOf('admin:org_hook') >= 0) {
@@ -110,7 +135,11 @@ const githubVerifyCallback = async (accessToken, _refreshToken, params, profile,
110135
orgRes.forEach((org) => checkToken(org, accessToken))
111136
}
112137
} catch (error) {
113-
logger.warn(new Error(error).stack)
138+
logger.warn({
139+
event: 'ORG_UPDATE_ERROR',
140+
error: error,
141+
msg: 'Error updating org'
142+
})
114143
}
115144
}
116145
done(null, merge(profile._json, {

0 commit comments

Comments
 (0)