feat: server times (#532)

src/app.ts

@@ -52,8 +52,9 @@ const build = (opts: buildOpts = {}): FastifyInstance => {
   app.addSchema(schemas.errorSchema)
 
   app.register(plugins.tenantId)
-  app.register(plugins.metrics({ enabledEndpoint: !isMultitenant }))
   app.register(plugins.logTenantId)
+  app.register(plugins.metrics({ enabledEndpoint: !isMultitenant }))
+  app.register(plugins.tracing)
   app.register(plugins.logRequest({ excludeUrls: ['/status', '/metrics', '/health'] }))
   app.register(routes.tus, { prefix: 'upload/resumable' })
   app.register(routes.bucket, { prefix: 'bucket' })

src/config.ts

@@ -112,7 +112,10 @@ type StorageConfigType = {
   s3ProtocolAccessKeyId?: string
   s3ProtocolAccessKeySecret?: string
   s3ProtocolNonCanonicalHostHeader?: string
+  tracingEnabled?: boolean
   tracingMode?: string
+  tracingTimeMinDuration: number
+  tracingReturnServerTimings: boolean
 }
 
 function getOptionalConfigFromEnv(key: string, fallback?: string): string | undefined {
@@ -160,16 +163,18 @@ export function getConfig(options?: { reload?: boolean }): StorageConfigType {
   }
 
   envPaths.map((envPath) => dotenv.config({ path: envPath, override: false }))
+  const isMultitenant = getOptionalConfigFromEnv('MULTI_TENANT', 'IS_MULTITENANT') === 'true'
 
   config = {
     isProduction: process.env.NODE_ENV === 'production',
     exposeDocs: getOptionalConfigFromEnv('EXPOSE_DOCS') !== 'false',
+    isMultitenant,
     // Tenant
-    tenantId:
-      getOptionalConfigFromEnv('PROJECT_REF') ||
-      getOptionalConfigFromEnv('TENANT_ID') ||
-      'storage-single-tenant',
-    isMultitenant: getOptionalConfigFromEnv('MULTI_TENANT', 'IS_MULTITENANT') === 'true',
+    tenantId: isMultitenant
+      ? ''
+      : getOptionalConfigFromEnv('PROJECT_REF') ||
+        getOptionalConfigFromEnv('TENANT_ID') ||
+        'storage-single-tenant',
 
     // Server
     region: getOptionalConfigFromEnv('SERVER_REGION', 'REGION') || 'not-specified',
@@ -312,7 +317,13 @@ export function getConfig(options?: { reload?: boolean }): StorageConfigType {
     defaultMetricsEnabled: !(
       getOptionalConfigFromEnv('DEFAULT_METRICS_ENABLED', 'ENABLE_DEFAULT_METRICS') === 'false'
     ),
+    tracingEnabled: getOptionalConfigFromEnv('TRACING_ENABLED') === 'true',
     tracingMode: getOptionalConfigFromEnv('TRACING_MODE') ?? 'basic',
+    tracingTimeMinDuration: parseFloat(
+      getOptionalConfigFromEnv('TRACING_SERVER_TIME_MIN_DURATION') ?? '100.0'
+    ),
+    tracingReturnServerTimings:
+      getOptionalConfigFromEnv('TRACING_RETURN_SERVER_TIMINGS') === 'true',
 
     // Queue
     pgQueueEnable: getOptionalConfigFromEnv('PG_QUEUE_ENABLE', 'ENABLE_QUEUE_EVENTS') === 'true',

src/http/plugins/index.ts

@@ -9,4 +9,4 @@ export * from './tenant-feature'
 export * from './metrics'
 export * from './xml'
 export * from './signature-v4'
-export * from './tracing-mode'
+export * from './tracing'

src/http/plugins/log-request.ts

@@ -79,6 +79,7 @@ export const logRequest = (options: RequestLoggerOptions) =>
         owner: req.owner,
         operation: req.operation?.type ?? req.routeConfig.operation?.type,
         resources: req.resources,
+        serverTimes: req.serverTimings,
       })
     })
 
@@ -112,6 +113,7 @@ export const logRequest = (options: RequestLoggerOptions) =>
         owner: req.owner,
         resources: req.resources,
         operation: req.operation?.type ?? req.routeConfig.operation?.type,
+        serverTimes: req.serverTimings,
       })
     })
   })

src/http/plugins/tracing.ts

