chore(logging): improve logging (#185)

* - Improve request logging including tenantId and non-sensitive headers
- Extract Postgrest URL scheme as a config (default http)

* chore(logging): improve logging

* chore(logging): format message request log, add logLevel env

src/admin-app.ts

@@ -1,14 +1,16 @@
 import fastify, { FastifyInstance, FastifyServerOptions } from 'fastify'
 import { default as metrics } from 'fastify-metrics'
-import tenantRoutes from './routes/tenant'
 import { Registry } from 'prom-client'
+import tenantRoutes from './routes/tenant'
+import logRequest from './plugins/log-request'
 
 export interface AdminOptions {
   register?: Registry
 }
 
 const build = (opts: FastifyServerOptions = {}, adminOpts: AdminOptions = {}): FastifyInstance => {
   const app = fastify(opts)
+  app.register(logRequest({ excludeUrls: ['/status'] }))
   app.register(tenantRoutes, { prefix: 'tenants' })
   app.register(metrics, {
     endpoint: '/metrics',

src/app.ts

@@ -7,6 +7,7 @@ import { authSchema } from './schemas/auth'
 import { errorSchema } from './schemas/error'
 import logTenantId from './plugins/log-tenant-id'
 import tenantId from './plugins/tenant-id'
+import logRequest from './plugins/log-request'
 
 interface buildOpts extends FastifyServerOptions {
   exposeDocs?: boolean
@@ -53,6 +54,7 @@ const build = (opts: buildOpts = {}): FastifyInstance => {
 
   app.register(tenantId)
   app.register(logTenantId)
+  app.register(logRequest({ excludeUrls: ['/status'] }))
   app.register(bucketRoutes, { prefix: 'bucket' })
   app.register(objectRoutes, { prefix: 'object' })
 

src/monitoring/logger.ts

@@ -1,13 +1,34 @@
 import pino from 'pino'
 import { getConfig } from '../utils/config'
 
+const { logLevel } = getConfig()
+
 export const logger = pino({
   transport: buildTransport(),
   formatters: {
-    level(label) {
-      return { level: label }
+    level(label, number) {
+      return { level: number }
+    },
+  },
+  serializers: {
+    res(reply) {
+      return {
+        url: reply.url,
+        statusCode: reply.statusCode,
+      }
+    },
+    req(request) {
+      return {
+        method: request.method,
+        url: request.url,
+        headers: whitelistHeaders(request.headers),
+        hostname: request.hostname,
+        remoteAddress: request.ip,
+        remotePort: request.socket.remotePort,
+      }
     },
   },
+  level: logLevel,
   timestamp: pino.stdTimeFunctions.isoTime,
 })
 
@@ -30,3 +51,44 @@ export function buildTransport(): pino.TransportSingleOptions | undefined {
     target: './logflare',
   }
 }
+
+const whitelistHeaders = (headers: Record<string, unknown>) => {
+  const responseMetadata: Record<string, unknown> = {}
+  const allowlistedRequestHeaders = [
+    'accept',
+    'cf-connecting-ip',
+    'cf-ipcountry',
+    'host',
+    'user-agent',
+    'x-forwarded-proto',
+    'referer',
+    'content-length',
+    'x-real-ip',
+    'x-client-info',
+    'x-forwarded-user-agent',
+  ]
+  const allowlistedResponseHeaders = [
+    'cf-cache-status',
+    'cf-ray',
+    'content-location',
+    'content-range',
+    'content-type',
+    'content-length',
+    'date',
+    'transfer-encoding',
+    'x-kong-proxy-latency',
+    'x-kong-upstream-latency',
+    'sb-gateway-mode',
+    'sb-gateway-version',
+  ]
+  Object.keys(headers)
+    .filter(
+      (header) =>
+        allowlistedRequestHeaders.includes(header) || allowlistedResponseHeaders.includes(header)
+    )
+    .forEach((header) => {
+      responseMetadata[header.replace(/-/g, '_')] = headers[header]
+    })
+
+  return responseMetadata
+}

src/plugins/log-request.ts

@@ -0,0 +1,25 @@
+import fastifyPlugin from 'fastify-plugin'
+
+interface RequestLoggerOptions {
+  excludeUrls?: string[]
+}
+
+export default (options: RequestLoggerOptions) =>
+  fastifyPlugin(async (fastify) => {
+    fastify.addHook('onResponse', async (req, reply) => {
+      if (options.excludeUrls?.includes(req.url)) {
+        return
+      }
+
+      const rMeth = req.method
+      const rUrl = req.url
+      const uAgent = req.headers['user-agent']
+      const rId = req.id
+      const cIP = req.ip
+      const statusCode = reply.statusCode
+
+      const buildLogMessage = `${rMeth} | ${statusCode} | ${cIP} | ${rId} | ${rUrl} | ${uAgent}`
+
+      req.log.info({ req, res: reply, responseTime: reply.getResponseTime() }, buildLogMessage)
+    })
+  })

src/plugins/log-tenant-id.ts

@@ -2,6 +2,9 @@ import fastifyPlugin from 'fastify-plugin'
 
 export default fastifyPlugin(async (fastify) => {
   fastify.addHook('onRequest', async (request, reply) => {
-    reply.log = request.log = request.log.child({ tenantId: request.tenantId })
+    reply.log = request.log = request.log.child({
+      tenantId: request.tenantId,
+      project: request.tenantId,
+    })
   })
 })

src/plugins/postgrest.ts

@@ -13,8 +13,15 @@ declare module 'fastify' {
 }
 
 async function getPostgrestClient(request: FastifyRequest, jwt: string): Promise<PostgrestClient> {
-  const { anonKey, isMultitenant, postgrestURL, postgrestURLSuffix, xForwardedHostRegExp } =
-    getConfig()
+  const {
+    anonKey,
+    isMultitenant,
+    postgrestURL,
+    postgrestURLScheme,
+    postgrestURLSuffix,
+    xForwardedHostRegExp,
+  } = getConfig()
+
   let url = postgrestURL
   let apiKey = anonKey
   if (isMultitenant && xForwardedHostRegExp) {
@@ -25,7 +32,7 @@ async function getPostgrestClient(request: FastifyRequest, jwt: string): Promise
     if (!new RegExp(xForwardedHostRegExp).test(xForwardedHost)) {
       throw new Error('X-Forwarded-Host header does not match regular expression')
     }
-    url = `http://${xForwardedHost}${postgrestURLSuffix}`
+    url = `${postgrestURLScheme}://${xForwardedHost}${postgrestURLSuffix}`
     apiKey = await getAnonKey(request.tenantId)
   }
   const postgrest = new PostgrestClient(url, {

src/routes/bucket/createBucket.ts

@@ -44,7 +44,7 @@ export default async function routes(fastify: FastifyInstance) {
       try {
         owner = await getOwner(request.jwt, jwtSecret)
       } catch (err: any) {
-        console.log(err)
+        request.log.error({ error: err }, 'unable to get owner')
         return response.status(400).send(createResponse(err.message, '400', err.message))
       }
 
@@ -84,7 +84,7 @@ export default async function routes(fastify: FastifyInstance) {
         .single()
 
       if (error) {
-        request.log.error({ error }, 'error bucket')
+        request.log.error({ error }, 'error creating bucket')
         return response.status(400).send(transformPostgrestError(error, status))
       }
       request.log.info({ results }, 'results')

src/routes/object/updateObject.ts

@@ -92,7 +92,7 @@ export default async function routes(fastify: FastifyInstance) {
       try {
         owner = await getOwner(request.jwt, jwtSecret)
       } catch (err: any) {
-        console.log(err)
+        request.log.error({ error: err }, 'unable to get owner')
         return response.status(400).send(createResponse(err.message, '400', err.message))
       }
 

src/server.ts

@@ -18,6 +18,7 @@ const exposeDocs = true
 
     const adminApp: FastifyInstance<Server, IncomingMessage, ServerResponse> = buildAdmin({
       logger,
+      disableRequestLogging: true,
       requestIdHeader: adminRequestIdHeader,
     })
 
@@ -33,6 +34,7 @@ const exposeDocs = true
 
   const app: FastifyInstance<Server, IncomingMessage, ServerResponse> = build({
     logger,
+    disableRequestLogging: true,
     exposeDocs,
     requestIdHeader,
   })

src/utils/config.ts

@@ -15,13 +15,15 @@ type StorageConfigType = {
   multitenantDatabaseUrl?: string
   postgrestURL: string
   postgrestURLSuffix?: string
+  postgrestURLScheme?: string
   region: string
   requestIdHeader?: string
   serviceKey: string
   storageBackendType: StorageBackendType
   tenantId: string
   urlLengthLimit: number
   xForwardedHostRegExp?: string
+  logLevel?: string
   logflareEnabled?: boolean
   logflareApiKey?: string
   logflareSourceToken?: string
@@ -62,6 +64,7 @@ export function getConfig(): StorageConfigType {
     multitenantDatabaseUrl: getOptionalConfigFromEnv('MULTITENANT_DATABASE_URL'),
     postgrestURL: getOptionalIfMultitenantConfigFromEnv('POSTGREST_URL') || '',
     postgrestURLSuffix: getOptionalConfigFromEnv('POSTGREST_URL_SUFFIX'),
+    postgrestURLScheme: getOptionalConfigFromEnv('POSTGREST_URL_SCHEME') || 'http',
     region: getConfigFromEnv('REGION'),
     requestIdHeader: getOptionalConfigFromEnv('REQUEST_ID_HEADER'),
     serviceKey: getOptionalIfMultitenantConfigFromEnv('SERVICE_KEY') || '',
@@ -72,6 +75,7 @@ export function getConfig(): StorageConfigType {
       '',
     urlLengthLimit: Number(getOptionalConfigFromEnv('URL_LENGTH_LIMIT')) || 7_500,
     xForwardedHostRegExp: getOptionalConfigFromEnv('X_FORWARDED_HOST_REGEXP'),
+    logLevel: getOptionalConfigFromEnv('LOG_LEVEL') || 'trace',
     logflareEnabled: getOptionalConfigFromEnv('LOGFLARE_ENABLED') === 'true',
     logflareApiKey: getOptionalConfigFromEnv('LOGFLARE_API_KEY'),
     logflareSourceToken: getOptionalConfigFromEnv('LOGFLARE_SOURCE_TOKEN'),