feat(server): logging stack traces for db errors + allow async stack traces through env var

packages/server/knexfile.ts

@@ -9,7 +9,8 @@ import {
   postgresMaxConnections,
   isDevOrTestEnv,
   postgresConnectionAcquireTimeoutMillis,
-  postgresConnectionCreateTimeoutMillis
+  postgresConnectionCreateTimeoutMillis,
+  knexAsyncStackTracesEnabled
 } from '@/modules/shared/helpers/envHelper'
 import { dbLogger as logger } from '@/logging/logging'
 import { Knex } from 'knex'
@@ -84,7 +85,8 @@ const configArgs: KnexConfigArgs = {
   logger,
   maxConnections: postgresMaxConnections(),
   connectionAcquireTimeoutMillis: postgresConnectionAcquireTimeoutMillis(),
-  connectionCreateTimeoutMillis: postgresConnectionCreateTimeoutMillis()
+  connectionCreateTimeoutMillis: postgresConnectionCreateTimeoutMillis(),
+  asyncStackTraces: knexAsyncStackTracesEnabled()
 }
 
 const config: Record<string, Knex.Config> = {

packages/server/logging/knexMonitoring.ts

@@ -212,14 +212,17 @@ const initKnexPrometheusMetricsForRegionEvents = async (params: {
           sqlNumberBindings: data.bindings?.length || -1
         })
         .observe(durationSec)
+
+    const trace = (new Error().stack || '').split('\n').slice(1).join('\n').trim()
     params.logger.info(
       {
         region,
         sql: data.sql,
         sqlMethod: normalizeSqlMethod(data.method),
         sqlQueryId: queryId,
         sqlQueryDurationMs: toNDecimalPlaces(durationMs, 0),
-        sqlNumberBindings: data.bindings?.length || -1
+        sqlNumberBindings: data.bindings?.length || -1,
+        trace
       },
       'DB query successfully completed after {sqlQueryDurationMs} ms'
     )

packages/server/modules/shared/helpers/envHelper.ts

@@ -433,3 +433,9 @@ export const shouldRunTestsInMultiregionMode = () =>
 export function shutdownTimeoutSeconds() {
   return getIntFromEnv('SHUTDOWN_TIMEOUT_SECONDS', '300')
 }
+
+export const knexAsyncStackTracesEnabled = () => {
+  const envSet = process.env.KNEX_ASYNC_STACK_TRACES_ENABLED
+  if (!envSet) return undefined
+  return getBooleanFromEnv('KNEX_ASYNC_STACK_TRACES_ENABLED')
+}

packages/shared/src/environment/multiRegionConfig.ts

@@ -2,6 +2,7 @@ import { z } from 'zod'
 import fs from 'node:fs/promises'
 import { Knex, knex } from 'knex'
 import { Logger } from 'pino'
+import { isUndefined } from '#lodash'
 
 const regionConfigSchema = z.object({
   postgres: z.object({
@@ -92,6 +93,12 @@ export type KnexConfigArgs = {
   applicationName: string
   connectionAcquireTimeoutMillis: number
   connectionCreateTimeoutMillis: number
+  /**
+   * If set to any value - true or false - will explicitly enable or disable async stack traces
+   * that show where queries are launched from. If not set, will default to true in dev
+   * and test environments
+   */
+  asyncStackTraces?: boolean
 }
 
 export const createKnexConfig = ({
@@ -103,11 +110,16 @@ export const createKnexConfig = ({
   maxConnections,
   caCertificate,
   connectionAcquireTimeoutMillis,
-  connectionCreateTimeoutMillis
+  connectionCreateTimeoutMillis,
+  asyncStackTraces
 }: {
   connectionString?: string | undefined
   caCertificate?: string | undefined
 } & KnexConfigArgs): Knex.Config => {
+  const shouldEnableAsyncStackTraces = isUndefined(asyncStackTraces)
+    ? isDevOrTestEnv
+    : asyncStackTraces
+
   return {
     client: 'pg',
     migrations: {
@@ -137,7 +149,7 @@ export const createKnexConfig = ({
     },
     // we wish to avoid leaking sql queries in the logs: https://knexjs.org/guide/#compilesqlonerror
     compileSqlOnError: isDevOrTestEnv,
-    asyncStackTraces: isDevOrTestEnv,
+    asyncStackTraces: shouldEnableAsyncStackTraces,
     pool: {
       min: 0,
       max: maxConnections,

utils/helm/speckle-server/templates/_helpers.tpl

@@ -772,6 +772,11 @@ Generate the environment variables for Speckle server and Speckle objects deploy
 - name: POSTGRES_CONNECTION_ACQUIRE_TIMEOUT_MILLIS
   value: {{ .Values.db.connectionAcquireTimeoutMillis | quote }}
 
+{{- if .Values.db.knexAsyncStackTracesEnabled }}
+- name: KNEX_ASYNC_STACK_TRACES_ENABLED
+  value: {{ .Values.db.knexAsyncStackTracesEnabled | quote }}
+{{- end}}
+
 - name: PGSSLMODE
   value: "{{ .Values.db.PGSSLMODE }}"
 

utils/helm/speckle-server/values.schema.json

@@ -241,6 +241,11 @@
           "description": "The maximum time in milliseconds to wait for a new connection to be created in the connection pool. Should be less than the acquisition timeout, as a new connection may need to be created then acquired.",
           "default": 5000
         },
+        "knexAsyncStackTracesEnabled": {
+          "type": "boolean",
+          "description": "If enabled, will provide better stack traces for errors arising out of knex operations",
+          "default": false
+        },
         "databaseName": {
           "type": "string",
           "description": "(Optional) The name of the Postgres database to which Speckle will connect. Only required for the Database Monitoring utility when the connection string is to a database connection pool and multi-region is disabled, otherwise this value is ignored.",

utils/helm/speckle-server/values.yaml

@@ -194,6 +194,9 @@ db:
   ## @param db.connectionCreationTimeoutMillis The maximum time in milliseconds to wait for a new connection to be created in the connection pool. Should be less than the acquisition timeout, as a new connection may need to be created then acquired.
   ##
   connectionCreationTimeoutMillis: 5000
+  ## @param db.knexAsyncStackTracesEnabled If enabled, will provide better stack traces for errors arising out of knex operations
+  ##
+  knexAsyncStackTracesEnabled: false
 
   ## @param db.databaseName (Optional) The name of the Postgres database to which Speckle will connect. Only required for the Database Monitoring utility when the connection string is to a database connection pool and multi-region is disabled, otherwise this value is ignored.
   databaseName: ''