@@ -0,0 +1,139 @@
+import fastifyPlugin from 'fastify-plugin'
+import { isIP } from 'net'
+import { getTenantConfig } from '@internal/database'
+
+import { getConfig } from '../../config'
+import { context, trace } from '@opentelemetry/api'
+import { traceCollector } from '@internal/monitoring/otel-processor'
+import { ReadableSpan } from '@opentelemetry/sdk-trace-base'
+import { logger, logSchema } from '@internal/monitoring'
+
+declare module 'fastify' {
+  interface FastifyRequest {
+    tracingMode?: string
+    serverTimings?: { spanName: string; duration: number }[]
+  }
+}
+
+const {
+  isMultitenant,
+  tracingEnabled,
+  tracingMode: defaultTracingMode,
+  tracingReturnServerTimings,
+} = getConfig()
+
+export const tracing = fastifyPlugin(async function tracingMode(fastify) {
+  if (!tracingEnabled) {
+    return
+  }
+  fastify.register(traceServerTime)
+
+  fastify.addHook('onRequest', async (request) => {
+    if (isMultitenant && request.tenantId) {
+      const tenantConfig = await getTenantConfig(request.tenantId)
+      request.tracingMode = tenantConfig.tracingMode
+    } else {
+      request.tracingMode = defaultTracingMode
+    }
+  })
+})
+
+export const traceServerTime = fastifyPlugin(async function traceServerTime(fastify) {
+  if (!tracingEnabled) {
+    return
+  }
+  fastify.addHook('onResponse', async (request, reply) => {
+    const traceId = trace.getSpan(context.active())?.spanContext().traceId
+
+    if (traceId) {
+      const spans = traceCollector.getSpansForTrace(traceId)
+      if (spans) {
+        try {
+          const serverTimingHeaders = spansToServerTimings(spans)
+
+          request.serverTimings = serverTimingHeaders
+
+          // Return Server-Timing if enabled
+          if (tracingReturnServerTimings) {
+            const httpServerTimes = serverTimingHeaders
+              .map(({ spanName, duration }) => {
+                return `${spanName};dur=${duration.toFixed(3)}` // Convert to milliseconds
+              })
+              .join(',')
+            reply.header('Server-Timing', httpServerTimes)
+          }
+        } catch (e) {
+          logSchema.error(logger, 'failed parsing server times', { error: e, type: 'otel' })
+        }
+
+        traceCollector.clearTrace(traceId)
+      }
+    }
+  })
+
+  fastify.addHook('onRequestAbort', async (req) => {
+    const traceId = trace.getSpan(context.active())?.spanContext().traceId
+
+    if (traceId) {
+      const spans = traceCollector.getSpansForTrace(traceId)
+      if (spans) {
+        req.serverTimings = spansToServerTimings(spans)
+      }
+      traceCollector.clearTrace(traceId)
+    }
+  })
+})
+
+function enrichSpanName(spanName: string, span: ReadableSpan) {
+  if (span.attributes['knex.version']) {
+    const queryOperation = (span.attributes['db.operation'] as string)?.split(' ').shift()
+    return (
+      `pg_query_` +
+      queryOperation?.toUpperCase() +
+      (span.attributes['db.sql.table'] ? '_' + span.attributes['db.sql.table'] : '_postgres')
+    )
+  }
+
+  if (['GET', 'PUT', 'HEAD', 'DELETE', 'POST'].includes(spanName)) {
+    return `HTTP_${spanName}`
+  }
+
+  return spanName
+}
+
+function spansToServerTimings(spans: ReadableSpan[]) {
+  return spans
+    .sort((a, b) => {
+      return a.startTime[1] - b.startTime[1]
+    })
+    .map((span) => {
+      const duration = span.duration[1] // Duration in nanoseconds
+
+      let spanName =
+        span.name
+          .split('->')
+          .pop()
+          ?.trimStart()
+          .replaceAll('\n', '')
+          .replaceAll('.', '_')
+          .replaceAll(' ', '_')
+          .replaceAll('-', '_')
+          .replaceAll('___', '_')
+          .replaceAll(':', '_')
+          .replaceAll('_undefined', '') || 'UNKNOWN'
+
+      spanName = enrichSpanName(spanName, span)
+      const hostName = span.attributes['net.peer.name'] as string | undefined
+
+      return {
+        spanName,
+        duration: duration / 1e6,
+        action: span.attributes['db.statement'],
+        host: hostName
+          ? isIP(hostName)
+            ? hostName
+            : hostName?.split('.').slice(-3).join('.')
+          : undefined,
+      }
+    })
+}

