feat: various observability improvements (specklesystems#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,29 +47,74 @@ 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>
 
   logger.child = () => logger as any
 
   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',