Merge pull request #962 from dpc-sdp/feature/nuxt-logging

[R20-1581] feat(@dpc-sdp/nuxt-ripple): adds logging in vue/nuxt contexts

.gitignore

@@ -1,6 +1,6 @@
 # Temporary files
 node_modules
-*.log*
+*.log
 .nuxt
 .nitro
 .cache

packages/nuxt-ripple/components/TideBaseLayout.vue

@@ -93,7 +93,13 @@
 
 <script setup lang="ts">
 // @ts-ignore
-import { useAppConfig, useRoute, useNuxtApp, useTideLanguage } from '#imports'
+import {
+  useAppConfig,
+  useRoute,
+  useNuxtApp,
+  useTideLanguage,
+  useLogger
+} from '#imports'
 import { computed, onMounted, provide, ref } from 'vue'
 import { defu as defuMerge } from 'defu'
 import { TideSiteData } from '../types'
@@ -164,6 +170,12 @@ const footerNav = computed(() => {
 })
 
 const nuxtApp = useNuxtApp()
+const logger = useLogger()
+
+logger.info('Calling tide:page hook...', {
+  label: 'TideBaseLayout'
+})
+
 /*
  * This hook can be called from plugins to extend Tide managed pages behaviour - see /plugins folder for examples
  */

packages/nuxt-ripple/composables/use-logger.ts

@@ -0,0 +1,17 @@
+export const useLogger = () => {
+  const { $logger } = useNuxtApp()
+  const noop = () => {}
+
+  if (process.server) {
+    return $logger
+  }
+
+  return {
+    debug: noop,
+    info: noop,
+    warning: noop,
+    error: noop
+  }
+}
+
+export default useLogger

packages/nuxt-ripple/composables/use-section-id.ts

@@ -0,0 +1,9 @@
+import { useRequestHeaders } from '#imports'
+
+export const useSectionId = (): string => {
+  const sectionIdHeaderName = 'section-io-id'
+  const requestHeaders = useRequestHeaders([sectionIdHeaderName])
+  return requestHeaders[sectionIdHeaderName] || 'no section id'
+}
+
+export default useSectionId

packages/nuxt-ripple/composables/use-tide-page.ts

@@ -1,5 +1,11 @@
 import type { TidePageBase } from './../types'
