huanld/speckle-server
1
0
Fork 0
Code Issues Pull Requests Actions 1 Packages Projects Releases Wiki Activity

feat(logging): log all http requests and responses (#1416)

Browse Source 
- feat(logging): log all http requests and responses
- the auto logger does not log the body, to ensure sensitive payloads are not logged. Unfortunately this means that error messages are not logged either, so need to be manually logged.
- fix(logging): 400 errors should be info not error severity logging
This commit is contained in:
Iain Sproat
2023-02-27 15:14:56 +00:00
committed by GitHub
parent b9d68efc55
commit 7e89950358
13 changed files with 137 additions and 81 deletions
Download Patch File Download Diff File Expand all files Collapse all files
packages/server/app.ts
+6 -6
View File
@@ -11,7 +11,10 @@ import { createTerminus } from '@godaddy/terminus'
import * as Sentry from '@sentry/node'
import Logging from '@/logging'
import { startupLogger, shutdownLogger } from '@/logging/logging'
import { LoggingExpressMiddleware } from '@/logging/expressLogging'
import {
DetermineRequestIdMiddleware,
LoggingExpressMiddleware
} from '@/logging/expressLogging'
import { errorLoggingMiddleware } from '@/logging/errorLogging'
import prometheusClient from 'prom-client'
@@ -183,9 +186,8 @@ export async function init() {
// Should perhaps be done manually?
await knex.migrate.latest()
if (process.env.NODE_ENV !== 'test') {
app.use(LoggingExpressMiddleware)
}
app.use(DetermineRequestIdMiddleware)
app.use(LoggingExpressMiddleware)
if (process.env.COMPRESSION) {
app.use(compression())
@@ -217,12 +219,10 @@ export async function init() {
// Expose prometheus metrics
app.get('/metrics', async (req, res) => {
const boundLogger = startupLogger.child({ endpoint: '/metrics' })
try {
res.set('Content-Type', prometheusClient.register.contentType)
res.end(await prometheusClient.register.metrics())
} catch (ex: unknown) {
boundLogger.error(ex, 'Error while retrieving metrics.')
res.status(500).end(ex instanceof Error ? ex.message : `${ex}`)
}
})
packages/server/logging/expressLogging.ts
+80 -1
View File
@@ -1,7 +1,86 @@
import { logger } from './logging'
import { randomUUID } from 'crypto'
import HttpLogger from 'pino-http'
import { IncomingMessage } from 'http'
import { NextFunction, Response } from 'express'
import pino, { SerializedResponse } from 'pino'
import { GenReqId } from 'pino-http'
const REQUEST_ID_HEADER = 'x-request-id'
const GenerateRequestId: GenReqId = (req: IncomingMessage) => DetermineRequestId(req)
const DetermineRequestId = (
req: IncomingMessage,
uuidGenerator: () => string = randomUUID
): string => {
const headers = req.headers[REQUEST_ID_HEADER]
if (!Array.isArray(headers)) return headers || uuidGenerator()
return headers[0] || uuidGenerator()
}
export const LoggingExpressMiddleware = HttpLogger({
logger,
autoLogging: false
autoLogging: true,
genReqId: GenerateRequestId,
customLogLevel: (req, res, err) => {
if (res.statusCode >= 400 && res.statusCode < 500) {
return 'info'
} else if (res.statusCode >= 500 || err) {
return 'error'
} else if (res.statusCode >= 300 && res.statusCode < 400) {
return 'silent'
}
return 'info'
},
// we need to redact any potential sensitive data from being logged.
// as we do not know what headers may be sent in a request by a user or client
// we have to allow list selected headers
serializers: {
req: pino.stdSerializers.wrapRequestSerializer((req) => {
return {
id: req.raw.id,
method: req.raw.method,
path: req.raw.url?.split('?')[0], // Remove query params which might be sensitive
// Allowlist useful headers
headers: {
host: req.raw.headers.host,
'user-agent': req.raw.headers['user-agent'],
'x-request-id': req.raw.headers[REQUEST_ID_HEADER],
referer: req.raw.headers.referer
}
}
}),
res: pino.stdSerializers.wrapResponseSerializer((res) => {
const resRaw = res as SerializedResponse & {
raw: {
headers: Record<string, string>
}
}
return {
statusCode: res.raw.statusCode,
// Allowlist useful headers
headers: {
'content-length': resRaw.raw.headers['content-length'],
'content-type': resRaw.raw.headers['content-type'],
'retry-after': resRaw.raw.headers['retry-after'],
'x-ratelimit-remaining': resRaw.raw.headers['x-ratelimit-remaining'],
'x-ratelimit-reset': resRaw.raw.headers['x-ratelimit-reset'],
'x-request-id': resRaw.raw.headers['x-request-id'],
'x-speckle-meditation': resRaw.raw.headers['x-speckle-meditation']
}
}
})
}
})
export const DetermineRequestIdMiddleware = (
req: IncomingMessage,
res: Response,
next: NextFunction
) => {
const id = DetermineRequestId(req)
res.setHeader(REQUEST_ID_HEADER, id)
next()
}
packages/server/logging/logging.ts
-1
View File
@@ -23,5 +23,4 @@ export const uploadEndpointLogger = extendLoggerComponent(logger, 'upload-endpoi
export const dbLogger = extendLoggerComponent(logger, 'db')
export const servicesLogger = extendLoggerComponent(logger, 'services')
export const rateLimiterLogger = extendLoggerComponent(logger, 'rate-limiter')
export const authLogger = extendLoggerComponent(logger, 'auth')
export const redisLogger = extendLoggerComponent(logger, 'redis')
packages/server/modules/auth/rest/index.js
+4 -11
View File
@@ -14,7 +14,6 @@ const { revokeRefreshToken } = require(`@/modules/auth/services/apps`)
const { validateScopes } = require(`@/modules/shared`)
const { InvalidAccessCodeRequestError } = require('@/modules/auth/errors')
const { ForbiddenError } = require('apollo-server-errors')
const { authLogger } = require('@/logging/logging')
// TODO: Secure these endpoints!
module.exports = (app) => {
@@ -23,7 +22,6 @@ module.exports = (app) => {
TODO: ensure same origin.
*/
app.get('/auth/accesscode', async (req, res) => {
const boundLogger = authLogger.child({ endpoint: '/auth/accesscode' })
try {
const appId = req.query.appId
const app = await getApp({ id: appId })
@@ -49,14 +47,11 @@ module.exports = (app) => {
err instanceof InvalidAccessCodeRequestError ||
err instanceof ForbiddenError
) {
boundLogger.info(
{ err },
'Invalid access code request error, or Forbidden error.'
)
res.log.info({ err }, 'Invalid access code request error, or Forbidden error.')
return res.status(400).send(err.message)
} else {
sentry({ err })
boundLogger.error(err)
res.log.error(err)
return res
.status(500)
.send('Something went wrong while processing your request')
@@ -69,7 +64,6 @@ module.exports = (app) => {
*/
app.options('/auth/token', cors())
app.post('/auth/token', cors(), async (req, res) => {
const boundLogger = authLogger.child({ endpoint: '/auth/token' })
try {
// Token refresh
if (req.body.refreshToken) {
@@ -104,7 +98,7 @@ module.exports = (app) => {
return res.send(authResponse)
} catch (err) {
sentry({ err })
boundLogger.warn(err)
res.log.info({ err }, 'Error while trying to generate a new token.')
return res.status(401).send({ err: err.message })
}
})
@@ -113,7 +107,6 @@ module.exports = (app) => {
Ensures a user is logged out by invalidating their token and refresh token.
*/
app.post('/auth/logout', async (req, res) => {
const boundLogger = authLogger.child({ endpoint: '/auth/logout' })
try {
const token = req.body.token
const refreshToken = req.body.refreshToken
@@ -126,7 +119,7 @@ module.exports = (app) => {
return res.status(200).send({ message: 'You have logged out.' })
} catch (err) {
sentry({ err })
boundLogger.error(err)
res.log.info({ err }, 'Error while trying to logout.')
return res.status(400).send('Something went wrong while trying to logout.')
}
})
packages/server/modules/auth/strategies/azure-ad.js
+6 -5
View File
@@ -12,7 +12,6 @@ const {
resolveAuthRedirectPath
} = require('@/modules/serverinvites/services/inviteProcessingService')
const { passportAuthenticate } = require('@/modules/auth/services/passportService')
const { authLogger } = require('@/logging/logging')
const { UserInputError } = require('@/modules/core/errors/userinput')
module.exports = async (app, session, sessionStorage, finalizeAuth) => {
@@ -51,7 +50,6 @@ module.exports = async (app, session, sessionStorage, finalizeAuth) => {
session,
passportAuthenticate('azuread-openidconnect'),
async (req, res, next) => {
let boundLogger = authLogger.child({ endpoint: '/auth/azure/callback' })
const serverInfo = await getServerInfo()
try {
@@ -112,7 +110,7 @@ module.exports = async (app, session, sessionStorage, finalizeAuth) => {
// ID is used later for verifying access token
req.user.id = myUser.id
boundLogger = boundLogger.child({ userId: myUser.id })
req.log = req.log.child({ userId: myUser.id })
// use the invite
await finalizeInvitedServerRegistration(user.email, myUser.id)
@@ -125,10 +123,13 @@ module.exports = async (app, session, sessionStorage, finalizeAuth) => {
} catch (err) {
switch (err.constructor) {
case UserInputError:
boundLogger.info(err)
req.log.info(
{ err },
'User input error during Azure AD authentication callback.'
)
break
default:
boundLogger.error(err)
req.log.error(err, 'Error during Azure AD authentication callback.')
}
return next()
}
packages/server/modules/auth/strategies/local.js
+7 -10
View File
@@ -17,7 +17,6 @@ const {
resolveAuthRedirectPath
} = require('@/modules/serverinvites/services/inviteProcessingService')
const { getIpFromRequest } = require('@/modules/shared/utils/ip')
const { authLogger } = require('@/logging/logging')
const { NoInviteFoundError } = require('@/modules/serverinvites/errors')
const {
UserInputError,
@@ -38,23 +37,22 @@ module.exports = async (app, session, sessionAppId, finalizeAuth) => {
session,
sessionAppId,
async (req, res, next) => {
const boundLogger = authLogger.child({ endpoint: '/auth/local/login' })
try {
const valid = await validatePasssword({
email: req.body.email,
password: req.body.password
})
if (!valid) throw new UserInputError('Invalid credentials')
if (!valid) throw new UserInputError('Invalid credentials.')
const user = await getUserByEmail({ email: req.body.email })
if (!user) throw new UserInputError('Invalid credentials')
if (!user) throw new UserInputError('Invalid credentials.')
req.user = { id: user.id }
return next()
} catch (err) {
boundLogger.info({ err }, 'Error while logging in.')
return res.status(401).send({ err: true, message: 'Invalid credentials' })
res.log.info({ err }, 'Error while logging in.')
return res.status(401).send({ err: true, message: 'Invalid credentials.' })
}
},
finalizeAuth
@@ -65,7 +63,6 @@ module.exports = async (app, session, sessionAppId, finalizeAuth) => {
session,
sessionAppId,
async (req, res, next) => {
let boundLogger = authLogger.child({ endpoint: '/auth/local/register' })
const serverInfo = await getServerInfo()
try {
if (!req.body.password) throw new UserInputError('Password missing')
@@ -102,7 +99,7 @@ module.exports = async (app, session, sessionAppId, finalizeAuth) => {
// so we go ahead and register the user
const userId = await createUser(user)
req.user = { id: userId, email: user.email }
boundLogger = boundLogger.child({ userId })
req.log = req.log.child({ userId })
// 4. use up all server-only invites the email had attached to it
await finalizeInvitedServerRegistration(user.email, userId)
@@ -116,10 +113,10 @@ module.exports = async (app, session, sessionAppId, finalizeAuth) => {
case PasswordTooShortError:
case UserInputError:
case NoInviteFoundError:
boundLogger.info({ err }, 'Error while registering user.')
res.log.info({ err }, 'Error while registering.')
return res.status(400).send({ err: err.message })
default:
boundLogger.error(err, 'Error while registering user.')
res.log.error(err, 'Error while registering.')
return res.status(500).send({ err: err.message })
}
}
packages/server/modules/blobstorage/index.js
+5 -6
View File
@@ -80,7 +80,6 @@ exports.init = async (app) => {
allowForAllRegisteredUsersOnPublicStreamsWithPublicComments
]),
async (req, res) => {
let boundLogger = logger.child({ endpoint: '/api/stream/:streamId/blob' })
// no checking of startup conditions, just dont init the endpoints if not configured right
//authorize request
const uploadOperations = {}
@@ -90,12 +89,12 @@ exports.init = async (app) => {
limits: { fileSize: getFileSizeLimit() }
})
const streamId = req.params.streamId
boundLogger = boundLogger.child({ streamId, userId: req.context.userId })
req.log = req.log.child({ streamId, userId: req.context.userId })
busboy.on('file', (formKey, file, info) => {
const { filename: fileName } = info
const fileType = fileName.split('.').pop().toLowerCase()
boundLogger = boundLogger.child({ fileName, fileType })
req.log = req.log.child({ fileName, fileType })
const registerUploadResult = (processingPromise) => {
finalizePromises.push(
processingPromise.then((resultItem) => ({ ...resultItem, formKey }))
@@ -112,7 +111,7 @@ exports.init = async (app) => {
}
}
boundLogger = boundLogger.child({ blobId })
req.log = req.log.child({ blobId })
uploadOperations[blobId] = uploadFileStream(
storeFileStream,
@@ -153,7 +152,7 @@ exports.init = async (app) => {
})
busboy.on('error', async (err) => {
boundLogger.info({ err }, 'Upload request error.')
res.log.info({ err }, 'Upload request error.')
//delete all started uploads
await Promise.all(
Object.keys(uploadOperations).map((blobId) =>
@@ -162,7 +161,7 @@ exports.init = async (app) => {
)
const status = 400
const response = 'Upload request error. The server logs may have more details'
const response = 'Upload request error. The server logs may have more details.'
res.status(status).end(response)
})
packages/server/modules/core/rest/diffDownload.js
+5 -7
View File
@@ -7,16 +7,14 @@ const { SpeckleObjectsStream } = require('./speckleObjectsStream')
const { getObjectsStream } = require('../services/objects')
const { pipeline, PassThrough } = require('stream')
const { logger } = require('@/logging/logging')
module.exports = (app) => {
app.options('/api/getobjects/:streamId', cors())
app.post('/api/getobjects/:streamId', cors(), async (req, res) => {
const boundLogger = logger.child({
req.log = req.log.child({
userId: req.context.userId || '-',
streamId: req.params.streamId,
endpoint: '/api/getobjects/:streamId'
streamId: req.params.streamId
})
const hasStreamAccess = await validatePermissionsReadStream(
req.params.streamId,
@@ -45,9 +43,9 @@ module.exports = (app) => {
res,
(err) => {
if (err) {
boundLogger.error(err, `App error streaming objects`)
req.log.error(err, `App error streaming objects`)
} else {
boundLogger.info(
req.log.info(
`Streamed ${childrenList.length} objects (size: ${
gzipStream.bytesWritten / 1000000
} MB)`
@@ -72,7 +70,7 @@ module.exports = (app) => {
})
}
} catch (ex) {
boundLogger.error(ex, `DB Error streaming objects`)
req.log.error(ex, `DB Error streaming objects`)
speckleObjStream.emit('error', new Error('Database streaming error'))
}
speckleObjStream.end()
packages/server/modules/core/rest/diffUpload.js
+4 -6
View File
@@ -5,16 +5,14 @@ const cors = require('cors')
const { validatePermissionsWriteStream } = require('./authUtils')
const { hasObjects } = require('../services/objects')
const { logger } = require('@/logging/logging')
module.exports = (app) => {
app.options('/api/diff/:streamId', cors())
app.post('/api/diff/:streamId', cors(), async (req, res) => {
const boundLogger = logger.child({
req.log = req.log.child({
userId: req.context.userId || '-',
streamId: req.params.streamId,
endpoint: '/api/diff/:streamId'
streamId: req.params.streamId
})
const hasStreamAccess = await validatePermissionsWriteStream(
req.params.streamId,
@@ -26,13 +24,13 @@ module.exports = (app) => {
const objectList = JSON.parse(req.body.objects)
boundLogger.info(`Diffing ${objectList.length} objects.`)
req.log.info(`Diffing ${objectList.length} objects.`)
const response = await hasObjects({
streamId: req.params.streamId,
objectIds: objectList
})
boundLogger.debug(response)
req.log.debug(response)
res.writeHead(200, {
'Content-Encoding': 'gzip',
'Content-Type': 'application/json'
packages/server/modules/core/rest/upload.js
+14 -16
View File
@@ -6,7 +6,6 @@ const Busboy = require('busboy')
const { validatePermissionsWriteStream } = require('./authUtils')
const { createObjectsBatched } = require('../services/objects')
const { uploadEndpointLogger } = require('@/logging/logging')
const MAX_FILE_SIZE = 50 * 1024 * 1024
@@ -14,10 +13,9 @@ module.exports = (app) => {
app.options('/objects/:streamId', cors())
app.post('/objects/:streamId', cors(), async (req, res) => {
const boundLogger = uploadEndpointLogger.child({
req.log = req.log.child({
userId: req.context.userId || '-',
streamId: req.params.streamId,
endpoint: '/objects/:streamId'
streamId: req.params.streamId
})
const hasStreamAccess = await validatePermissionsWriteStream(
@@ -54,7 +52,7 @@ module.exports = (app) => {
const gzippedBuffer = Buffer.concat(buffer)
if (gzippedBuffer.length > MAX_FILE_SIZE) {
boundLogger.error(
req.log.error(
`Upload error: Batch size too large (${gzippedBuffer.length} > ${MAX_FILE_SIZE})`
)
if (!requestDropped)
@@ -68,7 +66,7 @@ module.exports = (app) => {
const gunzippedBuffer = zlib.gunzipSync(gzippedBuffer).toString()
if (gunzippedBuffer.length > MAX_FILE_SIZE) {
boundLogger.error(
req.log.error(
`Upload error: Batch size too large (${gunzippedBuffer.length} > ${MAX_FILE_SIZE})`
)
if (!requestDropped)
@@ -83,7 +81,7 @@ module.exports = (app) => {
try {
objs = JSON.parse(gunzippedBuffer)
} catch (e) {
boundLogger.error(`Upload error: Batch not in JSON format`)
req.log.error(`Upload error: Batch not in JSON format`)
if (!requestDropped) res.status(400).send('Failed to parse data.')
requestDropped = true
}
@@ -98,7 +96,7 @@ module.exports = (app) => {
}
const promise = createObjectsBatched(req.params.streamId, objs).catch((e) => {
boundLogger.error(e, `Upload error.`)
req.log.error(e, `Upload error.`)
if (!requestDropped)
res
.status(400)
@@ -111,7 +109,7 @@ module.exports = (app) => {
await promise
boundLogger.info(
req.log.info(
{
durationSeconds: (Date.now() - t0) / 1000,
crtMemUsageMB: process.memoryUsage().heapUsed / 1024 / 1024,
@@ -138,7 +136,7 @@ module.exports = (app) => {
let objs = []
if (buffer.length > MAX_FILE_SIZE) {
boundLogger.error(
req.log.error(
`Upload error: Batch size too large (${buffer.length} > ${MAX_FILE_SIZE})`
)
if (!requestDropped)
@@ -151,7 +149,7 @@ module.exports = (app) => {
try {
objs = JSON.parse(buffer)
} catch (e) {
boundLogger.error(`Upload error: Batch not in JSON format`)
req.log.error(`Upload error: Batch not in JSON format`)
if (!requestDropped) res.status(400).send('Failed to parse data.')
requestDropped = true
}
@@ -165,7 +163,7 @@ module.exports = (app) => {
}
const promise = createObjectsBatched(req.params.streamId, objs).catch((e) => {
boundLogger.error(e, `Upload error.`)
req.log.error(e, `Upload error.`)
if (!requestDropped)
res
.status(400)
@@ -177,7 +175,7 @@ module.exports = (app) => {
promises.push(promise)
await promise
boundLogger.info(
req.log.info(
{
uploadedSizeMB: buffer.length / 1000000,
durationSeconds: (Date.now() - t0) / 1000,
@@ -188,7 +186,7 @@ module.exports = (app) => {
)
})
} else {
boundLogger.error(`Invalid ContentType header: ${mimeType}`)
req.log.info(`Invalid ContentType header: ${mimeType}`)
if (!requestDropped)
res
.status(400)
@@ -202,7 +200,7 @@ module.exports = (app) => {
busboy.on('finish', async () => {
if (requestDropped) return
boundLogger.info(
req.log.info(
{
crtMemUsageMB: process.memoryUsage().heapUsed / 1024 / 1024
},
@@ -219,7 +217,7 @@ module.exports = (app) => {
})
busboy.on('error', async (err) => {
boundLogger.info(`Upload error: ${err}`)
req.log.info(`Upload error: ${err}`)
if (!requestDropped)
res.status(400).end('Upload request error. The server logs have more details')
requestDropped = true
packages/server/modules/emails/rest/index.js
+1 -3
View File
@@ -1,4 +1,3 @@
const { authLogger } = require('@/logging/logging')
const { EmailVerificationFinalizationError } = require('@/modules/emails/errors')
const {
finalizeEmailVerification
@@ -6,7 +5,6 @@ const {
module.exports = (app) => {
app.get('/auth/verifyemail', async (req, res) => {
const boundLogger = authLogger.child({ endpoint: '/auth/verifyemail' })
try {
await finalizeEmailVerification(req.query.t)
return res.redirect('/?emailverifiedstatus=true')
@@ -15,7 +13,7 @@ module.exports = (app) => {
error instanceof EmailVerificationFinalizationError
? error.message
: 'Email verification unexpectedly failed'
boundLogger.info({ err: error }, 'Email verification failed.')
req.log.info({ err: error }, 'Email verification failed.')
return res.redirect(`/?emailverifiederror=${msg}`)
}
})
packages/server/modules/fileuploads/index.js
+3 -4
View File
@@ -5,7 +5,7 @@ const { saveUploadFile } = require('./services/fileuploads')
const request = require('request')
const { streamWritePermissions } = require('@/modules/shared/authz')
const { authMiddlewareCreator } = require('@/modules/shared/middleware')
const { moduleLogger, logger } = require('@/logging/logging')
const { moduleLogger } = require('@/logging/logging')
const saveFileUploads = async ({ userId, streamId, branchName, uploadResults }) => {
await Promise.all(
@@ -35,8 +35,7 @@ exports.init = async (app) => {
'/api/file/:fileType/:streamId/:branchName?',
authMiddlewareCreator(streamWritePermissions),
async (req, res) => {
const boundLogger = logger.child({
endpoint: '/api/file/:fileType/:streamId/:branchName?',
req.log = req.log.child({
streamId: req.params.streamId,
userId: req.context.userId,
branchName: req.params.branchName ?? 'main'
@@ -46,7 +45,7 @@ exports.init = async (app) => {
`${process.env.CANONICAL_URL}/api/stream/${req.params.streamId}/blob`,
async (err, response, body) => {
if (err) {
boundLogger.error(err)
res.log.error(err, 'Error while uploading blob.')
res.status(500).send(err.message)
return
}
packages/server/modules/pwdreset/rest/index.ts
+2 -5
View File
@@ -1,4 +1,3 @@
import { logger } from '@/logging/logging'
import { finalizePasswordReset } from '@/modules/pwdreset/services/finalize'
import { requestPasswordRecovery } from '@/modules/pwdreset/services/request'
import { ensureError } from '@/modules/shared/helpers/errorHelper'
@@ -7,28 +6,26 @@ import { Express } from 'express'
export default function (app: Express) {
// sends a password recovery email.
app.post('/auth/pwdreset/request', async (req, res) => {
const boundLogger = logger.child({ endpoint: 'auth/pwdreset/request' })
try {
const email = req.body.email
await requestPasswordRecovery(email)
return res.status(200).send('Password reset email sent.')
} catch (e: unknown) {
boundLogger.info({ err: e }, 'Error while requesting password recovery.')
req.log.info({ err: e }, 'Error while requesting password recovery.')
res.status(400).send(ensureError(e).message)
}
})
// Finalizes password recovery.
app.post('/auth/pwdreset/finalize', async (req, res) => {
const boundLogger = logger.child({ endpoint: 'auth/pwdreset/finalize' })
try {
if (!req.body.tokenId || !req.body.password) throw new Error('Invalid request.')
await finalizePasswordReset(req.body.tokenId, req.body.password)
return res.status(200).send('Password reset. Please log in.')
} catch (e: unknown) {
boundLogger.info({ err: e }, 'Error while finalizing password recovery.')
req.log.info({ err: e }, 'Error while finalizing password recovery.')
res.status(400).send(ensureError(e).message)
}
})