From 8ce2579a17ec9e804b8dae793013b12c423be806 Mon Sep 17 00:00:00 2001 From: fenos Date: Fri, 29 Sep 2023 11:31:01 +0100 Subject: [PATCH] feat: standardise logs --- package-lock.json | 132 ++---------------- package.json | 4 +- src/http/error-handler.ts | 4 - src/http/plugins/db.ts | 47 ++++++- src/http/plugins/log-request.ts | 21 ++- src/http/plugins/log-tenant-id.ts | 1 + src/http/plugins/storage.ts | 1 + src/http/routes/bucket/createBucket.ts | 4 +- src/http/routes/bucket/getAllBuckets.ts | 2 - src/http/routes/bucket/getBucket.ts | 2 - src/http/routes/object/createObject.ts | 3 - src/http/routes/object/getPublicObject.ts | 1 - src/http/routes/object/listObjects.ts | 2 - src/http/routes/object/uploadSignedObject.ts | 3 - src/http/routes/render/renderSignedImage.ts | 1 - src/http/routes/tus/handlers.ts | 9 +- src/http/routes/tus/index.ts | 5 +- src/http/routes/tus/lifecycle.ts | 2 + src/monitoring/logflare.ts | 7 + src/monitoring/logger.ts | 48 ++++++- src/queue/events/base-event.ts | 1 + .../events/multipart-upload-completed.ts | 2 + src/queue/events/object-admin-delete.ts | 18 ++- src/queue/events/webhook.ts | 17 ++- src/server.ts | 31 ++-- src/storage/database/adapter.ts | 2 + src/storage/database/knex.ts | 2 + src/storage/errors.ts | 19 ++- src/storage/object.ts | 25 +++- src/storage/uploader.ts | 5 + src/test/webhooks.test.ts | 6 + 31 files changed, 225 insertions(+), 202 deletions(-) diff --git a/package-lock.json b/package-lock.json index b6e7d085..489cfd40 100644 --- a/package-lock.json +++ b/package-lock.json @@ -42,7 +42,7 @@ "pg-boss": "^8.1.1", "pg-listen": "^1.7.0", "pino": "^8.2.0", - "pino-logflare": "^0.3.12", + "pino-logflare": "^0.4.2", "postgres-migrations": "^5.3.0", "prom-client": "^14.0.1" }, @@ -3556,11 +3556,6 @@ "@types/node": "*" } }, - "node_modules/@types/lodash": { - "version": "4.14.184", - "resolved": "https://registry.npmjs.org/@types/lodash/-/lodash-4.14.184.tgz", - "integrity": "sha512-RoZphVtHbxPZizt4IcILciSWiC6dcn+eZ8oX9IWEYfDMcocdd42f7NPI6fQj+6zI8y4E0L7gu2pcZKLGTRaV9Q==" - }, "node_modules/@types/lru-cache": { "version": "7.10.10", "resolved": "https://registry.npmjs.org/@types/lru-cache/-/lru-cache-7.10.10.tgz", @@ -4278,22 +4273,6 @@ "node": ">=8.6.0" } }, - "node_modules/big-integer": { - "version": "1.6.51", - "resolved": "https://registry.npmjs.org/big-integer/-/big-integer-1.6.51.tgz", - "integrity": "sha512-GPEid2Y9QU1Exl1rpO9B2IPJGHPSupF5GnVIP0blYvNOMer2bTvSWs1jGOUg04hTmu67nmLsQ9TBo1puaotBHg==", - "engines": { - "node": ">=0.6" - } - }, - "node_modules/bignumber.js": { - "version": "9.1.0", - "resolved": "https://registry.npmjs.org/bignumber.js/-/bignumber.js-9.1.0.tgz", - "integrity": "sha512-4LwHK4nfDOraBCtst+wOWIHbu1vhvAPJK8g8nROd4iuc3PSEjWif/qwbkh8jwCJz6yDBvtU4KPynETgrfh7y3A==", - "engines": { - "node": "*" - } - }, "node_modules/binary-extensions": { "version": "2.2.0", "resolved": "https://registry.npmjs.org/binary-extensions/-/binary-extensions-2.2.0.tgz", @@ -4831,11 +4810,6 @@ } } }, - "node_modules/decimal.js": { - "version": "10.3.1", - "resolved": "https://registry.npmjs.org/decimal.js/-/decimal.js-10.3.1.tgz", - "integrity": "sha512-V0pfhfr8suzyPGOx3nmq4aHqabehUZn6Ch9kyFpV79TGDTWFmHqUqXdabR7QHqxzrYolF4+tVmJhUG4OURg5dQ==" - }, "node_modules/dedent": { "version": "0.7.0", "resolved": "https://registry.npmjs.org/dedent/-/dedent-0.7.0.tgz", @@ -7364,25 +7338,9 @@ } }, "node_modules/logflare-transport-core": { - "version": "0.2.5", - "resolved": "https://registry.npmjs.org/logflare-transport-core/-/logflare-transport-core-0.2.5.tgz", - "integrity": "sha512-CufxlLL81hAnJgaO8UL4AkeeyUHwrwEhcjI+w0VJY/5U7NaA5nwc+pyTXrTXH76UxHttauegGIjX2FfeA2XoQg==", - "dependencies": { - "@types/lodash": "^4.14.153", - "axios": "^0.21.1", - "big-integer": "^1.6.48", - "bignumber.js": "^9.0.0", - "decimal.js": "^10.2.0", - "lodash": "^4.17.15" - } - }, - "node_modules/logflare-transport-core/node_modules/axios": { - "version": "0.21.4", - "resolved": "https://registry.npmjs.org/axios/-/axios-0.21.4.tgz", - "integrity": "sha512-ut5vewkiu8jjGBdqpM44XxjuCjq9LAKeHVmoVfHVzy8eHgxxq8SbAVQNovDA8mVi05kP0Ea/n/UzcSHcTJQfNg==", - "dependencies": { - "follow-redirects": "^1.14.0" - } + "version": "0.3.3", + "resolved": "https://registry.npmjs.org/logflare-transport-core/-/logflare-transport-core-0.3.3.tgz", + "integrity": "sha512-n82NsRVWvlaa3jd9QQ8rDroCjCJcIamQOlarLDBou9RsF0QaRv39rduy0ToPmlGQn1OPZBwlsv+R36lXupSmVQ==" }, "node_modules/lru-cache": { "version": "7.17.0", @@ -7969,20 +7927,17 @@ } }, "node_modules/pino-logflare": { - "version": "0.3.12", - "resolved": "https://registry.npmjs.org/pino-logflare/-/pino-logflare-0.3.12.tgz", - "integrity": "sha512-+b61yGXEwrT3vDWg3YiX7qwBGEoNswwoNbaaHjiD08nXG1PPug2+Z3HM7E2eEWJ9ZTHksFy7svhul9gy/BTJ0Q==", + "version": "0.4.2", + "resolved": "https://registry.npmjs.org/pino-logflare/-/pino-logflare-0.4.2.tgz", + "integrity": "sha512-WiqSIpBGH2Cn1KOinB95ovxxsmHkx33/aF0zZy0iip7dIA/x2VRiPCo9/1+II4cls/rjcMmkoNOZHZx8zNWLGQ==", "dependencies": { - "axios": "^0.21.1", "batch2": "^1.0.6", "commander": "^5.0.0", "fast-json-parse": "^1.0.3", - "lodash": "^4.17.15", - "logflare-transport-core": "^0.2.5", + "logflare-transport-core": "^0.3.3", "pino": "^6.3.2", "pumpify": "^2.0.1", "split2": "^3.1.1", - "stream-browserify": "^3.0.0", "through2": "^3.0.1" }, "bin": { @@ -7992,14 +7947,6 @@ "node": ">=10.2.0" } }, - "node_modules/pino-logflare/node_modules/axios": { - "version": "0.21.4", - "resolved": "https://registry.npmjs.org/axios/-/axios-0.21.4.tgz", - "integrity": "sha512-ut5vewkiu8jjGBdqpM44XxjuCjq9LAKeHVmoVfHVzy8eHgxxq8SbAVQNovDA8mVi05kP0Ea/n/UzcSHcTJQfNg==", - "dependencies": { - "follow-redirects": "^1.14.0" - } - }, "node_modules/pino-logflare/node_modules/commander": { "version": "5.1.0", "resolved": "https://registry.npmjs.org/commander/-/commander-5.1.0.tgz", @@ -12674,11 +12621,6 @@ "@types/node": "*" } }, - "@types/lodash": { - "version": "4.14.184", - "resolved": "https://registry.npmjs.org/@types/lodash/-/lodash-4.14.184.tgz", - "integrity": "sha512-RoZphVtHbxPZizt4IcILciSWiC6dcn+eZ8oX9IWEYfDMcocdd42f7NPI6fQj+6zI8y4E0L7gu2pcZKLGTRaV9Q==" - }, "@types/lru-cache": { "version": "7.10.10", "resolved": "https://registry.npmjs.org/@types/lru-cache/-/lru-cache-7.10.10.tgz", @@ -13190,16 +13132,6 @@ "through2": "^3.0.1" } }, - "big-integer": { - "version": "1.6.51", - "resolved": "https://registry.npmjs.org/big-integer/-/big-integer-1.6.51.tgz", - "integrity": "sha512-GPEid2Y9QU1Exl1rpO9B2IPJGHPSupF5GnVIP0blYvNOMer2bTvSWs1jGOUg04hTmu67nmLsQ9TBo1puaotBHg==" - }, - "bignumber.js": { - "version": "9.1.0", - "resolved": "https://registry.npmjs.org/bignumber.js/-/bignumber.js-9.1.0.tgz", - "integrity": "sha512-4LwHK4nfDOraBCtst+wOWIHbu1vhvAPJK8g8nROd4iuc3PSEjWif/qwbkh8jwCJz6yDBvtU4KPynETgrfh7y3A==" - }, "binary-extensions": { "version": "2.2.0", "resolved": "https://registry.npmjs.org/binary-extensions/-/binary-extensions-2.2.0.tgz", @@ -13603,11 +13535,6 @@ "ms": "2.1.2" } }, - "decimal.js": { - "version": "10.3.1", - "resolved": "https://registry.npmjs.org/decimal.js/-/decimal.js-10.3.1.tgz", - "integrity": "sha512-V0pfhfr8suzyPGOx3nmq4aHqabehUZn6Ch9kyFpV79TGDTWFmHqUqXdabR7QHqxzrYolF4+tVmJhUG4OURg5dQ==" - }, "dedent": { "version": "0.7.0", "resolved": "https://registry.npmjs.org/dedent/-/dedent-0.7.0.tgz", @@ -15512,27 +15439,9 @@ } }, "logflare-transport-core": { - "version": "0.2.5", - "resolved": "https://registry.npmjs.org/logflare-transport-core/-/logflare-transport-core-0.2.5.tgz", - "integrity": "sha512-CufxlLL81hAnJgaO8UL4AkeeyUHwrwEhcjI+w0VJY/5U7NaA5nwc+pyTXrTXH76UxHttauegGIjX2FfeA2XoQg==", - "requires": { - "@types/lodash": "^4.14.153", - "axios": "^0.21.1", - "big-integer": "^1.6.48", - "bignumber.js": "^9.0.0", - "decimal.js": "^10.2.0", - "lodash": "^4.17.15" - }, - "dependencies": { - "axios": { - "version": "0.21.4", - "resolved": "https://registry.npmjs.org/axios/-/axios-0.21.4.tgz", - "integrity": "sha512-ut5vewkiu8jjGBdqpM44XxjuCjq9LAKeHVmoVfHVzy8eHgxxq8SbAVQNovDA8mVi05kP0Ea/n/UzcSHcTJQfNg==", - "requires": { - "follow-redirects": "^1.14.0" - } - } - } + "version": "0.3.3", + "resolved": "https://registry.npmjs.org/logflare-transport-core/-/logflare-transport-core-0.3.3.tgz", + "integrity": "sha512-n82NsRVWvlaa3jd9QQ8rDroCjCJcIamQOlarLDBou9RsF0QaRv39rduy0ToPmlGQn1OPZBwlsv+R36lXupSmVQ==" }, "lru-cache": { "version": "7.17.0", @@ -15982,31 +15891,20 @@ } }, "pino-logflare": { - "version": "0.3.12", - "resolved": "https://registry.npmjs.org/pino-logflare/-/pino-logflare-0.3.12.tgz", - "integrity": "sha512-+b61yGXEwrT3vDWg3YiX7qwBGEoNswwoNbaaHjiD08nXG1PPug2+Z3HM7E2eEWJ9ZTHksFy7svhul9gy/BTJ0Q==", + "version": "0.4.2", + "resolved": "https://registry.npmjs.org/pino-logflare/-/pino-logflare-0.4.2.tgz", + "integrity": "sha512-WiqSIpBGH2Cn1KOinB95ovxxsmHkx33/aF0zZy0iip7dIA/x2VRiPCo9/1+II4cls/rjcMmkoNOZHZx8zNWLGQ==", "requires": { - "axios": "^0.21.1", "batch2": "^1.0.6", "commander": "^5.0.0", "fast-json-parse": "^1.0.3", - "lodash": "^4.17.15", - "logflare-transport-core": "^0.2.5", + "logflare-transport-core": "^0.3.3", "pino": "^6.3.2", "pumpify": "^2.0.1", "split2": "^3.1.1", - "stream-browserify": "^3.0.0", "through2": "^3.0.1" }, "dependencies": { - "axios": { - "version": "0.21.4", - "resolved": "https://registry.npmjs.org/axios/-/axios-0.21.4.tgz", - "integrity": "sha512-ut5vewkiu8jjGBdqpM44XxjuCjq9LAKeHVmoVfHVzy8eHgxxq8SbAVQNovDA8mVi05kP0Ea/n/UzcSHcTJQfNg==", - "requires": { - "follow-redirects": "^1.14.0" - } - }, "commander": { "version": "5.1.0", "resolved": "https://registry.npmjs.org/commander/-/commander-5.1.0.tgz", diff --git a/package.json b/package.json index 999bf137..4633e98f 100644 --- a/package.json +++ b/package.json @@ -4,7 +4,7 @@ "description": "Supabase storage middleend", "main": "index.js", "scripts": { - "dev": "ts-node-dev --log-error --files ./src/server.ts --stack_trace_limit=100 -r trace -r clarify", + "dev": "ts-node-dev --log-error --files ./src/server.ts --stack_trace_limit=100 -r trace -r clarify | pino-pretty", "build": "tsc -p tsconfig.json", "start": "NODE_ENV=production node dist/server.js", "migration:run": "ts-node-dev ./src/scripts/migrate-call.ts", @@ -58,7 +58,7 @@ "pg-boss": "^8.1.1", "pg-listen": "^1.7.0", "pino": "^8.2.0", - "pino-logflare": "^0.3.12", + "pino-logflare": "^0.4.2", "postgres-migrations": "^5.3.0", "prom-client": "^14.0.1" }, diff --git a/src/http/error-handler.ts b/src/http/error-handler.ts index 21f85c52..dc217022 100644 --- a/src/http/error-handler.ts +++ b/src/http/error-handler.ts @@ -14,10 +14,6 @@ export const setErrorHandler = (app: FastifyInstance) => { // it will be logged in the request log plugin reply.executionError = error - if (process.env.NODE_ENV !== 'production') { - console.error(error) - } - if (isRenderableError(error)) { const renderableError = error.render() const statusCode = error.userStatusCode diff --git a/src/http/plugins/db.ts b/src/http/plugins/db.ts index 1662f3fd..08e69036 100644 --- a/src/http/plugins/db.ts +++ b/src/http/plugins/db.ts @@ -3,6 +3,7 @@ import { TenantConnection } from '../../database/connection' import { getServiceKeyUser } from '../../database/tenant' import { getPostgresConnection } from '../../database' import { verifyJWT } from '../../auth' +import { logSchema } from '../../monitoring' declare module 'fastify' { interface FastifyRequest { @@ -33,7 +34,10 @@ export const db = fastifyPlugin(async (fastify) => { fastify.addHook('onSend', async (request, reply, payload) => { if (request.db) { request.db.dispose().catch((e) => { - request.log.error(e, 'Error disposing db connection') + logSchema.error(request.log, 'Error disposing db connection', { + type: 'db-connection', + error: e, + }) }) } return payload @@ -41,13 +45,27 @@ export const db = fastifyPlugin(async (fastify) => { fastify.addHook('onTimeout', async (request) => { if (request.db) { - await request.db.dispose() + try { + await request.db.dispose() + } catch (e) { + logSchema.error(request.log, 'Error disposing db connection', { + type: 'db-connection', + error: e, + }) + } } }) fastify.addHook('onRequestAbort', async (request) => { if (request.db) { - await request.db.dispose() + try { + await request.db.dispose() + } catch (e) { + logSchema.error(request.log, 'Error disposing db connection', { + type: 'db-connection', + error: e, + }) + } } }) }) @@ -72,7 +90,10 @@ export const dbSuperUser = fastifyPlugin(async (fastify) => { fastify.addHook('onSend', async (request, reply, payload) => { if (request.db) { request.db.dispose().catch((e) => { - request.log.error(e, 'Error disposing db connection') + logSchema.error(request.log, 'Error disposing db connection', { + type: 'db-connection', + error: e, + }) }) } @@ -81,13 +102,27 @@ export const dbSuperUser = fastifyPlugin(async (fastify) => { fastify.addHook('onTimeout', async (request) => { if (request.db) { - await request.db.dispose() + try { + await request.db.dispose() + } catch (e) { + logSchema.error(request.log, 'Error disposing db connection', { + type: 'db-connection', + error: e, + }) + } } }) fastify.addHook('onRequestAbort', async (request) => { if (request.db) { - await request.db.dispose() + try { + await request.db.dispose() + } catch (e) { + logSchema.error(request.log, 'Error disposing db connection', { + type: 'db-connection', + error: e, + }) + } } }) }) diff --git a/src/http/plugins/log-request.ts b/src/http/plugins/log-request.ts index eb2a258e..aff34795 100644 --- a/src/http/plugins/log-request.ts +++ b/src/http/plugins/log-request.ts @@ -1,6 +1,5 @@ import fastifyPlugin from 'fastify-plugin' -import { redactQueryParamFromRequest } from '../../monitoring' -import { normalizeRawError } from '../../storage' +import { logSchema, redactQueryParamFromRequest } from '../../monitoring' interface RequestLoggerOptions { excludeUrls?: string[] @@ -30,15 +29,13 @@ export const logRequest = (options: RequestLoggerOptions) => const buildLogMessage = `${tenantId} | ${rMeth} | ${statusCode} | ${cIP} | ${rId} | ${rUrl} | ${uAgent}` - req.log.info( - { - req, - res: reply, - responseTime: reply.getResponseTime(), - error, - rawError: normalizeRawError(error), - }, - buildLogMessage - ) + logSchema.request(req.log, buildLogMessage, { + type: 'request', + req, + res: reply, + responseTime: reply.getResponseTime(), + error: error, + owner: req.owner, + }) }) }) diff --git a/src/http/plugins/log-tenant-id.ts b/src/http/plugins/log-tenant-id.ts index 001e08b1..a5343f90 100644 --- a/src/http/plugins/log-tenant-id.ts +++ b/src/http/plugins/log-tenant-id.ts @@ -5,6 +5,7 @@ export const logTenantId = fastifyPlugin(async (fastify) => { reply.log = request.log = request.log.child({ tenantId: request.tenantId, project: request.tenantId, + reqId: request.id, }) }) }) diff --git a/src/http/plugins/storage.ts b/src/http/plugins/storage.ts index f894c352..6c27665a 100644 --- a/src/http/plugins/storage.ts +++ b/src/http/plugins/storage.ts @@ -18,6 +18,7 @@ export const storage = fastifyPlugin(async (fastify) => { const database = new StorageKnexDB(request.db, { tenantId: request.tenantId, host: request.headers['x-forwarded-host'] as string, + reqId: request.id, }) request.backend = storageBackend request.storage = new Storage(storageBackend, database) diff --git a/src/http/routes/bucket/createBucket.ts b/src/http/routes/bucket/createBucket.ts index 530d74b6..87d638e4 100644 --- a/src/http/routes/bucket/createBucket.ts +++ b/src/http/routes/bucket/createBucket.ts @@ -60,7 +60,7 @@ export default async function routes(fastify: FastifyInstance) { file_size_limit, } = request.body - const bucket = await request.storage.createBucket({ + await request.storage.createBucket({ id: id ?? bucketName, name: bucketName, owner, @@ -71,8 +71,6 @@ export default async function routes(fastify: FastifyInstance) { : allowed_mime_types, }) - request.log.info({ results: bucket }, 'results') - return response.status(200).send({ name: bucketName, }) diff --git a/src/http/routes/bucket/getAllBuckets.ts b/src/http/routes/bucket/getAllBuckets.ts index 2acde895..9cb2de01 100644 --- a/src/http/routes/bucket/getAllBuckets.ts +++ b/src/http/routes/bucket/getAllBuckets.ts @@ -39,8 +39,6 @@ export default async function routes(fastify: FastifyInstance) { 'id, name, public, owner, created_at, updated_at, file_size_limit, allowed_mime_types' ) - request.log.info({ results }, 'results') - response.send(results) } ) diff --git a/src/http/routes/bucket/getBucket.ts b/src/http/routes/bucket/getBucket.ts index 9895420a..2a58abbe 100644 --- a/src/http/routes/bucket/getBucket.ts +++ b/src/http/routes/bucket/getBucket.ts @@ -37,8 +37,6 @@ export default async function routes(fastify: FastifyInstance) { 'id, name, owner, public, created_at, updated_at, file_size_limit, allowed_mime_types' ) - request.log.info({ results }, 'results') - response.send(results) } ) diff --git a/src/http/routes/object/createObject.ts b/src/http/routes/object/createObject.ts index 529dd571..19d4a5a8 100644 --- a/src/http/routes/object/createObject.ts +++ b/src/http/routes/object/createObject.ts @@ -55,9 +55,6 @@ export default async function routes(fastify: FastifyInstance) { schema, }, async (request, response) => { - const contentType = request.headers['content-type'] - request.log.info(`content-type is ${contentType}`) - const { bucketName } = request.params const objectName = request.params['*'] diff --git a/src/http/routes/object/getPublicObject.ts b/src/http/routes/object/getPublicObject.ts index c21e4478..ce76938f 100644 --- a/src/http/routes/object/getPublicObject.ts +++ b/src/http/routes/object/getPublicObject.ts @@ -56,7 +56,6 @@ export default async function routes(fastify: FastifyInstance) { // send the object from s3 const s3Key = `${request.tenantId}/${bucketName}/${objectName}` - request.log.info(s3Key) return request.storage.renderer('asset').render(request, response, { bucket: globalS3Bucket, diff --git a/src/http/routes/object/listObjects.ts b/src/http/routes/object/listObjects.ts index 237b0089..a1c0a5f7 100644 --- a/src/http/routes/object/listObjects.ts +++ b/src/http/routes/object/listObjects.ts @@ -69,8 +69,6 @@ export default async function routes(fastify: FastifyInstance) { }, }) - request.log.info({ results }, 'results') - response.status(200).send(results) } ) diff --git a/src/http/routes/object/uploadSignedObject.ts b/src/http/routes/object/uploadSignedObject.ts index 394745d3..31e80292 100644 --- a/src/http/routes/object/uploadSignedObject.ts +++ b/src/http/routes/object/uploadSignedObject.ts @@ -80,9 +80,6 @@ export default async function routes(fastify: FastifyInstance) { throw new StorageBackendError('Invalid JWT', 400, err.message, err) } - const contentType = request.headers['content-type'] - request.log.info(`content-type is ${contentType}`) - const { url, exp, owner } = payload const { bucketName } = request.params const objectName = request.params['*'] diff --git a/src/http/routes/render/renderSignedImage.ts b/src/http/routes/render/renderSignedImage.ts index f29c8627..39120255 100644 --- a/src/http/routes/render/renderSignedImage.ts +++ b/src/http/routes/render/renderSignedImage.ts @@ -71,7 +71,6 @@ export default async function routes(fastify: FastifyInstance) { } const s3Key = `${request.tenantId}/${url}` - request.log.info(s3Key) const [bucketName, ...objParts] = url.split('/') const obj = await request.storage diff --git a/src/http/routes/tus/handlers.ts b/src/http/routes/tus/handlers.ts index d4b96901..02afdb82 100644 --- a/src/http/routes/tus/handlers.ts +++ b/src/http/routes/tus/handlers.ts @@ -10,7 +10,6 @@ import { OptionsHandler } from '@tus/server/handlers/OptionsHandler' import { UploadId } from './upload-id' import { getFileSizeLimit } from '../../../storage/limits' import { Uploader } from '../../../storage/uploader' -import { logger } from '../../../monitoring' const reExtractFileID = /([^/]+)\/?$/ @@ -56,7 +55,7 @@ export class Patch extends PatchHandler { throw e } finally { await req.upload.db.dispose().catch(() => { - logger.error('failed disposing connection') + req.log.error('failed disposing connection') }) } } @@ -108,7 +107,7 @@ export class Head extends HeadHandler { throw e } finally { await req.upload.db.dispose().catch(() => { - logger.error('failed disposing connection') + req.log.error('failed disposing connection') }) } } @@ -156,7 +155,7 @@ export class Post extends PostHandler { throw e } finally { await req.upload.db.dispose().catch(() => { - logger.error('failed disposing connection') + req.log.error('failed disposing connection') }) } } @@ -246,7 +245,7 @@ export class Options extends OptionsHandler { throw e } finally { await req.upload.db.dispose().catch(() => { - logger.error('failed disposing connection') + req.log.error('failed disposing connection') }) } } diff --git a/src/http/routes/tus/index.ts b/src/http/routes/tus/index.ts index 40fce9ae..11f26527 100644 --- a/src/http/routes/tus/index.ts +++ b/src/http/routes/tus/index.ts @@ -1,4 +1,4 @@ -import { FastifyInstance } from 'fastify' +import { FastifyBaseLogger, FastifyInstance } from 'fastify' import { Server } from '@tus/server' import { jwt, storage, db, dbSuperUser } from '../../plugins' import { getConfig } from '../../../config' @@ -27,6 +27,7 @@ const { } = getConfig() type MultiPartRequest = http.IncomingMessage & { + log: FastifyBaseLogger upload: { storage: Storage owner?: string @@ -108,6 +109,7 @@ export default async function routes(fastify: FastifyInstance) { fastify.register(storage) fastify.addHook('preHandler', async (req) => { + ;(req.raw as MultiPartRequest).log = req.log ;(req.raw as MultiPartRequest).upload = { storage: req.storage, owner: req.owner, @@ -164,6 +166,7 @@ export default async function routes(fastify: FastifyInstance) { fastify.register(storage) fastify.addHook('preHandler', async (req) => { + ;(req.raw as MultiPartRequest).log = req.log ;(req.raw as MultiPartRequest).upload = { storage: req.storage, owner: req.owner, diff --git a/src/http/routes/tus/lifecycle.ts b/src/http/routes/tus/lifecycle.ts index bd1f180d..0f58af11 100644 --- a/src/http/routes/tus/lifecycle.ts +++ b/src/http/routes/tus/lifecycle.ts @@ -6,10 +6,12 @@ import { randomUUID } from 'crypto' import { UploadId } from './upload-id' import { Uploader } from '../../../storage/uploader' import { TenantConnection } from '../../../database/connection' +import { BaseLogger } from 'pino' const { globalS3Bucket } = getConfig() export type MultiPartRequest = http.IncomingMessage & { + log: BaseLogger upload: { storage: Storage db: TenantConnection diff --git a/src/monitoring/logflare.ts b/src/monitoring/logflare.ts index 2a728ef6..fa41914e 100644 --- a/src/monitoring/logflare.ts +++ b/src/monitoring/logflare.ts @@ -1,5 +1,7 @@ /* eslint-disable @typescript-eslint/no-var-requires */ +import { defaultPreparePayload } from 'pino-logflare' + const dotenv = require('dotenv') const { createWriteStream: createLogFlareWriteStream } = require('pino-logflare') @@ -20,5 +22,10 @@ export default function () { return createLogFlareWriteStream({ apiKey: logflareApiKey, sourceToken: logflareSourceToken, + onPreparePayload: (payload: any, meta: any) => { + const item = defaultPreparePayload(payload, meta) + item.project = payload.project + return item + }, }) } diff --git a/src/monitoring/logger.ts b/src/monitoring/logger.ts index fc269105..cf67ab7e 100644 --- a/src/monitoring/logger.ts +++ b/src/monitoring/logger.ts @@ -1,7 +1,8 @@ -import pino from 'pino' +import pino, { BaseLogger } from 'pino' import { getConfig } from '../config' -import { FastifyRequest } from 'fastify' +import { FastifyReply, FastifyRequest } from 'fastify' import { URL } from 'url' +import { normalizeRawError } from '../storage' const { logLevel } = getConfig() @@ -13,6 +14,9 @@ export const logger = pino({ }, }, serializers: { + error(error) { + return normalizeRawError(error) + }, res(reply) { return { statusCode: reply.statusCode, @@ -21,6 +25,7 @@ export const logger = pino({ }, req(request) { return { + traceId: request.id, method: request.method, url: redactQueryParamFromRequest(request, ['token']), headers: whitelistHeaders(request.headers), @@ -34,6 +39,39 @@ export const logger = pino({ timestamp: pino.stdTimeFunctions.isoTime, }) +export interface RequestLog { + type: 'request' + req: FastifyRequest + res: FastifyReply + responseTime: number + error?: Error | unknown + owner?: string +} + +export interface EventLog { + jodId: string + type: 'event' + event: string + payload: string + objectPath: string + tenantId: string + project: string + reqId?: string +} + +interface ErrorLog { + type: string + error?: Error | unknown +} + +export const logSchema = { + request: (logger: BaseLogger, message: string, log: RequestLog) => { + logger.info(log, message) + }, + error: (logger: BaseLogger, message: string, log: ErrorLog) => logger.error(log, message), + event: (logger: BaseLogger, message: string, log: EventLog) => logger.info(log, message), +} + export function buildTransport(): pino.TransportSingleOptions | undefined { const { logflareApiKey, logflareSourceToken, logflareEnabled } = getConfig() @@ -72,6 +110,12 @@ const whitelistHeaders = (headers: Record) => { 'x-forwarded-user-agent', 'x-client-trace-id', 'x-upsert', + 'content-type', + 'if-none-match', + 'if-modified-since', + 'upload-metadata', + 'upload-length', + 'tus-resumable', ] const allowlistedResponseHeaders = [ 'cf-cache-status', diff --git a/src/queue/events/base-event.ts b/src/queue/events/base-event.ts index 36edb568..fcce589d 100644 --- a/src/queue/events/base-event.ts +++ b/src/queue/events/base-event.ts @@ -11,6 +11,7 @@ import { logger } from '../../monitoring' export interface BasePayload { $version: string + reqId?: string tenant: { ref: string host: string diff --git a/src/queue/events/multipart-upload-completed.ts b/src/queue/events/multipart-upload-completed.ts index 31e0cf55..61d4e6d1 100644 --- a/src/queue/events/multipart-upload-completed.ts +++ b/src/queue/events/multipart-upload-completed.ts @@ -3,6 +3,7 @@ import { Job } from 'pg-boss' import { getConfig } from '../../config' import { S3Backend } from '../../storage/backend' import { isS3Error } from '../../storage' +import { logger } from '../../monitoring' interface UploadCompleted extends BasePayload { bucketName: string @@ -29,6 +30,7 @@ export class MultiPartUploadCompleted extends BaseEvent { if (isS3Error(e) && e.$metadata.httpStatusCode === 404) { return } + logger.error({ error: e }, 'multi part uploaded completed failed') throw e } } diff --git a/src/queue/events/object-admin-delete.ts b/src/queue/events/object-admin-delete.ts index ad00d02f..084b6a51 100644 --- a/src/queue/events/object-admin-delete.ts +++ b/src/queue/events/object-admin-delete.ts @@ -2,7 +2,7 @@ import { BaseEvent, BasePayload } from './base-event' import { getConfig } from '../../config' import { Job } from 'pg-boss' import { withOptionalVersion } from '../../storage/backend' -import { logger } from '../../monitoring' +import { logger, logSchema } from '../../monitoring' export interface ObjectDeleteEvent extends BasePayload { name: string @@ -16,23 +16,31 @@ export class ObjectAdminDelete extends BaseEvent { static queueName = 'object:admin:delete' static async handle(job: Job) { - logger.info({ job: JSON.stringify(job) }, 'Handling ObjectAdminDelete') - try { const storage = await this.createStorage(job.data) const version = job.data.version const s3Key = `${job.data.tenant.ref}/${job.data.bucketId}/${job.data.name}` + logSchema.event(logger, `[Admin]: ObjectAdminDelete ${s3Key}`, { + jodId: job.id, + type: 'event', + event: 'ObjectAdminDelete', + payload: JSON.stringify(job.data), + objectPath: s3Key, + tenantId: job.data.tenant.ref, + project: job.data.tenant.ref, + reqId: job.data.reqId, + }) + await storage.backend.deleteObjects(globalS3Bucket, [ withOptionalVersion(s3Key, version), withOptionalVersion(s3Key, version) + '.info', ]) } catch (e) { - console.error(e) logger.error( { - error: JSON.stringify(e), + error: e, }, 'Error Deleting files from queue' ) diff --git a/src/queue/events/webhook.ts b/src/queue/events/webhook.ts index 7ddd8e6c..f9b3c77f 100644 --- a/src/queue/events/webhook.ts +++ b/src/queue/events/webhook.ts @@ -2,7 +2,7 @@ import { BaseEvent } from './base-event' import { Job, WorkOptions } from 'pg-boss' import axios from 'axios' import { getConfig } from '../../config' -import { logger } from '../../monitoring' +import { logger, logSchema } from '../../monitoring' const { webhookURL, webhookApiKey, webhookQueuePullInterval } = getConfig() @@ -14,6 +14,7 @@ interface WebhookEvent { applyTime: number } sentAt: string + traceId?: string tenant: { ref: string host: string @@ -35,7 +36,19 @@ export class Webhook extends BaseEvent { return job } - logger.info({ job }, 'handling webhook') + const payload = job.data.event.payload as { bucketId?: string; name?: string } + const path = `${job.data.tenant.ref}/${payload.bucketId}/${payload.name}` + + logSchema.event(logger, `[Lifecycle]: ${job.data.event.type} ${path}`, { + jodId: job.id, + type: 'event', + event: job.data.event.type, + payload: JSON.stringify(job.data.event.payload), + objectPath: path, + tenantId: job.data.tenant.ref, + project: job.data.tenant.ref, + reqId: job.data.traceId, + }) try { await axios.post( diff --git a/src/server.ts b/src/server.ts index 61ce8bce..c6f9bef5 100644 --- a/src/server.ts +++ b/src/server.ts @@ -6,9 +6,8 @@ import buildAdmin from './admin-app' import { getConfig } from './config' import { runMultitenantMigrations, runMigrations } from './database/migrate' import { listenForTenantUpdate } from './database/tenant' -import { logger } from './monitoring' +import { logger, logSchema } from './monitoring' import { Queue } from './queue' -import { normalizeRawError } from './storage' import { TenantConnection } from './database/connection' const exposeDocs = true @@ -44,10 +43,14 @@ const exposeDocs = true app.listen({ port, host }, (err, address) => { if (err) { - console.error(err) + logSchema.error(logger, `Server failed to start`, { + type: 'serverStartError', + error: err, + }) process.exit(1) } - console.log(`Server listening at ${address}`) + + logger.info(`Server listening at ${address}`) }) if (isMultitenant) { @@ -63,18 +66,19 @@ const exposeDocs = true try { await adminApp.listen({ port: adminPort, host }) } catch (err) { - adminApp.log.error(err) + logSchema.error(adminApp.log, 'Failed to start admin app', { + type: 'adminAppStartError', + error: err, + }) process.exit(1) } } process.on('uncaughtException', (e) => { - logger.error( - { - error: normalizeRawError(e), - }, - 'uncaught exception' - ) + logSchema.error(logger, 'uncaught exception', { + type: 'uncaughtException', + error: e, + }) process.exit(1) }) @@ -84,7 +88,10 @@ const exposeDocs = true await Promise.allSettled([Queue.stop(), TenantConnection.stop()]) process.exit(0) } catch (e) { - logger.error('shutdown error', { error: e }) + logSchema.error(logger, 'shutdown error', { + type: 'SIGTERM', + error: e, + }) process.exit(1) } }) diff --git a/src/storage/database/adapter.ts b/src/storage/database/adapter.ts index 92920751..ade9fac8 100644 --- a/src/storage/database/adapter.ts +++ b/src/storage/database/adapter.ts @@ -35,6 +35,7 @@ export interface TransactionOptions { export interface DatabaseOptions { tenantId: string + reqId?: string host: string tnx?: TNX parentTnx?: TNX @@ -44,6 +45,7 @@ export interface DatabaseOptions { export interface Database { tenantHost: string tenantId: string + reqId?: string role?: string tenant(): { ref: string; host: string } diff --git a/src/storage/database/knex.ts b/src/storage/database/knex.ts index 5666d0bc..9a4c2d8f 100644 --- a/src/storage/database/knex.ts +++ b/src/storage/database/knex.ts @@ -22,6 +22,7 @@ import { isUuid } from '../limits' export class StorageKnexDB implements Database { public readonly tenantHost: string public readonly tenantId: string + public readonly reqId: string | undefined public readonly role?: string constructor( @@ -30,6 +31,7 @@ export class StorageKnexDB implements Database { ) { this.tenantHost = options.host this.tenantId = options.tenantId + this.reqId = options.reqId this.role = connection?.role } diff --git a/src/storage/errors.ts b/src/storage/errors.ts index 44cc3555..be7f4c48 100644 --- a/src/storage/errors.ts +++ b/src/storage/errors.ts @@ -1,5 +1,4 @@ import { S3ServiceException } from '@aws-sdk/client-s3' -import { logger } from '../monitoring' export type StorageError = { statusCode: string @@ -99,21 +98,21 @@ export class StorageBackendError extends Error implements RenderableError { export function normalizeRawError(error: any) { if (error instanceof Error) { - return JSON.stringify({ - _error: error, + return { + raw: JSON.stringify(error), name: error.name, message: error.message, stack: error.stack, - }) - } - - if (error instanceof Object) { - return error.toString() + } } try { - return JSON.stringify(error) + return { + raw: JSON.stringify(error), + } } catch (e) { - logger.error(e, 'Failed to stringify error') + return { + raw: 'Failed to stringify error', + } } } diff --git a/src/storage/object.ts b/src/storage/object.ts index c28da431..f1a4d318 100644 --- a/src/storage/object.ts +++ b/src/storage/object.ts @@ -122,6 +122,7 @@ export class ObjectStorage { name: objectName, bucketId: this.bucketId, version: obj.version, + reqId: this.db.reqId, }) }) @@ -129,6 +130,7 @@ export class ObjectStorage { tenant: this.db.tenant(), name: objectName, bucketId: this.bucketId, + reqId: this.db.reqId, }) } @@ -177,6 +179,7 @@ export class ObjectStorage { tenant: db.tenant(), name: object.name, bucketId: this.bucketId, + reqId: this.db.reqId, }) ) ) @@ -202,6 +205,7 @@ export class ObjectStorage { name: objectName, bucketId: this.bucketId, metadata, + reqId: this.db.reqId, }) return result @@ -296,6 +300,7 @@ export class ObjectStorage { name: destinationKey, bucketId: this.bucketId, metadata, + reqId: this.db.reqId, }) return { @@ -308,6 +313,7 @@ export class ObjectStorage { bucketId: this.bucketId, tenant: this.db.tenant(), version: newVersion, + reqId: this.db.reqId, }) throw e } @@ -374,18 +380,20 @@ export class ObjectStorage { }) await db.deleteObject(this.bucketId, sourceObjectName, sourceObj.version) + await ObjectAdminDelete.send({ + name: sourceObjectName, + bucketId: this.bucketId, + tenant: this.db.tenant(), + version: sourceObj.version, + reqId: this.db.reqId, + }) - await Promise.all([ - ObjectAdminDelete.send({ - name: sourceObjectName, - bucketId: this.bucketId, - tenant: this.db.tenant(), - version: sourceObj.version, - }), + await Promise.allSettled([ ObjectRemovedMove.sendWebhook({ tenant: this.db.tenant(), name: sourceObjectName, bucketId: this.bucketId, + reqId: this.db.reqId, }), ObjectCreatedMove.sendWebhook({ tenant: this.db.tenant(), @@ -395,7 +403,9 @@ export class ObjectStorage { oldObject: { name: sourceObjectName, bucketId: this.bucketId, + reqId: this.db.reqId, }, + reqId: this.db.reqId, }), ]) }) @@ -405,6 +415,7 @@ export class ObjectStorage { bucketId: this.bucketId, tenant: this.db.tenant(), version: newVersion, + reqId: this.db.reqId, }) throw e } diff --git a/src/storage/uploader.ts b/src/storage/uploader.ts index 620ec383..fdc421c1 100644 --- a/src/storage/uploader.ts +++ b/src/storage/uploader.ts @@ -124,6 +124,7 @@ export class Uploader { bucketId: options.bucketId, tenant: this.db.tenant(), version: version, + reqId: this.db.reqId, }) throw e } @@ -175,6 +176,7 @@ export class Uploader { bucketId: bucketId, tenant: this.db.tenant(), version: currentObj.version, + reqId: this.db.reqId, }) ) } @@ -187,6 +189,7 @@ export class Uploader { name: objectName, bucketId: bucketId, metadata: objectMetadata, + reqId: this.db.reqId, }) ) @@ -197,6 +200,7 @@ export class Uploader { objectName: objectName, bucketName: bucketId, version: id, + reqId: this.db.reqId, }) ) } @@ -216,6 +220,7 @@ export class Uploader { bucketId: bucketId, tenant: this.db.tenant(), version: id, + reqId: this.db.reqId, }) throw e } diff --git a/src/test/webhooks.test.ts b/src/test/webhooks.test.ts index f90b45d6..80108765 100644 --- a/src/test/webhooks.test.ts +++ b/src/test/webhooks.test.ts @@ -112,11 +112,13 @@ describe('Webhooks', () => { host: undefined, ref: 'bjhaohmqunupljrqypxz', }, + reqId: expect.any(String), version: expect.any(String), }, name: 'object:admin:delete', options: undefined, }) + expect(sendSpy).toHaveBeenNthCalledWith( 2, expect.objectContaining({ @@ -135,6 +137,7 @@ describe('Webhooks', () => { host: undefined, ref: 'bjhaohmqunupljrqypxz', }, + reqId: expect.any(String), }), }), tenant: { @@ -183,6 +186,7 @@ describe('Webhooks', () => { host: undefined, ref: 'bjhaohmqunupljrqypxz', }, + reqId: expect.any(String), }), }), tenant: { @@ -219,11 +223,13 @@ describe('Webhooks', () => { oldObject: { bucketId: 'bucket6', name: obj.name, + reqId: expect.any(String), }, tenant: { host: undefined, ref: 'bjhaohmqunupljrqypxz', }, + reqId: expect.any(String), }), }), tenant: {