Merge pull request #4255 from Shopify/lopert.newline-logs

split log newlines into array

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

@@ -1,10 +1,12 @@
 import {pollAppLogs} from './poll-app-logs.js'
 import {writeAppLogsToFile} from './write-app-logs.js'
+import {FunctionRunLog} from '../types.js'
 import {partnersFqdn} from '@shopify/cli-kit/node/context/fqdn'
 import {describe, expect, test, vi, beforeEach, afterEach} from 'vitest'
 import {fetch} from '@shopify/cli-kit/node/http'
 import * as components from '@shopify/cli-kit/node/ui/components'
 import * as output from '@shopify/cli-kit/node/output'
+import camelcaseKeys from 'camelcase-keys'
 
 const JWT_TOKEN = 'jwtToken'
 const API_KEY = 'apiKey'
@@ -264,18 +266,28 @@ describe('pollAppLogs', () => {
       },
     })
 
+    const appLogPayloadZero = new FunctionRunLog(
+      camelcaseKeys(JSON.parse(RESPONSE_DATA.app_logs[0]!.payload), {deep: true}),
+    )
     expect(writeAppLogsToFile).toHaveBeenCalledWith({
       appLog: RESPONSE_DATA.app_logs[0],
+      appLogPayload: appLogPayloadZero,
       apiKey: API_KEY,
       stdout,
     })
+
+    const appLogPayloadOne = new FunctionRunLog(
+      camelcaseKeys(JSON.parse(RESPONSE_DATA.app_logs[1]!.payload), {deep: true}),
+    )
     expect(writeAppLogsToFile).toHaveBeenCalledWith({
       appLog: RESPONSE_DATA.app_logs[1],
+      appLogPayload: appLogPayloadOne,
       apiKey: API_KEY,
       stdout,
     })
     expect(writeAppLogsToFile).toHaveBeenCalledWith({
       appLog: RESPONSE_DATA.app_logs[2],
+      appLogPayload: JSON.parse(RESPONSE_DATA.app_logs[2]!.payload),
       apiKey: API_KEY,
       stdout,
     })
@@ -396,4 +408,43 @@ describe('pollAppLogs', () => {
     expect(outputWarnSpy).toHaveBeenCalledWith('Error while polling app logs.')
     expect(vi.getTimerCount()).toEqual(1)
   })
+
+  test('displays error message, waits, and retries if response contained bad JSON', async () => {
+    // Given
+    const outputDebugSpy = vi.spyOn(output, 'outputDebug')
+    const outputWarnSpy = vi.spyOn(output, 'outputWarn')
+
+    const badFunctionLogPayload = 'invalid json'
+    const responseDataWithBadJson = {
+      app_logs: [
+        {
+          shop_id: 1,
+          api_client_id: 1830457,
+          payload: badFunctionLogPayload,
+          log_type: FUNCTION_RUN,
+          cursor: '2024-05-23T19:17:02.321773Z',
+          status: 'success',
+          source: SOURCE,
+          source_namespace: 'extensions',
+          log_timestamp: '2024-05-23T19:17:00.240053Z',
+        },
+      ],
+    }
+    const mockedFetch = vi.fn().mockResolvedValueOnce(Response.json(responseDataWithBadJson))
+    vi.mocked(fetch).mockImplementation(mockedFetch)
+
+    // When
+    await pollAppLogs({
+      stdout,
+      appLogsFetchInput: {jwtToken: JWT_TOKEN},
+      apiKey: API_KEY,
+      resubscribeCallback: MOCKED_RESUBSCRIBE_CALLBACK,
+    })
+
+    // When/Then
+    await expect(writeAppLogsToFile).not.toHaveBeenCalled
+    expect(outputWarnSpy).toHaveBeenCalledWith('Error while polling app logs.')
+    expect(outputWarnSpy).toHaveBeenCalledWith('Retrying in 5 seconds.')
+    expect(outputDebugSpy).toHaveBeenCalledWith(expect.stringContaining('JSON'))
+  })
 })

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

@@ -13,9 +13,10 @@ import {
   REQUEST_EXECUTION_IN_BACKGROUND_CACHE_ABOUT_TO_EXPIRE_REASON,
   handleFetchAppLogsError,
 } from '../utils.js'
