feat(log): Implement structured logging

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') {

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

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,

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', {

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()
+}

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, {