Merge pull request #6263 from Shopify/app_log_errors_in_dev_output

Ensure errors in app logging render in regular dev log stream

Author: nickwesselman

packages/app/src/cli/services/app-logs/dev/poll-app-logs.test.ts

@@ -379,11 +379,11 @@ describe('pollAppLogs', () => {
       organizationId: 'organizationId',
     })
 
-    expect(outputWarnSpy).toHaveBeenCalledWith('Request throttled while polling app logs.')
+    expect(outputWarnSpy).toHaveBeenCalledWith('Request throttled while polling app logs.', stdout)
     expect(vi.getTimerCount()).toEqual(1)
   })
 
-  test('displays error message, waits, and retries if error occured', async () => {
+  test('displays error message, waits, and retries if error occurred', async () => {
     // Given
     const outputDebugSpy = vi.spyOn(output, 'outputDebug')
     const outputWarnSpy = vi.spyOn(output, 'outputWarn')
@@ -406,7 +406,7 @@ describe('pollAppLogs', () => {
     })
 
     // Then
-    expect(outputWarnSpy).toHaveBeenCalledWith('Error while polling app logs.')
+    expect(outputWarnSpy).toHaveBeenCalledWith('Error while polling app logs.', stdout)
     expect(vi.getTimerCount()).toEqual(1)
   })
 
@@ -450,8 +450,8 @@ describe('pollAppLogs', () => {
 
     // When/Then
     await expect(writeAppLogsToFile).not.toHaveBeenCalled
-    expect(outputWarnSpy).toHaveBeenCalledWith('Error while polling app logs.')
-    expect(outputWarnSpy).toHaveBeenCalledWith('Retrying in 5 seconds.')
+    expect(outputWarnSpy).toHaveBeenCalledWith('Error while polling app logs.', stdout)
+    expect(outputWarnSpy).toHaveBeenCalledWith('Retrying in 5 seconds.', stdout)
     expect(outputDebugSpy).toHaveBeenCalledWith(expect.stringContaining('JSON'))
   })
 })

packages/app/src/cli/services/app-logs/dev/poll-app-logs.ts