-import {AppLogData, ErrorResponse} from '../types.js'
+import {AppLogData, ErrorResponse, FunctionRunLog} from '../types.js'
 import {outputContent, outputDebug, outputToken, outputWarn} from '@shopify/cli-kit/node/output'
 import {useConcurrentOutputContext} from '@shopify/cli-kit/node/ui/components'
+import camelcaseKeys from 'camelcase-keys'
 import {Writable} from 'stream'
 
 export const pollAppLogs = async ({
@@ -74,12 +75,12 @@ export const pollAppLogs = async ({
       const {app_logs: appLogs} = data
 
       for (const log of appLogs) {
-        const payload = JSON.parse(log.payload)
-
+        let payload = JSON.parse(log.payload)
         // eslint-disable-next-line no-await-in-loop
         await useConcurrentOutputContext({outputPrefix: log.source, stripAnsi: false}, async () => {
           if (log.log_type === LOG_TYPE_FUNCTION_RUN) {
             handleFunctionRunLog(log, payload, stdout)
+            payload = new FunctionRunLog(camelcaseKeys(payload, {deep: true}))
           } else if (log.log_type.startsWith(LOG_TYPE_FUNCTION_NETWORK_ACCESS)) {
             handleFunctionNetworkAccessLog(log, payload, stdout)
           } else {
@@ -88,6 +89,7 @@ export const pollAppLogs = async ({
 
           const logFile = await writeAppLogsToFile({
             appLog: log,
+            appLogPayload: payload,
             apiKey,
             stdout,
           })

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

@@ -1,5 +1,5 @@
 import {writeAppLogsToFile} from './write-app-logs.js'
-import {AppLogData} from '../types.js'
+import {AppLogData, AppLogPayload, FunctionRunLog} from '../types.js'
 import {joinPath} from '@shopify/cli-kit/node/path'
 import {writeLog} from '@shopify/cli-kit/node/logs'
 import {describe, expect, test, vi, beforeEach} from 'vitest'
@@ -10,14 +10,28 @@ vi.mock('@shopify/cli-kit/node/logs')
 const APP_LOG: AppLogData = {
   shop_id: 1,
   api_client_id: 2,
-  payload: JSON.stringify({someJson: 'someJSOn'}),
+  payload: JSON.stringify({someJson: 'someJSOn', logs: 'Line 1!\n Line2!\n'}),
   log_type: 'function_run',
   cursor: '2024-05-22T15:06:43.841156Z',
   status: 'success',
   source: 'my-function',
   source_namespace: 'extensions',
   log_timestamp: '2024-05-22T15:06:41.827379Z',
 }
+
+const NEW_APP_LOG: AppLogData = {
+  shop_id: 1,
+  api_client_id: 2,
+  payload: JSON.stringify({someJson: 'someJSOn'}),
+  log_type: 'new_app_log_type',
+  cursor: '2024-05-22T15:06:43.841156Z',
+  status: 'success',
+  source: 'my-function',
+  source_namespace: 'extensions',
+  log_timestamp: '2024-05-22T15:06:41.827379Z',
+}
+
+const FUNCTION_RUN_PAYLOAD = new FunctionRunLog(camelcaseKeys(JSON.parse(APP_LOG.payload)))
 const API_KEY = 'apiKey'
 
 describe('writeAppLogsToFile', () => {
@@ -27,40 +41,71 @@ describe('writeAppLogsToFile', () => {
     stdout = {write: vi.fn()}
   })
 
-  test('calls writeLog with the right data', async () => {
+  test('calls writeLog with the FunctionRunLog payload type', async () => {
     // Given
     // determine the fileName and path
     const fileName = `20240522_150641_827Z_${APP_LOG.source_namespace}_${APP_LOG.source}`
     const path = joinPath(API_KEY, fileName)
 
     // When
-    const returnedPath = await writeAppLogsToFile({appLog: APP_LOG, apiKey: API_KEY, stdout})
+    const returnedPath = await writeAppLogsToFile({
+      appLog: APP_LOG,
+      appLogPayload: FUNCTION_RUN_PAYLOAD,
+      apiKey: API_KEY,
+      stdout,
+    })
 
     // Then
+    const expectedSaveData = {
+      shopId: APP_LOG.shop_id,
+      apiClientId: APP_LOG.api_client_id,
+      payload: {
+        logs: ['Line 1!', ' Line2!'],
+      },
+      logType: APP_LOG.log_type,
+      cursor: APP_LOG.cursor,
+      status: APP_LOG.status,
+      source: APP_LOG.source,
+      sourceNamespace: APP_LOG.source_namespace,
+      logTimestamp: APP_LOG.log_timestamp,
+    }
+    const expectedLogData = JSON.stringify(expectedSaveData, null, 2)
+
     expect(returnedPath.fullOutputPath.startsWith(path)).toBe(true)
-    expect(writeLog).toHaveBeenCalledWith(expect.stringContaining(path), expectedLogDataFromAppEvent(APP_LOG))
+    expect(writeLog).toHaveBeenCalledWith(expect.stringContaining(path), expectedLogData)
   })
 
-  test('prints and re-throws parsing errors', async () => {
+  test('calls writeLog with strings when no matching payload type', async () => {
     // Given
-    const appLog = {
-      ...APP_LOG,
-      payload: 'invalid JSON',
-    }
+    // determine the fileName and path
+    const fileName = `20240522_150641_827Z_${APP_LOG.source_namespace}_${APP_LOG.source}`
+    const path = joinPath(API_KEY, fileName)
 
-    // When/Then
-    await expect(writeAppLogsToFile({appLog, apiKey: API_KEY, stdout})).rejects.toThrow()
-    expect(stdout.write).toHaveBeenCalledWith(expect.stringContaining('Error while writing log to file: '))
+    // When
+    const returnedPath = await writeAppLogsToFile({
+      appLog: NEW_APP_LOG,
+      appLogPayload: JSON.parse(NEW_APP_LOG.payload),
+      apiKey: API_KEY,
+      stdout,
+    })
+
+    // Then
+    expect(returnedPath.fullOutputPath.startsWith(path)).toBe(true)
+    expect(writeLog).toHaveBeenCalledWith(
+      expect.stringContaining(path),
+      expectedLogDataFromAppEvent(NEW_APP_LOG, JSON.parse(NEW_APP_LOG.payload)),
+    )
   })
 })
 
-function expectedLogDataFromAppEvent(event: AppLogData): string {
-  const data = camelcaseKeys(
+function expectedLogDataFromAppEvent(event: AppLogData, payload: AppLogPayload | any): string {
+  const data: any = camelcaseKeys(
     {
       ...event,
-      payload: JSON.parse(event.payload),
+      payload,
     },
     {deep: true},
   )
+
   return JSON.stringify(data, null, 2)
 }

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

@@ -1,4 +1,4 @@
-import {AppLogData} from '../types.js'
+import {AppLogData, AppLogPayload, FunctionRunLog} from '../types.js'
 import {joinPath} from '@shopify/cli-kit/node/path'
 import {writeLog, getLogsDir} from '@shopify/cli-kit/node/logs'
 import {randomUUID} from '@shopify/cli-kit/node/crypto'
@@ -12,10 +12,13 @@ interface AppLogFile {
 
 export const writeAppLogsToFile = async ({
   appLog,
+  appLogPayload,
   apiKey,
   stdout,
 }: {
   appLog: AppLogData
+  // eslint-disable-next-line @typescript-eslint/no-explicit-any
+  appLogPayload: AppLogPayload | any
   apiKey: string
   stdout: Writable
 }): Promise<AppLogFile> => {
@@ -27,14 +30,19 @@ export const writeAppLogsToFile = async ({
   const fullOutputPath = joinPath(getLogsDir(), path)
 
   try {
-    const toSaveData = camelcaseKeys(
+    // eslint-disable-next-line @typescript-eslint/no-explicit-any
+    const toSaveData: any = camelcaseKeys(
       {
         ...appLog,
-        payload: JSON.parse(appLog.payload),
+        payload: appLogPayload,
       },
       {deep: true},
     )
 
+    if (appLogPayload instanceof FunctionRunLog) {
+      toSaveData.payload.logs = appLogPayload.logs.split('\n').filter(Boolean)
+    }
+
     const logData = JSON.stringify(toSaveData, null, 2)
 
     await writeLog(path, logData)