-import { useCookie, isPreviewPath, AuthCookieNames } from '#imports'
+import {
+  useCookie,
+  isPreviewPath,
+  AuthCookieNames,
+  useLogger,
+  useSectionId
+} from '#imports'
 
 const isCacheTimeExpired = (date: number, expiryInMinutes = 5) => {
   // 5 minute default expiry in step with varnish cache
@@ -8,7 +14,7 @@ const isCacheTimeExpired = (date: number, expiryInMinutes = 5) => {
   return date < timePlusExpiry
 }
 
-const checkForRedirect = async (page: TidePageBase) => {
+const checkForRedirect = async (page: TidePageBase, debugLogger) => {
   // Redirect on the 6 codes that Drupal supplies
   if (page?.type === 'redirect') {
     switch (page.status_code) {
@@ -18,6 +24,13 @@ const checkForRedirect = async (page: TidePageBase) => {
       case '304':
       case '305':
       case '307':
+        debugLogger(`Redirecting to ${page?.redirect_url}`, {
+          pageType: page?.type,
+          pageRedirectUrl: page?.redirect_url,
+          pageRedirectType: page?.redirect_type,
+          pageStatusCode: page?.status_code
+        })
+
         await navigateTo(page.redirect_url, {
           replace: true,
           redirectCode: page.status_code,
@@ -33,19 +46,41 @@ export const useTidePage = async (
   slug?: string,
   site?: number
 ): Promise<TidePageBase> => {
+  const logger = useLogger()
   const route = useRoute()
+
   const path = slug || route.path
   const { public: config } = useRuntimeConfig()
   const siteId = site || config.tide?.site
 
+  const sectionRequestId = useSectionId()
+
+  const debugLogger = (message: string, data = {}) => {
+    logger.debug(message, {
+      label: 'useTidePage',
+      section_io_id: sectionRequestId,
+      ...data
+    })
+  }
+
+  debugLogger('Route requested', {
+    path,
+    siteId
+  })
+
   // check we dont add too many keys to cache
   const nuxt = useNuxtApp()
   const maxCacheItems = 50
   if (nuxt.payload.data) {
-    if (Object.keys(nuxt.payload.data).length > maxCacheItems + 1) {
-      if (process.dev) {
-        console.log('clear nuxt cache')
+    debugLogger(
+      `Nuxt cache length is: ${Object.keys(nuxt.payload.data).length}`,
+      {
+        nuxtCacheKeys: Object.keys(nuxt.payload.data)
       }
+    )
+
+    if (Object.keys(nuxt.payload.data).length > maxCacheItems + 1) {
+      debugLogger(`Cache is larger than max ${maxCacheItems} items, clearing...`)
       clearNuxtData()
     }
   }
@@ -55,14 +90,22 @@ export const useTidePage = async (
   // Refresh data so it doesnt go stale whilst client side nav
   if (pageData.value && pageData.value._fetched) {
     if (isCacheTimeExpired(pageData.value._fetched)) {
-      if (process.dev) {
-        console.log('Cache reset for page', `page-${path}`)
-      }
+
+      debugLogger(
+        'Cached data for this page is stale, clearing nuxt cache just for this page...',
+        {
+          cacheKey: `page-${path}`
+        }
+      )
+
       await clearNuxtData(`page-${path}`)
     }
   }
 
-  const headers = {}
+  const headers: {
+    cookie?: string
+    'x-section-request-id'?: string
+  } = {}
 
   // Need to manually pass the cookies needed for auth as they aren't automatically added when server rendered
   if (isPreviewPath(path)) {
@@ -73,9 +116,15 @@ export const useTidePage = async (
     headers.cookie = `${AuthCookieNames.ACCESS_TOKEN}=${accessTokenCookie.value};${AuthCookieNames.ACCESS_TOKEN_EXPIRY}=${accessTokenExpiryCookie.value}`
   }
 
+  if (process.server) {
+    headers['x-section-request-id'] = sectionRequestId
+  }
+
   let sectionCacheTags: string | null = null
 
   if (!pageData.value) {
+    debugLogger('No cached page found, fetching the page data...')
+
     const { data, error } = await useFetch('/api/tide/page', {
       key: `page-${path}`,
       baseURL: config.apiUrl || '',
@@ -102,12 +151,22 @@ export const useTidePage = async (
       useTideError(error.value?.statusCode)
     }
 
-    await checkForRedirect(data.value)
+    debugLogger('Page data fetched', {
+      pageTitle: data.value.title,
+      pageNodeId: data.value.nid
+    })
+
+    await checkForRedirect(data.value, debugLogger)
 
     return data.value
   }
 
-  await checkForRedirect(pageData.value)
+  debugLogger('Cached data for this page was found and is being used...', {
+    pageTitle: pageData.value.title,
+    pageNodeId: pageData.value.nid
+  })
+
+  await checkForRedirect(pageData.value, debugLogger)
 
   return pageData.value
 }

packages/nuxt-ripple/composables/use-tide-site.ts

@@ -1,11 +1,22 @@
 import type { TideSiteData } from './../types'
+import { useSectionId } from '#imports'
 
 export const useTideSite = async (id?: number): Promise<TideSiteData> => {
   const { public: config } = useRuntimeConfig()
   const siteId = id || config.tide?.site
   const { data: siteData } = useNuxtData(`site-${siteId}`)
   const nuxt = useNuxtApp()
 
+  const sectionRequestId = useSectionId()
+
+  const headers: {
+    'x-section-request-id'?: string
+  } = {}
+
+  if (process.server) {
+    headers['x-section-request-id'] = sectionRequestId
+  }
+
   let sectionCacheTags: string | null = null
 
   if (!siteData.value) {
@@ -15,6 +26,7 @@ export const useTideSite = async (id?: number): Promise<TideSiteData> => {
       params: {
         id: siteId
       },
+      headers,
       async onResponse({ response }) {
         sectionCacheTags = response.headers.get('section-cache-tags')
       }

packages/nuxt-ripple/plugins/00.logging.server.ts

@@ -0,0 +1,10 @@
+import { defineNuxtPlugin } from '#app'
+import { logger } from '@dpc-sdp/ripple-tide-api'
+
+export default defineNuxtPlugin(() => {
+  return {
+    provide: {
+      logger
+    }
+  }
+})

packages/nuxt-ripple/plugins/site-theme.ts

@@ -1,4 +1,4 @@
-import { useAppConfig, useHead } from '#imports'
+import { useAppConfig, useHead, useLogger } from '#imports'
 import { defu as defuMerge } from 'defu'
 
 const formatThemeStyle = (themeObj) => {
@@ -13,6 +13,12 @@ const formatThemeStyle = (themeObj) => {
 
 export default defineNuxtPlugin((nuxtApp) => {
   nuxtApp.hook('tide:page', ({ site }) => {
+    const logger = useLogger()
+
+    logger.info('tide:page hook was triggered', {
+      label: 'site-theme.ts'
+    })
+
     const siteTheme = defuMerge(
       site?.theme,
       useAppConfig()?.ripple?.theme || {}

packages/nuxt-ripple/server/api/tide/page.ts

@@ -4,7 +4,8 @@ import {
   getQuery,
   H3Event,
   getCookie,
-  setResponseHeader
+  setResponseHeader,
+  getHeader
 } from 'h3'
 import { createHandler, TidePageApi } from '@dpc-sdp/ripple-tide-api'
 import { BadRequestError } from '@dpc-sdp/ripple-tide-api/errors'
@@ -41,11 +42,14 @@ export const createPageHandler = async (
       headers['X-OAuth2-Authorization'] = `Bearer ${tokenCookie}`
     }
 
+    const sectionId = getHeader(event, 'x-section-request-id')
+
     const pageResponse = await tidePageApi.getPageByPath(
       query.path,
       query.site,
       {},
-      headers
+      headers,
+      sectionId
     )
 
     // Need to pass on the section cache tags to the nuxt app

packages/nuxt-ripple/server/api/tide/site.ts

@@ -15,7 +15,9 @@ export const createSiteHandler = async (
       throw new BadRequestError('Site id is required')
     }
 
-    const siteResponse = await tideSiteApi.getSiteData(query.id)
+    const sectionId = getHeader(event, 'x-section-request-id')
+
+    const siteResponse = await tideSiteApi.getSiteData(query.id, sectionId)
 
     // Need to pass on the section cache tags to the nuxt app
     if (siteResponse.headers && siteResponse.headers['section-cache-tags']) {

packages/ripple-tide-api/src/services/http-client.ts

@@ -38,7 +38,11 @@ export default class HttpClient {
           `${request.method?.toUpperCase()} request to ${this.client.getUri(
             request
           )}`,
-          { label: this.logLabel }
+          {
+            label: this.logLabel,
+            // _logId is a custom property added by us https://github.com/axios/axios/issues/2203
+            section_io_id: (request as any)._logId || 'no section id'
+          }
         )
         return request
       },
@@ -62,7 +66,9 @@ export default class HttpClient {
               error.request.path
             }`,
             {
-              label: this.logLabel
+              label: this.logLabel,
+              // _logId is a custom property added by us https://github.com/axios/axios/issues/2203
+              section_io_id: error.request?._logId || 'no section id'
             }
           )
         } else {