@@ -50,31 +50,7 @@ export const pollAppLogs = async ({
     const response = await developerPlatformClient.appLogs({jwtToken, cursor}, organizationId)
 
     const {errors, status} = response as AppLogsError
-    if (status !== 200) {
-      const errorResponse = {
-        errors: errors.map((error) => ({message: error, status})),
-      }
-
-      const result = await handleFetchAppLogsError({
-        response: errorResponse,
-        onThrottle: (retryIntervalMs) => {
-          outputWarn(`Request throttled while polling app logs.`)
-          outputWarn(`Retrying in ${retryIntervalMs / 1000} seconds.`)
-        },
-        onUnknownError: (retryIntervalMs) => {
-          outputWarn(`Error while polling app logs.`)
-          outputWarn(`Retrying in ${retryIntervalMs / 1000} seconds.`)
-        },
-        onResubscribe: () => {
-          return resubscribeCallback()
-        },
-      })
-
-      if (result.nextJwtToken) {
-        nextJwtToken = result.nextJwtToken
-      }
-      retryIntervalMs = result.retryIntervalMs
-    } else {
+    if (status === 200) {
       const {app_logs: appLogs} = response as AppLogsSuccess
 
       for (const log of appLogs) {
@@ -106,6 +82,30 @@ export const pollAppLogs = async ({
           )
         })
       }
+    } else {
+      const errorResponse = {
+        errors: errors.map((error) => ({message: error, status})),
+      }
+
+      const result = await handleFetchAppLogsError({
+        response: errorResponse,
+        onThrottle: (retryIntervalMs) => {
+          outputWarn(`Request throttled while polling app logs.`, stdout)
+          outputWarn(`Retrying in ${retryIntervalMs / 1000} seconds.`, stdout)
+        },
+        onUnknownError: (retryIntervalMs) => {
+          outputWarn(`Error while polling app logs.`, stdout)
+          outputWarn(`Retrying in ${retryIntervalMs / 1000} seconds.`, stdout)
+        },
+        onResubscribe: () => {
+          return resubscribeCallback()
+        },
+      })
+
+      if (result.nextJwtToken) {
+        nextJwtToken = result.nextJwtToken
+      }
+      retryIntervalMs = result.retryIntervalMs
     }
 
     const {cursor: responseCursor} = response as AppLogsSuccess
@@ -129,8 +129,8 @@ export const pollAppLogs = async ({
     }, retryIntervalMs)
     // eslint-disable-next-line no-catch-all/no-catch-all
   } catch (error) {
-    outputWarn(`Error while polling app logs.`)
-    outputWarn(`Retrying in ${POLLING_ERROR_RETRY_INTERVAL_MS / 1000} seconds.`)
+    outputWarn(`Error while polling app logs.`, stdout)
+    outputWarn(`Retrying in ${POLLING_ERROR_RETRY_INTERVAL_MS / 1000} seconds.`, stdout)
     outputDebug(`${error as string}}\n`)
 
     setTimeout(() => {

packages/app/src/cli/services/app-logs/utils.ts

@@ -14,6 +14,8 @@ import {outputDebug, outputWarn} from '@shopify/cli-kit/node/output'
 import {AbortError} from '@shopify/cli-kit/node/error'
 import camelcaseKeys from 'camelcase-keys'
 import {formatLocalDate} from '@shopify/cli-kit/common/string'
+import {useConcurrentOutputContext} from '@shopify/cli-kit/node/ui/components'
+import {Writable} from 'stream'
 
 export const POLLING_INTERVAL_MS = 450
 export const POLLING_ERROR_RETRY_INTERVAL_MS = 5 * 1000
@@ -193,6 +195,7 @@ export const subscribeToAppLogs = async (
   developerPlatformClient: DeveloperPlatformClient,
   variables: AppLogsSubscribeMutationVariables,
   organizationId: string,
+  stdout?: Writable,
 ): Promise<string> => {
   // Now try the subscription with the fresh token
   const result = await developerPlatformClient.subscribeToAppLogs(variables, organizationId)
@@ -208,8 +211,10 @@ export const subscribeToAppLogs = async (
 
   if (errors && errors.length > 0) {
     const errorOutput = errors.join(', ')
-    outputWarn(`Errors subscribing to app logs: ${errorOutput}`)
-    outputWarn('App log streaming is not available in this session.')
+    await useConcurrentOutputContext({stripAnsi: false}, () => {
+      outputWarn(`Errors subscribing to app logs: ${errorOutput}`, stdout)
+      outputWarn('App log streaming is not available in this session.', stdout)
+    })
     throw new AbortError(errorOutput)
   } else {
     if (!jwtToken) {

packages/app/src/cli/services/dev/processes/app-logs-polling.test.ts

@@ -142,6 +142,7 @@ describe('app-logs-polling', () => {
         developerPlatformClient,
         appLogsSubscribeVariables,
         'organizationId',
+        stdout,
       )
       expect(createLogsDir).toHaveBeenCalledWith(API_KEY)
       expect(pollAppLogs).toHaveBeenCalledOnce()
@@ -191,6 +192,7 @@ describe('app-logs-polling', () => {
         developerPlatformClient,
         appLogsSubscribeVariables,
         'organizationId',
+        stdout,
       )
       expect(outputDebug).toHaveBeenCalledWith('Failed to start function logs: Error: uh oh, another error', stderr)
       expect(pollAppLogs).not.toHaveBeenCalled()

packages/app/src/cli/services/dev/processes/app-logs-polling.ts

@@ -69,7 +69,12 @@ export const subscribeAndStartPolling: DevProcessFunction<SubscribeAndStartPolli
   {developerPlatformClient, appLogsSubscribeVariables, storeName, organizationId, appWatcher, localApp: _localApp},
 ) => {
   async function startPolling(abortSignal?: AbortSignal) {
-    const jwtToken = await subscribeToAppLogs(developerPlatformClient, appLogsSubscribeVariables, organizationId)
+    const jwtToken = await subscribeToAppLogs(
+      developerPlatformClient,
+      appLogsSubscribeVariables,
+      organizationId,
+      stdout,
+    )
 
     const apiKey = appLogsSubscribeVariables.apiKey
     await createLogsDir(apiKey)