feat: various observability improvements (#2027)

* feat(server): adding userId to req logs

* feat(server): adding userId to gql logs

* feat(fe2): adding userId to logger calls

* feat(fe2): more userId logging additions

* even more thorough logging in FE2

* more adjustments

* add country to fe2 logs

* added prop to help distinguish gql req time logs

* get initial SSR req id in CSR logs

* improved 'fetch failed' error

* better rate limit error message

* minor improvements

packages/frontend-2/.env.example

@@ -4,6 +4,9 @@ PORT=8081
 NUXT_PUBLIC_LOG_LEVEL=debug
 NUXT_PUBLIC_LOG_PRETTY=true
 
+# Whether to emit extra properties (bindings) that would be sent to seq to the console in CSR
+NUXT_PUBLIC_LOG_CSR_EMIT_PROPS=false
+
 NUXT_PUBLIC_API_ORIGIN=http://127.0.0.1:3000
 
 NUXT_PUBLIC_BASE_URL=http://127.0.0.1:8081

packages/frontend-2/app.vue

@@ -13,6 +13,7 @@
 import { useTheme } from '~~/lib/core/composables/theme'
 import { useAuthManager } from '~~/lib/auth/composables/auth'
 import { useMixpanelInitialization } from '~~/lib/core/composables/mp'
+
 const { isDarkTheme } = useTheme()
 
 useHead({

packages/frontend-2/components/error/page/Renderer.vue

@@ -2,18 +2,19 @@
 <template>
   <div class="flex flex-col items-center space-y-8">
     <ErrorPageProjectInviteBanner />
-    <h1 class="h1 font-bold">Error {{ error.statusCode || 500 }}</h1>
+    <h1 class="h1 font-bold">Error {{ finalError.statusCode || 500 }}</h1>
     <h2 class="h3 text-foreground-2 mx-4 break-words">
-      {{ capitalize(error.message || '') }}
+      {{ finalError.message }}
     </h2>
-    <div v-if="isDev && error.stack" class="max-w-xl" v-html="error.stack" />
+    <div v-if="isDev && finalError.stack" class="max-w-xl" v-html="finalError.stack" />
     <FormButton :to="homeRoute" size="xl">Go Home</FormButton>
   </div>
 </template>
 <script setup lang="ts">
+import { formatAppError } from '~/lib/core/helpers/observability'
 import { homeRoute } from '~~/lib/common/helpers/route'
 
-defineProps<{
+const props = defineProps<{
   error: {
     statusCode: number
     message: string
@@ -22,6 +23,5 @@ defineProps<{
 }>()
 
 const isDev = ref(process.dev)
-
-const capitalize = (str: string) => str.charAt(0).toUpperCase() + str.slice(1)
+const finalError = computed(() => formatAppError(props.error))
 </script>

packages/frontend-2/error.vue

@@ -10,6 +10,7 @@
 <script setup lang="ts">
 import type { NuxtError } from '#app'
 import { useTheme } from '~/lib/core/composables/theme'
+import { formatAppError } from '~/lib/core/helpers/observability'
 
 /**
  * Any errors thrown while rendering this page will cause Nuxt to revert to the default
@@ -21,9 +22,10 @@ const props = defineProps<{
 }>()
 
 const { isDarkTheme } = useTheme()
+const finalError = computed(() => formatAppError(props.error))
 
 useHead({
-  title: computed(() => `${props.error.statusCode} - ${props.error.message}`),
+  title: computed(() => `${finalError.value.statusCode} - ${finalError.value.message}`),
   bodyAttrs: {
     class: 'simple-scrollbar bg-foundation-page text-foreground'
   },

packages/frontend-2/lib/auth/composables/activeUser.ts

@@ -21,6 +21,16 @@ export const activeUserQuery = graphql(`
   }
 `)
 
+/**
+ * Lightweight composable to read user id from cache imperatively (useful for logging)
+ */
+export function useReadUserId() {
+  const client = useApolloClient().client
+  return () => {
+    return client.readQuery({ query: activeUserQuery })?.activeUser?.id
+  }
+}
+
 /**
  * Get active user.
  * undefined - not yet resolved

packages/frontend-2/lib/core/composables/appErrorState.ts

@@ -16,7 +16,7 @@ export function useAppErrorState() {
       const epm = state.errorRpm.hit()
 
       if (!state.inErrorState.value && epm >= ENTER_STATE_AT_ERRORS_PER_MIN) {
-        logger.error(
+        logger.fatal(
           `Too many errors (${epm} errors per minute), entering app error state!`
         )
         state.inErrorState.value = true

packages/frontend-2/lib/core/composables/server.ts

@@ -2,6 +2,7 @@ import { useQuery } from '@vue/apollo-composable'
 import { nanoid } from 'nanoid'
 import { graphql } from '~~/lib/common/generated/gql'
 import type { H3Event } from 'h3'
+import type { Optional } from '@speckle/shared'
 
 export const mainServerInfoDataQuery = graphql(`
   query MainServerInfoData {
@@ -31,6 +32,22 @@ export function useServerInfo() {
   return { serverInfo, isGuestMode }
 }
 
+/**
+ * Get the req.id that is/was used in the initial SSR request
+ *
+ * Note: In SSR, this can only be used after the 001-logging middleware, cause that's when the ID is set
+ */
+export function useServerRequestId() {
+  const nuxt = useNuxtApp()
+  const state = useState('server_request_id', () => {
+    // The client side should not need to resolve this info, as it should come from the serialized SSR state
+    if (process.client || !nuxt.ssrContext) return undefined
+    return nuxt.ssrContext.event.node.req.id as string
+  })
+
+  return computed(() => state.value)
+}
+
 /**
  * Get the value that should be used as the request correlation ID
  *
@@ -59,3 +76,17 @@ export function useRequestId(params?: {
     return state.value
   }
 }
+
+/**
+ * Resolve the user's geolocation, if possible (only supported wherever we host behind Cloudflare)
+ */
+export function useUserCountry() {
+  const nuxt = useNuxtApp()
+  const state = useState('active_user_country', () => {
+    // The client side should not need to resolve this info, as it should come from the serialized SSR state
+    if (process.client || !nuxt.ssrContext) return undefined
+    return nuxt.ssrContext.event.node.req.headers['cf-ipcountry'] as Optional<string>
+  })
+
+  return computed(() => state.value)
+}

packages/frontend-2/lib/core/configs/apollo.ts

@@ -313,7 +313,8 @@ function createLink(params: {
           ...omit(res, ['forward', 'response']),
           networkErrorMessage: res.networkError?.message,
           gqlErrorMessages: res.graphQLErrors?.map((e) => e.message),
-          errorMessage: errMsg
+          errorMessage: errMsg,
+          graphql: true
         },
         'Apollo Client error: {errorMessage}'
       )
@@ -389,7 +390,7 @@ function createLink(params: {
     const name = operation.operationName
 
     nuxtApp.$logger.debug(
-      { operation: name },
+      { operation: name, graphql: true },
       `Apollo operation {operation} started...`
     )
     return forward(operation).map((result) => {
@@ -400,7 +401,8 @@ function createLink(params: {
         {
           operation: name,
           elapsed,
-          success
+          success,
+          graphql: true
         },
         `Apollo operation {operation} finished in {elapsed}ms`
       )

packages/frontend-2/lib/core/helpers/observability.ts

@@ -4,7 +4,15 @@
 /* eslint-disable @typescript-eslint/no-unsafe-assignment */
 
 import { Observability } from '@speckle/shared'
-import { get, isBoolean, isNumber, isObjectLike, isString, noop } from 'lodash-es'
+import {
+  upperFirst,
+  get,
+  isBoolean,
+  isNumber,
+  isObjectLike,
+  isString,
+  noop
+} from 'lodash-es'
 
 /**
  * Add pino-pretty like formatting
@@ -21,9 +29,10 @@ const prettify = (log: object, msg: string) =>
 
 /**
  * Wrap any logger call w/ logic that prettifies the error message like pino-pretty does
+ * and emits bindings if they are provided
  */
 const log =
-  (logger: (...args: unknown[]) => void) =>
+  (logger: (...args: unknown[]) => void, bindings?: () => Record<string, unknown>) =>
   (...vals: unknown[]) => {
     const finalVals = vals.slice()
 
@@ -38,25 +47,39 @@ const log =
       finalVals.unshift(finalMsg)
     }
 
+    if (bindings) {
+      const boundVals = JSON.parse(JSON.stringify(bindings()))
+      finalVals.push(boundVals)
+    }
+
     logger(...finalVals)
   }
 
 export function buildFakePinoLogger(
-  options?: Partial<{ onError: (...args: any[]) => void }>
+  options?: Partial<{
+    onError: (...args: any[]) => void
+    /**
+     * Returns an object that will be merged into the log context when outputting to the console.
+     * These will not be sent to seq!
+     */
+    consoleBindings: () => Record<string, unknown>
+  }>
 ) {
+  const bindings = options?.consoleBindings
+
   const errLogger = (...args: unknown[]) => {
     const { onError } = options || {}
     if (onError) onError(...args)
-    log(console.error)(...args)
+    log(console.error, bindings)(...args)
   }
 
   const logger = {
-    debug: log(console.debug),
-    info: log(console.info),
-    warn: log(console.warn),
+    debug: log(console.debug, bindings),
+    info: log(console.info, bindings),
+    warn: log(console.warn, bindings),
     error: errLogger,
     fatal: errLogger,
-    trace: log(console.trace),
+    trace: log(console.trace, bindings),
     silent: noop
   } as unknown as ReturnType<typeof Observability.getLogger>
 
@@ -64,3 +87,34 @@ export function buildFakePinoLogger(
 
   return logger
 }
+
+export type SimpleError = {
+  statusCode: number
+  message: string
+  stack?: string
+}
+
+export const formatAppError = (err: SimpleError) => {
+  const { statusCode, message, stack } = err
+
+  let finalMessage = message || ''
+  let finalStatusCode = statusCode || 500
+
+  if (finalMessage.match(/^fetch failed$/i)) {
+    finalMessage = 'Internal API call failed, please contact site administrators'
+  }
+
+  if (finalMessage.match(/status code 429/i)) {
+    finalMessage =
+      'You are sending too many requests. You have been rate limited. Please try again later.'
+    finalStatusCode = 429
+  }
+
+  finalMessage = upperFirst(finalMessage)
+
+  return {
+    statusCode: finalStatusCode,
+    message: finalMessage,
+    stack
+  }
+}

packages/frontend-2/nuxt.config.ts

@@ -48,6 +48,7 @@ export default defineNuxtConfig({
       mixpanelTokenId: 'UNDEFINED',
       logLevel: NUXT_PUBLIC_LOG_LEVEL,
       logPretty: isLogPretty,
+      logCsrEmitProps: false,
       logClientApiToken: '',
       logClientApiEndpoint: '',
       speckleServerVersion: SPECKLE_SERVER_VERSION || 'unknown',

packages/frontend-2/plugins/001-logger.ts

@@ -1,6 +1,11 @@
 /* eslint-disable @typescript-eslint/restrict-template-expressions */
-import { isString } from 'lodash-es'
-import { useRequestId } from '~/lib/core/composables/server'
+import { isString, omit } from 'lodash-es'
+import { useReadUserId } from '~/lib/auth/composables/activeUser'
+import {
+  useRequestId,
+  useServerRequestId,
+  useUserCountry
+} from '~/lib/core/composables/server'
 import { isObjectLike } from '~~/lib/common/helpers/type'
 import { buildFakePinoLogger } from '~~/lib/core/helpers/observability'
 
@@ -16,33 +21,91 @@ export default defineNuxtPlugin(async (nuxtApp) => {
       logClientApiToken,
       speckleServerVersion,
       logClientApiEndpoint,
-      serverName
+      serverName,
+      logCsrEmitProps
     }
   } = useRuntimeConfig()
   const route = useRoute()
   const router = useRouter()
   const reqId = useRequestId()
+  const serverReqId = useServerRequestId()
+  const getUserId = useReadUserId()
+  const country = useUserCountry()
 
   const collectMainInfo = (params: { isBrowser: boolean }) => {
-    return {
+    const info = {
       browser: params.isBrowser,
       speckleServerVersion,
       serverName,
       frontendType: 'frontend-2',
       route: route?.path,
       routeDefinition: route.matched?.[route.matched.length - 1]?.path,
-      req: { id: reqId }
+      req: { id: reqId },
+      userId: getUserId(),
+      country: country.value,
+      serverReqId: serverReqId.value
     }
+    return info
   }
 
   // Set up logger
   let logger: ReturnType<typeof import('@speckle/shared').Observability.getLogger>
   if (process.server) {
-    const { buildLogger } = await import('~/server/lib/core/helpers/observability')
-    logger = buildLogger(logLevel, logPretty).child({
-      ...collectMainInfo({ isBrowser: false })
+    const { buildLogger, enableDynamicBindings, serializeRequest } = await import(
+      '~/server/lib/core/helpers/observability'
+    )
+    logger = enableDynamicBindings(buildLogger(logLevel, logPretty).child({}), () => ({
+      ...collectMainInfo({ isBrowser: false }),
+      ...(nuxtApp.ssrContext
+        ? { req: serializeRequest(nuxtApp.ssrContext.event.node.req) }
+        : {})
+    }))
+
+    // Collect bindings for pino-http logger
+    nuxtApp.hook('app:rendered', () => {
+      if (!nuxtApp.ssrContext) return
+      const bindings = collectMainInfo({ isBrowser: false })
+      nuxtApp.ssrContext.event.node.res.vueLoggerBindings = omit(bindings, [
+        'req',
+        'res'
+      ])
     })
   } else {
+    const localTimeFormat = new Intl.DateTimeFormat('en-GB', {
+      dateStyle: 'full',
+      timeStyle: 'long'
+    })
+    const collectBrowserInfo = () => {
+      const {
+        userAgent,
+        platform: navigatorPlatform,
+        vendor: navigatorVendor
+      } = navigator
+      const url = window.location.href
+      const localTime = localTimeFormat.format(new Date())
+
+      // Get browser dimensions & screen dimensions
+      const { innerWidth: browserWidth, innerHeight: browserHeight } = window
+      const { width: screenWidth, height: screenHeight } = window.screen
+
+      return {
+        userAgent,
+        navigatorPlatform,
+        navigatorVendor,
+        url,
+        localTime,
+        dimensions: {
+          browser: { width: browserWidth, height: browserHeight },
+          screen: { width: screenWidth, height: screenHeight }
+        }
+      }
+    }
+
+    const collectCoreInfo = () => ({
+      ...collectBrowserInfo(),
+      ...collectMainInfo({ isBrowser: true })
+    })
+
     if (logClientApiToken?.length && logClientApiEndpoint?.length) {
       const seq = await import('seq-logging/browser')
       const seqLogger = new seq.Logger({
@@ -52,22 +115,6 @@ export default defineNuxtPlugin(async (nuxtApp) => {
         onError: console.error
       })
 
-      const collectBrowserInfo = () => {
-        const {
-          userAgent,
-          platform: navigatorPlatform,
-          vendor: navigatorVendor
-        } = navigator
-        const url = window.location.href
-
-        return { userAgent, navigatorPlatform, navigatorVendor, url }
-      }
-
-      const collectCoreInfo = () => ({
-        ...collectBrowserInfo(),
-        ...collectMainInfo({ isBrowser: true })
-      })
-
       const errorListener = (event: ErrorEvent | PromiseRejectionEvent) => {
         const isUnhandledRejection = isObjectLike(event) && 'reason' in event
         const err = ('reason' in event ? event.reason : event.error) as unknown
@@ -129,23 +176,29 @@ export default defineNuxtPlugin(async (nuxtApp) => {
       window.addEventListener('error', errorListener)
       window.addEventListener('unhandledrejection', errorListener)
 
-      logger = buildFakePinoLogger({ onError: customLogger })
+      logger = buildFakePinoLogger({
+        onError: customLogger,
+        consoleBindings: logCsrEmitProps ? collectCoreInfo : undefined
+      })
       logger.debug('Set up seq ingestion...')
     } else {
-      logger = buildFakePinoLogger()
+      // No seq integration, fallback to basic console logging
+      logger = buildFakePinoLogger({
+        consoleBindings: logCsrEmitProps ? collectCoreInfo : undefined
+      })
     }
   }
 
-  // Set up global error handler
+  // Set up global vue error handler
   nuxtApp.vueApp.config.errorHandler = (err, _vm, info) => {
     logger.error(err, 'Unhandled error in Vue app', info)
   }
 
   // Uncaught routing error handler
   router.onError((err, to, from) => {
-    // skip 404
+    // skip 404, 403, 401
     if (isObjectLike(err) && 'statusCode' in err) {
-      if ([404].includes(err.statusCode as number)) return
+      if ([404, 403, 401].includes(err.statusCode as number)) return
     }
 
     logger.error(err, 'Unhandled error in routing', {

packages/frontend-2/server/lib/core/helpers/observability.ts

@@ -1,5 +1,60 @@
+/* eslint-disable @typescript-eslint/no-unsafe-return */
 import { Observability } from '@speckle/shared'
+import type { IncomingMessage } from 'node:http'
+import { get } from 'lodash-es'
+import type { Logger } from 'pino'
+
+const redactedReqHeaders = ['authorization', 'cookie']
 
 export function buildLogger(logLevel: string = 'info', logPretty: boolean = false) {
   return Observability.getLogger(logLevel, logPretty)
 }
+
+export function enableDynamicBindings(
+  logger: Logger,
+  bindings: () => Record<string, unknown>
+): Logger {
+  return new Proxy(logger, {
+    get(target, prop) {
+      if (
+        ['trace', 'debug', 'info', 'warn', 'error', 'fatal'].includes(prop as string)
+      ) {
+        const logMethod = get(target, prop) as (...args: unknown[]) => void
+        return (...args: unknown[]) => {
+          const log = logMethod.bind(target)
+
+          // Re-setting bindings on every log call, cause there's no other way to make them dynamic
+          try {
+            const boundVals = bindings()
+            target.setBindings(boundVals)
+          } catch (e) {
+            target.error(e, 'Failed to set dynamic bindings')
+          }
+
+          return log(...args)
+        }
+      }
+
+      return get(target, prop)
+    }
+  })
+}
+
+export function serializeRequest(req: IncomingMessage) {
+  return {
+    id: req.id,
+    method: req.method,
+    path: req.url?.split('?')[0], // Remove query params which might be sensitive
+    // Allowlist useful headers
+    headers: Object.keys(req.headers).reduce((obj, key) => {
+      let valueToPrint = req.headers[key]
+      if (redactedReqHeaders.includes(key.toLocaleLowerCase())) {
+        valueToPrint = `REDACTED[length: ${valueToPrint ? valueToPrint.length : 0}]`
+      }
+      return {
+        ...obj,
+        [key]: valueToPrint
+      }
+    }, {})
+  }
+}

packages/frontend-2/server/middleware/001-logging.ts

@@ -9,6 +9,7 @@ import { randomUUID } from 'crypto'
 import type { IncomingHttpHeaders } from 'http'
 import { REQUEST_ID_HEADER } from '~~/server/lib/core/helpers/constants'
 import { get } from 'lodash'
+import { serializeRequest } from '~/server/lib/core/helpers/observability'
 
 /**
  * Server request logger
@@ -32,8 +33,6 @@ const logger = Observability.getLogger(
   useRuntimeConfig().public.logPretty
 )
 
-const redactedHeaders = ['authorization', 'cookie']
-
 export const LoggingMiddleware = pinoHttp({
   logger,
   autoLogging: true,
@@ -68,10 +67,13 @@ export const LoggingMiddleware = pinoHttp({
     const isCompleted = !req.readableAborted && res.writableEnded
     const requestStatus = isCompleted ? 'completed' : 'aborted'
     const requestPath = req.url?.split('?')[0] || 'unknown'
+    const appBindings = res.vueLoggerBindings || {}
+
     return {
       ...val,
       requestStatus,
-      requestPath
+      requestPath,
+      ...appBindings
     }
   },
 
@@ -81,10 +83,13 @@ export const LoggingMiddleware = pinoHttp({
   customErrorObject(req, res, err, val: Record<string, unknown>) {
     const requestStatus = 'failed'
     const requestPath = req.url?.split('?')[0] || 'unknown'
+    const appBindings = res.vueLoggerBindings || {}
+
     return {
       ...val,
       requestStatus,
-      requestPath
+      requestPath,
+      ...appBindings
     }
   },
 
@@ -92,24 +97,7 @@ export const LoggingMiddleware = pinoHttp({
   // 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: Object.keys(req.raw.headers).reduce((obj, key) => {
-          let valueToPrint = req.raw.headers[key]
-          if (redactedHeaders.includes(key.toLocaleLowerCase())) {
-            valueToPrint = `REDACTED[length: ${valueToPrint ? valueToPrint.length : 0}]`
-          }
-          return {
-            ...obj,
-            [key]: valueToPrint
-          }
-        }, {})
-      }
-    }),
+    req: pino.stdSerializers.wrapRequestSerializer((req) => serializeRequest(req.raw)),
     res: pino.stdSerializers.wrapResponseSerializer((res) => {
       const resRaw = res as SerializedResponse & {
         raw: {

packages/frontend-2/type-augmentations/server.d.ts

@@ -0,0 +1,7 @@
+declare module 'http' {
+  interface ServerResponse {
+    vueLoggerBindings: Record<string, unknown>
+  }
+}
+
+export {}

packages/server/app.ts

@@ -73,15 +73,18 @@ function logSubscriptionOperation(params: {
   response?: SubscriptionResponse
 }) {
   const { error, response, ctx, execParams } = params
+  const userId = ctx.userId
   if (!error && !response) return
 
   const logger = ctx.log.child({
     graphql_query: execParams.query.toString(),
     graphql_variables: redactSensitiveVariables(execParams.variables),
     graphql_operation_name: execParams.operationName,
-    graphql_operation_type: 'subscription'
+    graphql_operation_type: 'subscription',
+    userId
   })
 
+  const errMsg = 'GQL subscription event {graphql_operation_name} errored'
   const errors = response?.errors || (error ? [error] : [])
   if (errors.length) {
     for (const error of errors) {
@@ -89,13 +92,13 @@ function logSubscriptionOperation(params: {
         (error instanceof GraphQLError && error.extensions?.code === 'FORBIDDEN') ||
         error instanceof ApolloError
       ) {
-        logger.info(error, 'graphql error')
+        logger.info(error, errMsg)
       } else {
-        logger.error(error, 'graphql error')
+        logger.error(error, errMsg)
       }
     }
   } else if (response?.data) {
-    logger.info('graphql response')
+    logger.info('GQL subscription event {graphql_operation_name} emitted')
   }
 }
 

packages/server/logging/apolloPlugin.js

@@ -22,6 +22,8 @@ module.exports = {
     return {
       didResolveOperation(ctx) {
         let logger = ctx.context.log || graphqlLogger
+        const auth = ctx.context
+        const userId = auth?.userId
 
         const op = `GQL ${ctx.operation.operation} ${ctx.operation.selectionSet.selections[0].name.value}`
         const name = `GQL ${ctx.operation.selectionSet.selections[0].name.value}`
@@ -34,7 +36,8 @@ module.exports = {
           graphql_query: query,
           graphql_variables: redactSensitiveVariables(variables),
           graphql_operation_value: op,
-          graphql_operation_name: name
+          graphql_operation_name: name,
+          userId
         })
 
         const transaction = Sentry.startTransaction({

packages/server/logging/expressLogging.ts

@@ -5,6 +5,9 @@ import { IncomingMessage } from 'http'
 import { NextFunction, Response } from 'express'
 import pino, { SerializedResponse } from 'pino'
 import { GenReqId } from 'pino-http'
+import { get } from 'lodash'
+import type { ServerResponse } from 'http'
+import { Optional } from '@speckle/shared'
 
 const REQUEST_ID_HEADER = 'x-request-id'
 
@@ -42,10 +45,13 @@ export const LoggingExpressMiddleware = HttpLogger({
     const isCompleted = !req.readableAborted && res.writableEnded
     const requestStatus = isCompleted ? 'completed' : 'aborted'
     const requestPath = req.url?.split('?')[0] || 'unknown'
+    const country = req.headers['cf-ipcountry'] as Optional<string>
+
     return {
       ...val,
       requestStatus,
-      requestPath
+      requestPath,
+      country
     }
   },
 
@@ -55,10 +61,13 @@ export const LoggingExpressMiddleware = HttpLogger({
   customErrorObject(req, res, err, val: Record<string, unknown>) {
     const requestStatus = 'failed'
     const requestPath = req.url?.split('?')[0] || 'unknown'
+    const country = req.headers['cf-ipcountry'] as Optional<string>
+
     return {
       ...val,
       requestStatus,
-      requestPath
+      requestPath,
+      country
     }
   },
 
@@ -94,10 +103,14 @@ export const LoggingExpressMiddleware = HttpLogger({
           headers: Record<string, string>
         }
       }
+      const serverRes = get(res, 'raw.raw') as ServerResponse
+      const auth = serverRes.req.context
+
       return {
         statusCode: res.raw.statusCode,
         // Allowlist useful headers
-        headers: resRaw.raw.headers
+        headers: resRaw.raw.headers,
+        userId: auth?.userId
       }
     })
   }

packages/server/type-augmentations/express.d.ts

@@ -15,4 +15,10 @@ declare module 'express-serve-static-core' {
   }
 }
 
+declare module 'http' {
+  interface IncomingMessage {
+    context?: AuthContext
+  }
+}
+
 export {}