src/http/routes/bucket/getAllBuckets.ts

@@ -43,7 +43,7 @@ export default async function routes(fastify: FastifyInstance) {
         'id, name, public, owner, created_at, updated_at, file_size_limit, allowed_mime_types'
       )
 
-      response.send(results)
+      return response.send(results)
     }
   )
 }

src/http/routes/bucket/getBucket.ts

@@ -41,7 +41,7 @@ export default async function routes(fastify: FastifyInstance) {
         'id, name, owner, public, created_at, updated_at, file_size_limit, allowed_mime_types'
       )
 
-      response.send(results)
+      return response.send(results)
     }
   )
 }

src/http/routes/bucket/index.ts

@@ -5,13 +5,12 @@ import emptyBucket from './emptyBucket'
 import getAllBuckets from './getAllBuckets'
 import getBucket from './getBucket'
 import updateBucket from './updateBucket'
-import { storage, jwt, db, tracingMode } from '../../plugins'
+import { storage, jwt, db } from '../../plugins'
 
 export default async function routes(fastify: FastifyInstance) {
   fastify.register(jwt)
   fastify.register(db)
   fastify.register(storage)
-  fastify.register(tracingMode)
 
   fastify.register(createBucket)
   fastify.register(emptyBucket)

src/http/routes/object/index.ts

@@ -1,5 +1,5 @@
 import { FastifyInstance } from 'fastify'
-import { jwt, storage, dbSuperUser, db, tracingMode } from '../../plugins'
+import { jwt, storage, dbSuperUser, db } from '../../plugins'
 import copyObject from './copyObject'
 import createObject from './createObject'
 import deleteObject from './deleteObject'
@@ -24,7 +24,6 @@ export default async function routes(fastify: FastifyInstance) {
     fastify.register(jwt)
     fastify.register(db)
     fastify.register(storage)
-    fastify.register(tracingMode)
 
     fastify.register(deleteObject)
     fastify.register(deleteObjects)
@@ -43,7 +42,6 @@ export default async function routes(fastify: FastifyInstance) {
   fastify.register(async (fastify) => {
     fastify.register(dbSuperUser)
     fastify.register(storage)
-    fastify.register(tracingMode)
 
     fastify.register(getPublicObject)
     fastify.register(getSignedObject)

src/http/routes/object/listObjects.ts

@@ -73,7 +73,7 @@ export default async function routes(fastify: FastifyInstance) {
         },
       })
 
-      response.status(200).send(results)
+      return response.status(200).send(results)
     }
   )
 }

src/http/routes/render/index.ts

@@ -2,7 +2,7 @@ import { FastifyInstance } from 'fastify'
 import renderPublicImage from './renderPublicImage'
 import renderAuthenticatedImage from './renderAuthenticatedImage'
 import renderSignedImage from './renderSignedImage'
-import { jwt, storage, requireTenantFeature, db, dbSuperUser, tracingMode } from '../../plugins'
+import { jwt, storage, requireTenantFeature, db, dbSuperUser } from '../../plugins'
 import { getConfig } from '../../../config'
 import { rateLimiter } from './rate-limiter'
 
@@ -23,7 +23,6 @@ export default async function routes(fastify: FastifyInstance) {
     fastify.register(jwt)
     fastify.register(db)
     fastify.register(storage)
-    fastify.register(tracingMode)
 
     fastify.register(renderAuthenticatedImage)
   })
@@ -37,7 +36,6 @@ export default async function routes(fastify: FastifyInstance) {
 
     fastify.register(dbSuperUser)
     fastify.register(storage)
-    fastify.register(tracingMode)
 
     fastify.register(renderSignedImage)
     fastify.register(renderPublicImage)

src/http/routes/s3/index.ts

@@ -1,7 +1,7 @@
 import { FastifyInstance, RouteHandlerMethod } from 'fastify'
 import { JSONSchema } from 'json-schema-to-ts'
 import { trace } from '@opentelemetry/api'
-import { db, jsonToXml, signatureV4, storage, tracingMode } from '../../plugins'
+import { db, jsonToXml, signatureV4, storage } from '../../plugins'
 import { findArrayPathsInSchemas, getRouter, RequestInput } from './router'
 import { s3ErrorHandler } from './error-handler'
 
@@ -110,7 +110,6 @@ export default async function routes(fastify: FastifyInstance) {
           fastify.register(signatureV4)
           fastify.register(db)
           fastify.register(storage)
-          fastify.register(tracingMode)
 
           localFastify[method](
             routePath,