diff --git a/CHANGELOG.md b/CHANGELOG.md index 6a8dd397bd..461de76440 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -9,6 +9,7 @@ This is the log of notable changes to EAS CLI and related packages. ### 🎉 New features - [eas-cli] Update workflow run logs in real time, instead of every 10 seconds. ([#4228](https://github.com/expo/eas-cli/pull/4228) by [@AHGIJMKLKKZNPJKQR](https://github.com/AHGIJMKLKKZNPJKQR)) +- [eas-cli] Display logs in `eas build --wait`. ([#4303](https://github.com/expo/eas-cli/pull/4303) by [@AHGIJMKLKKZNPJKQR](https://github.com/AHGIJMKLKKZNPJKQR)) ### 🐛 Bug fixes diff --git a/packages/eas-cli/src/__tests__/commands/workflow-logs-test.ts b/packages/eas-cli/src/__tests__/commands/workflow-logs-test.ts index b5e167c5c8..3427051c21 100644 --- a/packages/eas-cli/src/__tests__/commands/workflow-logs-test.ts +++ b/packages/eas-cli/src/__tests__/commands/workflow-logs-test.ts @@ -8,7 +8,7 @@ import { mockProjectId, mockTestCommand, } from './utils'; -import { fetchRawLogsForJobAsync } from '../../commandUtils/workflow/logs/fetchLogs'; +import { fetchRawLogsForJobAsync } from '../../commandUtils/workflow/fetchLogs'; import WorkflowLogView from '../../commands/workflow/logs'; import { AppPlatform, BuildPriority, BuildStatus } from '../../graphql/generated'; import { AppQuery } from '../../graphql/queries/AppQuery'; @@ -35,7 +35,7 @@ jest.mock('fs'); jest.mock('../../log'); jest.mock('../../prompts'); jest.mock('../../utils/json'); -jest.mock('../../commandUtils/workflow/logs/fetchLogs'); +jest.mock('../../commandUtils/workflow/fetchLogs'); describe(WorkflowLogView, () => { beforeEach(() => { diff --git a/packages/eas-cli/src/build/__tests__/logs-test.ts b/packages/eas-cli/src/build/__tests__/logs-test.ts new file mode 100644 index 0000000000..e2ef092b52 --- /dev/null +++ b/packages/eas-cli/src/build/__tests__/logs-test.ts @@ -0,0 +1,234 @@ +import { BuildPhase } from '@expo/eas-build-job'; +import { v4 as uuid } from 'uuid'; + +import { groupLogLinesIntoSteps } from '../../commandUtils/logs/parseLogs'; +import { JobLogs, RawLogLine } from '../../commandUtils/logs/types'; +import { + AppPlatform, + BuildFragment, + BuildPriority, + BuildStatus, + RealtimeLogsTargetType, +} from '../../graphql/generated'; +import { + formatActiveBuildText, + formatActiveBuildsText, + isBuildCompleted, + logSourceForBuild, +} from '../logs'; + +function createBuildFragment(overrides: Partial = {}): BuildFragment { + return { + id: 'build-id', + createdAt: new Date().toISOString(), + updatedAt: new Date().toISOString(), + platform: AppPlatform.Android, + logFiles: [], + priority: BuildPriority.Normal, + app: { + __typename: 'App', + slug: 'test-project', + id: uuid(), + name: 'test-project', + ownerAccount: { + __typename: 'Account', + id: uuid(), + name: 'test-account', + }, + }, + status: BuildStatus.InProgress, + isForIosSimulator: false, + ...overrides, + }; +} + +function phaseLines(phase: string, count: number): RawLogLine[] { + return Array.from({ length: count }, (_, index) => ({ phase, msg: `line${index}` })); +} + +function logsForPhase(phase: string, count: number): JobLogs { + return groupLogLinesIntoSteps(phaseLines(phase, count)); +} + +describe(logSourceForBuild, () => { + it('keys the source by the build id', () => { + expect(logSourceForBuild(createBuildFragment({ id: 'some-build-id' })).key).toBe( + 'some-build-id' + ); + }); + + it('targets the build itself for realtime logs', () => { + expect(logSourceForBuild(createBuildFragment({ id: 'some-build-id' })).realtimeTarget).toEqual({ + type: RealtimeLogsTargetType.Build, + id: 'some-build-id', + }); + }); + + it('is in progress only while the build is in progress', () => { + expect( + logSourceForBuild(createBuildFragment({ status: BuildStatus.InProgress })).isInProgress + ).toBe(true); + for (const status of [ + BuildStatus.New, + BuildStatus.InQueue, + BuildStatus.PendingCancel, + BuildStatus.Canceled, + BuildStatus.Errored, + BuildStatus.Finished, + ]) { + expect(logSourceForBuild(createBuildFragment({ status })).isInProgress).toBe(false); + } + }); + + describe('fetchRawLogLinesAsync', () => { + const originalFetch = global.fetch; + + afterEach(() => { + global.fetch = originalFetch; + }); + + it('parses the first log file of the build', async () => { + const fetchMock = jest.fn().mockResolvedValue({ + text: async () => + [ + '{"logId":"1","phase":"INSTALL_DEPENDENCIES","msg":"npm ci"}', + '{"logId":"2","phase":"INSTALL_DEPENDENCIES","msg":"done"}', + ].join('\n'), + }); + global.fetch = fetchMock as unknown as typeof global.fetch; + + const source = logSourceForBuild( + createBuildFragment({ logFiles: ['https://logs.test/first', 'https://logs.test/second'] }) + ); + + await expect(source.fetchRawLogLinesAsync()).resolves.toEqual([ + { logId: '1', phase: 'INSTALL_DEPENDENCIES', msg: 'npm ci' }, + { logId: '2', phase: 'INSTALL_DEPENDENCIES', msg: 'done' }, + ]); + expect(fetchMock).toHaveBeenCalledTimes(1); + expect(fetchMock).toHaveBeenCalledWith('https://logs.test/first'); + }); + + it('returns null when the build has no log file', async () => { + const fetchMock = jest.fn(); + global.fetch = fetchMock as unknown as typeof global.fetch; + + await expect( + logSourceForBuild(createBuildFragment({ logFiles: [] })).fetchRawLogLinesAsync() + ).resolves.toBeNull(); + expect(fetchMock).not.toHaveBeenCalled(); + }); + }); +}); + +describe(isBuildCompleted, () => { + it('reports FINISHED as completed', () => { + expect(isBuildCompleted(BuildStatus.Finished)).toBe(true); + }); + + it('reports ERRORED as completed', () => { + expect(isBuildCompleted(BuildStatus.Errored)).toBe(true); + }); + + it('reports CANCELED as completed', () => { + expect(isBuildCompleted(BuildStatus.Canceled)).toBe(true); + }); + + it('reports NEW as not completed', () => { + expect(isBuildCompleted(BuildStatus.New)).toBe(false); + }); + + it('reports IN_QUEUE as not completed', () => { + expect(isBuildCompleted(BuildStatus.InQueue)).toBe(false); + }); + + it('reports IN_PROGRESS as not completed', () => { + expect(isBuildCompleted(BuildStatus.InProgress)).toBe(false); + }); + + it('reports PENDING_CANCEL as not completed', () => { + expect(isBuildCompleted(BuildStatus.PendingCancel)).toBe(false); + }); +}); + +describe(formatActiveBuildText, () => { + it('returns the base text alone when there are no logs', () => { + expect(formatActiveBuildText('Build in progress...', new Map())).toBe('Build in progress...'); + }); + + it('shows the display name of a raw build phase', () => { + const output = formatActiveBuildText( + 'Build in progress...', + logsForPhase(BuildPhase.INSTALL_DEPENDENCIES, 1) + ); + + expect(output).toContain('Current phase'); + expect(output).toContain('Install dependencies'); + expect(output).not.toContain('INSTALL_DEPENDENCIES'); + }); + + it('passes a build step display name through untouched', () => { + const output = formatActiveBuildText( + 'Build in progress...', + groupLogLinesIntoSteps([ + { buildStepId: 'step-id-1', buildStepDisplayName: 'Run fastlane build', msg: 'line0' }, + ]) + ); + + expect(output).toContain('Run fastlane build'); + expect(output).not.toContain('step-id-1'); + }); + + it('keeps the base text and five trailing log lines', () => { + const output = formatActiveBuildText( + 'Build in progress...', + logsForPhase(BuildPhase.RUN_GRADLEW, 10) + ); + + expect(output.startsWith('Build in progress...\n')).toBe(true); + expect(output).toContain('line5'); + expect(output).toContain('line9'); + expect(output).not.toContain('line4'); + }); +}); + +describe(formatActiveBuildsText, () => { + it('returns the base text alone when no build has logs', () => { + expect( + formatActiveBuildsText('Waiting for builds to complete.', [ + { build: createBuildFragment(), logs: new Map() }, + ]) + ).toBe('Waiting for builds to complete.'); + }); + + it('labels each build with its platform emoji and display name', () => { + const output = formatActiveBuildsText('Waiting for builds to complete.', [ + { + build: createBuildFragment({ id: 'android-build', platform: AppPlatform.Android }), + logs: logsForPhase(BuildPhase.RUN_GRADLEW, 1), + }, + { + build: createBuildFragment({ id: 'ios-build', platform: AppPlatform.Ios }), + logs: logsForPhase(BuildPhase.RUN_FASTLANE, 1), + }, + ]); + + expect(output).toContain('🤖 Android'); + expect(output).toContain('Run gradlew'); + expect(output).toContain('🍏 iOS'); + expect(output).toContain('Run fastlane'); + }); + + it('keeps three trailing log lines per build', () => { + const output = formatActiveBuildsText('Waiting for builds to complete.', [ + { + build: createBuildFragment({ id: 'android-build', platform: AppPlatform.Android }), + logs: logsForPhase(BuildPhase.RUN_GRADLEW, 10), + }, + ]); + + expect(output).toContain('line7'); + expect(output).toContain('line9'); + expect(output).not.toContain('line6'); + }); +}); diff --git a/packages/eas-cli/src/build/__tests__/waitForBuildEndAsync-test.ts b/packages/eas-cli/src/build/__tests__/waitForBuildEndAsync-test.ts new file mode 100644 index 0000000000..90accc38c3 --- /dev/null +++ b/packages/eas-cli/src/build/__tests__/waitForBuildEndAsync-test.ts @@ -0,0 +1,163 @@ +import { BuildPhase } from '@expo/eas-build-job'; +import { v4 as uuid } from 'uuid'; + +import { ExpoGraphqlClient } from '../../commandUtils/context/contextUtils/createGraphqlClient'; +import { LogsState } from '../../commandUtils/logs/state'; +import { groupLogLinesIntoSteps } from '../../commandUtils/logs/parseLogs'; +import { JobLogs } from '../../commandUtils/logs/types'; +import { LogsWatcher } from '../../commandUtils/logs/watcher'; +import { + AppPlatform, + BuildFragment, + BuildPriority, + BuildStatus, +} from '../../graphql/generated'; +import { BuildQuery } from '../../graphql/queries/BuildQuery'; +import { Ora, isSpinnerEnabled, ora } from '../../ora'; +import { createRealtimeLogsClient } from '../../utils/centrifuge'; +import { sleepAsync } from '../../utils/promise'; +import { waitForBuildEndAsync } from '../build'; + +jest.mock('../../ora', () => ({ + ...jest.requireActual('../../ora'), + ora: jest.fn(), + isSpinnerEnabled: jest.fn(), +})); +jest.mock('../../commandUtils/logs/watcher', () => ({ + LogsWatcher: jest.fn(), +})); +jest.mock('../../utils/centrifuge', () => ({ + createRealtimeLogsClient: jest.fn(), +})); +jest.mock('../../graphql/queries/BuildQuery', () => ({ + BuildQuery: { + byIdAsync: jest.fn(), + }, +})); +jest.mock('../../utils/promise', () => ({ + ...jest.requireActual('../../utils/promise'), + sleepAsync: jest.fn(), +})); + +const graphqlClient = {} as unknown as ExpoGraphqlClient; + +function createBuildFragment(status: BuildStatus): BuildFragment { + return { + id: 'build-id', + createdAt: new Date().toISOString(), + updatedAt: new Date().toISOString(), + platform: AppPlatform.Android, + logFiles: [], + priority: BuildPriority.Normal, + app: { + __typename: 'App', + slug: 'test-project', + id: uuid(), + name: 'test-project', + ownerAccount: { + __typename: 'Account', + id: uuid(), + name: 'test-account', + }, + }, + status, + isForIosSimulator: false, + }; +} + +function createSpinner(): Ora { + const spinner: Record = { + text: '', + prefixText: '', + isSpinning: true, + start: jest.fn(() => spinner), + stop: jest.fn(() => spinner), + stopAndPersist: jest.fn(() => spinner), + succeed: jest.fn(() => spinner), + fail: jest.fn(() => spinner), + warn: jest.fn(() => spinner), + }; + return spinner as unknown as Ora; +} + +function setBuildStatuses(statuses: BuildStatus[]): void { + const mocked = jest.mocked(BuildQuery.byIdAsync); + for (const status of statuses) { + mocked.mockResolvedValueOnce(createBuildFragment(status)); + } +} + +describe(waitForBuildEndAsync, () => { + let spinner: Ora; + let publish: () => void; + let watcherClose: jest.Mock; + let logs: JobLogs; + + beforeEach(() => { + jest.clearAllMocks(); + spinner = createSpinner(); + logs = new Map(); + publish = () => {}; + watcherClose = jest.fn(); + + jest.mocked(ora).mockReturnValue(spinner); + jest.mocked(LogsWatcher).mockImplementation((( + _createRealtimeLogsClient: unknown, + onRealtimeLogs: () => void + ) => { + publish = onRealtimeLogs; + return { + syncAsync: jest.fn(async () => + new Map([ + ['build-id', { getLogs: () => logs, markCompleted: jest.fn() } as unknown as LogsState], + ]) + ), + close: watcherClose, + }; + }) as unknown as () => LogsWatcher); + jest.mocked(sleepAsync).mockImplementation(async () => { + publish(); + }); + }); + + it('does not create a watcher when the spinner is disabled', async () => { + jest.mocked(isSpinnerEnabled).mockReturnValue(false); + setBuildStatuses([BuildStatus.Finished]); + + await waitForBuildEndAsync(graphqlClient, { buildIds: ['build-id'], accountName: 'acct' }); + + expect(LogsWatcher).not.toHaveBeenCalled(); + expect(createRealtimeLogsClient).not.toHaveBeenCalled(); + }); + + it('renders the current phase and its log tail on publication while in progress', async () => { + jest.mocked(isSpinnerEnabled).mockReturnValue(true); + setBuildStatuses([BuildStatus.InProgress, BuildStatus.Finished]); + jest.mocked(sleepAsync).mockImplementationOnce(async () => { + logs = groupLogLinesIntoSteps([ + { phase: BuildPhase.INSTALL_DEPENDENCIES, msg: 'npm ci' }, + { phase: BuildPhase.INSTALL_DEPENDENCIES, msg: 'added 1 package' }, + ]); + publish(); + }); + + await waitForBuildEndAsync(graphqlClient, { buildIds: ['build-id'], accountName: 'acct' }); + + expect(LogsWatcher).toHaveBeenCalledTimes(1); + expect(spinner.text).toContain('Build in progress...'); + expect(spinner.text).toContain('Install dependencies'); + expect(spinner.text).toContain('added 1 package'); + expect(watcherClose).toHaveBeenCalledTimes(1); + }); + + it('ignores a publication that arrives while the build is queued', async () => { + jest.mocked(isSpinnerEnabled).mockReturnValue(true); + setBuildStatuses([BuildStatus.InProgress, BuildStatus.InQueue, BuildStatus.Finished]); + logs = groupLogLinesIntoSteps([{ phase: BuildPhase.INSTALL_DEPENDENCIES, msg: 'npm ci' }]); + + await waitForBuildEndAsync(graphqlClient, { buildIds: ['build-id'], accountName: 'acct' }); + + expect(jest.mocked(sleepAsync).mock.calls.length).toBe(2); + expect(spinner.text).toBe('Build queued...'); + }); +}); diff --git a/packages/eas-cli/src/build/build.ts b/packages/eas-cli/src/build/build.ts index d3d0677c78..d35b53b460 100644 --- a/packages/eas-cli/src/build/build.ts +++ b/packages/eas-cli/src/build/build.ts @@ -30,6 +30,12 @@ import { } from './errors'; import { transformMetadata } from './graphql'; import { LocalBuildMode, runLocalBuildAsync } from './local'; +import { + formatActiveBuildText, + formatActiveBuildsText, + isBuildCompleted, + logSourceForBuild, +} from './logs'; import { collectMetadataAsync } from './metadata'; import { printDeprecationWarnings } from './utils/printBuildInfo'; import { @@ -46,6 +52,8 @@ import { getExpoWebsiteBaseUrl } from '../api'; import { formatStarterSubscribeCommand } from '../billing/plans'; import { ExpoGraphqlClient } from '../commandUtils/context/contextUtils/createGraphqlClient'; import { EasCommandError } from '../commandUtils/errors'; +import { LogsState } from '../commandUtils/logs/state'; +import { LogsWatcher } from '../commandUtils/logs/watcher'; import { createFingerprintAsync } from '../fingerprint/cli'; import { AppPlatform, @@ -60,7 +68,7 @@ import { import { BuildMutation, BuildResult } from '../graphql/mutations/BuildMutation'; import { BuildQuery } from '../graphql/queries/BuildQuery'; import Log, { learnMore, link } from '../log'; -import { Ora, ora } from '../ora'; +import { Ora, isSpinnerEnabled, ora, updateSpinnerText } from '../ora'; import { RequestedPlatform, appPlatformDisplayNames, @@ -70,6 +78,7 @@ import { import { maybeUploadFingerprintAsync } from '../project/maybeUploadFingerprintAsync'; import { resolveRuntimeVersionAsync } from '../project/resolveRuntimeVersionAsync'; import { uploadFileAtPathToGCSAsync } from '../uploads'; +import { createRealtimeLogsClient } from '../utils/centrifuge'; import { formatBytes } from '../utils/files'; import { printJsonOnlyOutput } from '../utils/json'; import { createProgressTracker } from '../utils/progress'; @@ -538,17 +547,62 @@ export async function waitForBuildEndAsync( originalSpinnerText = 'Waiting for builds to complete. You can press Ctrl+C to exit.'; spinner = ora('Waiting for builds to complete. You can press Ctrl+C to exit.').start(); } - while (true) { - const builds = await getBuildsSafelyAsync(graphqlClient, buildIds); - const { refetch } = - builds.length === 1 - ? await handleSingleBuildProgressAsync({ build: builds[0], accountName }, { spinner }) - : await handleMultipleBuildsProgressAsync({ builds }, { spinner, originalSpinnerText }); - if (!refetch) { - return builds; + let render = (): void => {}; + const watcher = isSpinnerEnabled() + ? new LogsWatcher( + () => createRealtimeLogsClient(graphqlClient), + () => { + render(); + } + ) + : null; + + try { + while (true) { + render = (): void => {}; + const builds = await getBuildsSafelyAsync(graphqlClient, buildIds); + const logsStates = await syncBuildLogsAsync(watcher, builds); + const installRender = (nextRender: () => void): void => { + render = nextRender; + }; + const { refetch } = + builds.length === 1 + ? await handleSingleBuildProgressAsync( + { build: builds[0], accountName }, + { spinner, logsStates, installRender } + ) + : await handleMultipleBuildsProgressAsync( + { builds }, + { spinner, originalSpinnerText, logsStates, installRender } + ); + if (!refetch) { + return builds; + } + await sleepAsync(intervalSec * 1000); + } + } finally { + watcher?.close(); + } +} + +async function syncBuildLogsAsync( + watcher: LogsWatcher | null, + builds: MaybeBuildFragment[] +): Promise> { + if (!watcher) { + return new Map(); + } + const existingBuilds = builds.filter(isBuildFragment); + const logsStates = await watcher.syncAsync(existingBuilds.map(build => logSourceForBuild(build))); + for (const build of existingBuilds) { + if (isBuildCompleted(build.status)) { + nullthrows( + logsStates.get(build.id), + 'syncAsync must have been called before markCompleted' + ).markCompleted(); } - await sleepAsync(intervalSec * 1000); } + return logsStates; } async function getBuildsSafelyAsync( @@ -570,6 +624,11 @@ interface BuildProgressResult { refetch: boolean; } +type BuildLogsProgressOptions = { + logsStates: Map; + installRender: (render: () => void) => void; +}; + let queueProgressBarStarted = false; const queueProgressBar = new cliProgress.SingleBar( { format: '|{bar}| {estimatedWaitTime}' }, @@ -587,10 +646,12 @@ async function handleSingleBuildProgressAsync( build: MaybeBuildFragment; accountName: string; }, - { spinner }: { spinner: Ora } + { spinner, logsStates, installRender }: { spinner: Ora } & BuildLogsProgressOptions ): Promise { if (build === null) { - spinner.text = 'Could not fetch the build status. Check your network connection.'; + updateSpinnerText(spinner, { + text: 'Could not fetch the build status. Check your network connection.', + }); return { refetch: true }; } @@ -615,16 +676,18 @@ async function handleSingleBuildProgressAsync( statusNewSetAt ??= now; const newStatusDurationMs = now - statusNewSetAt; if (newStatusDurationMs < NEW_STATUS_GRACE_PERIOD_MS) { - spinner.text = 'Waiting for build to get enqueued…'; + updateSpinnerText(spinner, { text: 'Waiting for build to get enqueued…' }); } else { - spinner.text = `Build concurrency limit reached for your account. Build will enter queue once a concurrency becomes available. Add additional concurrencies at ${link( - formatAccountBillingUrl(accountName) - )}.`; + updateSpinnerText(spinner, { + text: `Build concurrency limit reached for your account. Build will enter queue once a concurrency becomes available. Add additional concurrencies at ${link( + formatAccountBillingUrl(accountName) + )}.`, + }); } break; } case BuildStatus.InQueue: { - spinner.text = 'Build queued...'; + updateSpinnerText(spinner, { text: 'Build queued...' }); const progressBarPayload = typeof build.estimatedWaitTimeLeftSeconds === 'number' ? { estimatedWaitTime: formatEstimatedWaitTime(build.estimatedWaitTimeLeftSeconds) } @@ -661,9 +724,17 @@ async function handleSingleBuildProgressAsync( case BuildStatus.Canceled: spinner.fail('Build canceled'); return { refetch: false }; - case BuildStatus.InProgress: - spinner.text = 'Build in progress...'; + case BuildStatus.InProgress: { + const logsState = logsStates.get(build.id); + const render = (): void => { + updateSpinnerText(spinner, { + text: formatActiveBuildText('Build in progress...', logsState?.getLogs() ?? new Map()), + }); + }; + installRender(render); + render(); break; + } case BuildStatus.Errored: spinner.fail('Build failed'); if (build.error) { @@ -698,7 +769,12 @@ const platforms = [AppPlatform.Android, AppPlatform.Ios]; async function handleMultipleBuildsProgressAsync( { builds: maybeBuilds }: { builds: MaybeBuildFragment[] }, - { spinner, originalSpinnerText }: { spinner: Ora; originalSpinnerText: string } + { + spinner, + originalSpinnerText, + logsStates, + installRender, + }: { spinner: Ora; originalSpinnerText: string } & BuildLogsProgressOptions ): Promise { const buildCount = maybeBuilds.length; const builds = maybeBuilds.filter(isBuildFragment); @@ -732,7 +808,24 @@ async function handleMultipleBuildsProgressAsync( someNew && statusNewSetAt !== null && Date.now() - statusNewSetAt >= NEW_STATUS_GRACE_PERIOD_MS; - spinner.text = formatPendingBuildsText(originalSpinnerText, builds, showConcurrencyWarning); + const pendingBuildsText = formatPendingBuildsText( + originalSpinnerText, + builds, + showConcurrencyWarning + ); + const inProgressBuilds = builds.filter(build => build.status === BuildStatus.InProgress); + const render = (): void => { + const text = formatActiveBuildsText( + pendingBuildsText, + inProgressBuilds.map(build => ({ + build, + logs: logsStates.get(build.id)?.getLogs() ?? new Map(), + })) + ); + updateSpinnerText(spinner, { text }); + }; + installRender(render); + render(); return { refetch: true }; } } diff --git a/packages/eas-cli/src/build/logs.ts b/packages/eas-cli/src/build/logs.ts new file mode 100644 index 0000000000..04ff67a983 --- /dev/null +++ b/packages/eas-cli/src/build/logs.ts @@ -0,0 +1,111 @@ +import { BuildPhase, buildPhaseDisplayName } from '@expo/eas-build-job'; + +import { choicesFromJobLogs, stepLogTail } from '../commandUtils/logs/format'; +import { parseLogLines } from '../commandUtils/logs/parseLogs'; +import { JobLogs, RawLogLine } from '../commandUtils/logs/types'; +import { LogSource } from '../commandUtils/logs/watcher'; +import { BuildFragment, BuildStatus, RealtimeLogsTargetType } from '../graphql/generated'; +import Log from '../log'; +import { appPlatformDisplayNames, appPlatformEmojis } from '../platform'; +import formatFields, { FormatFieldsItem } from '../utils/formatFields'; + +const SINGLE_BUILD_MAX_LOG_LINES = 5; +const MULTIPLE_BUILDS_MAX_LOG_LINES = 3; + +async function fetchAndParseLogsForBuildAsync(build: BuildFragment): Promise { + const logFileUrl = build.logFiles[0]; + if (!logFileUrl) { + return null; + } + const response = await fetch(logFileUrl); + const rawLogs = await response.text(); + if (!rawLogs) { + return null; + } + const { logLines, errors } = parseLogLines(rawLogs); + for (const error of errors) { + Log.debug(`Failed to parse a log line: ${error.message}`); + } + return logLines; +} + +export function logSourceForBuild(build: BuildFragment): LogSource { + return { + key: build.id, + realtimeTarget: { type: RealtimeLogsTargetType.Build, id: build.id }, + isInProgress: build.status === BuildStatus.InProgress, + fetchRawLogLinesAsync: async () => await fetchAndParseLogsForBuildAsync(build), + }; +} + +export function isBuildCompleted(status: BuildStatus): boolean { + switch (status) { + case BuildStatus.Finished: + case BuildStatus.Errored: + case BuildStatus.Canceled: + return true; + case BuildStatus.New: + case BuildStatus.InQueue: + case BuildStatus.InProgress: + case BuildStatus.PendingCancel: + return false; + } +} + +function stepDisplayName(label: string): string { + return Object.hasOwn(buildPhaseDisplayName, label) + ? buildPhaseDisplayName[label as BuildPhase] + : label; +} + +function activeBuildFields( + logs: JobLogs, + maxLogLines: number, + buildLabel: string | null +): FormatFieldsItem[] { + const steps = choicesFromJobLogs(logs); + if (steps.length === 0) { + return []; + } + const currentStep = steps[steps.length - 1]; + + const fields: FormatFieldsItem[] = [{ label: '', value: '' }]; + if (buildLabel !== null) { + fields.push({ label: ' Build', value: buildLabel }); + } + fields.push({ label: ' Current phase', value: stepDisplayName(currentStep.name) }); + if (currentStep.logLines?.length) { + fields.push({ label: ' Current logs', value: '' }); + for (const logLine of stepLogTail(currentStep, maxLogLines)) { + fields.push({ label: '', value: logLine }); + } + } + return fields; +} + +function appendFields(baseText: string, fields: FormatFieldsItem[]): string { + if (fields.length === 0) { + return baseText; + } + return `${baseText}\n${formatFields(fields)}`; +} + +export function formatActiveBuildText(baseText: string, logs: JobLogs): string { + return appendFields(baseText, activeBuildFields(logs, SINGLE_BUILD_MAX_LOG_LINES, null)); +} + +export function formatActiveBuildsText( + baseText: string, + buildsWithLogs: { build: BuildFragment; logs: JobLogs }[] +): string { + return appendFields( + baseText, + buildsWithLogs.flatMap(({ build, logs }) => + activeBuildFields( + logs, + MULTIPLE_BUILDS_MAX_LOG_LINES, + `${appPlatformEmojis[build.platform]} ${appPlatformDisplayNames[build.platform]}` + ) + ) + ); +} diff --git a/packages/eas-cli/src/commandUtils/workflow/logs/__tests__/parseLogs-test.ts b/packages/eas-cli/src/commandUtils/logs/__tests__/parseLogs-test.ts similarity index 97% rename from packages/eas-cli/src/commandUtils/workflow/logs/__tests__/parseLogs-test.ts rename to packages/eas-cli/src/commandUtils/logs/__tests__/parseLogs-test.ts index 84e353341d..7c77316bb0 100644 --- a/packages/eas-cli/src/commandUtils/workflow/logs/__tests__/parseLogs-test.ts +++ b/packages/eas-cli/src/commandUtils/logs/__tests__/parseLogs-test.ts @@ -1,7 +1,7 @@ import { groupLogLinesIntoSteps, mergeLogLines, parseLogLines } from '../parseLogs'; -import { WorkflowRawLogLine } from '../../types'; +import { RawLogLine } from '../types'; -function logLine(overrides: Partial = {}): WorkflowRawLogLine { +function logLine(overrides: Partial = {}): RawLogLine { return { msg: 'a message', ...overrides }; } diff --git a/packages/eas-cli/src/commandUtils/logs/__tests__/state-test.ts b/packages/eas-cli/src/commandUtils/logs/__tests__/state-test.ts new file mode 100644 index 0000000000..a0021b9de6 --- /dev/null +++ b/packages/eas-cli/src/commandUtils/logs/__tests__/state-test.ts @@ -0,0 +1,110 @@ +import { LogsState } from '../state'; +import { RawLogLine } from '../types'; + +function fileLine(logId: string, msg: string, buildStepId = 'install'): RawLogLine { + return { logId, buildStepId, msg }; +} + +function stepMessages(logsState: LogsState): string[] { + return Array.from(logsState.getLogs().values()).flatMap(group => + group.logLines.map(logLine => logLine.msg) + ); +} + +describe(LogsState, () => { + it('hides realtime lines until the file logs reach them', () => { + const logsState = new LogsState(); + logsState.ingestFileLogLines([fileLine('1', 'first')]); + logsState.ingestRealtimeLogLines([fileLine('5', 'pushed')]); + + expect(stepMessages(logsState)).toEqual(['first']); + }); + + it('shows realtime lines once a published logId also appears in the file', () => { + const logsState = new LogsState(); + logsState.ingestFileLogLines([fileLine('1', 'first')]); + logsState.ingestRealtimeLogLines([fileLine('2', 'pushed')]); + logsState.ingestFileLogLines([fileLine('1', 'first'), fileLine('2', 'pushed')]); + logsState.ingestRealtimeLogLines([fileLine('3', 'newer')]); + + expect(stepMessages(logsState)).toEqual(['first', 'pushed', 'newer']); + }); + + it('shows realtime logs when a publication repeats a logId already in the file', () => { + const logsState = new LogsState(); + logsState.ingestFileLogLines([fileLine('1', 'first')]); + logsState.ingestRealtimeLogLines([fileLine('1', 'first'), fileLine('2', 'pushed')]); + + expect(stepMessages(logsState)).toEqual(['first', 'pushed']); + }); + + it('shows buffered realtime lines once the job is completed', () => { + const logsState = new LogsState(); + logsState.ingestFileLogLines([fileLine('1', 'first')]); + logsState.ingestRealtimeLogLines([fileLine('9', 'pushed')]); + + logsState.markCompleted(); + logsState.markCompleted(); + + expect(stepMessages(logsState)).toEqual(['first', 'pushed']); + }); + + it('folds later publications once completion showed them', () => { + const logsState = new LogsState(); + logsState.ingestFileLogLines([fileLine('1', 'first')]); + logsState.ingestRealtimeLogLines([fileLine('9', 'buffered')]); + logsState.markCompleted(); + + logsState.ingestRealtimeLogLines([fileLine('10', 'pushed')]); + + expect(stepMessages(logsState)).toEqual(['first', 'buffered', 'pushed']); + }); + + it('replaces the file snapshot instead of accumulating it', () => { + const logsState = new LogsState(); + const keyless: RawLogLine = { buildStepId: 'install', msg: 'submission log' }; + + logsState.ingestFileLogLines([keyless]); + logsState.ingestFileLogLines([keyless]); + + expect(stepMessages(logsState)).toEqual(['submission log']); + }); + + it('drops a buffered realtime line once it lands in the file', () => { + const logsState = new LogsState(); + logsState.ingestFileLogLines([fileLine('1', 'first')]); + logsState.ingestRealtimeLogLines([fileLine('2', 'pushed')]); + logsState.ingestFileLogLines([fileLine('1', 'first'), fileLine('2', 'pushed')]); + + expect(stepMessages(logsState)).toEqual(['first', 'pushed']); + }); + + it('ignores publications that are not arrays of log lines', () => { + const logsState = new LogsState(); + logsState.ingestFileLogLines([fileLine('1', 'first')]); + + expect(logsState.ingestRealtimeLogLines({ logId: '2', msg: 'not an array' })).toBe(false); + expect(logsState.ingestRealtimeLogLines(['a string', 42, null])).toBe(false); + expect(logsState.ingestRealtimeLogLines([{ msg: 'no logId' }])).toBe(false); + expect(stepMessages(logsState)).toEqual(['first']); + }); + + it('deduplicates a line republished on the same channel', () => { + const logsState = new LogsState(); + logsState.ingestFileLogLines([fileLine('1', 'first')]); + logsState.ingestRealtimeLogLines([fileLine('1', 'first'), fileLine('2', 'pushed')]); + logsState.ingestRealtimeLogLines([fileLine('2', 'pushed')]); + + expect(stepMessages(logsState)).toEqual(['first', 'pushed']); + }); + + it('deduplicates a line republished later', () => { + const logsState = new LogsState(); + logsState.ingestFileLogLines([fileLine('1', 'first')]); + logsState.ingestRealtimeLogLines([fileLine('1', 'first'), fileLine('2', 'pushed')]); + logsState.ingestRealtimeLogLines([fileLine('3', 'newer')]); + logsState.ingestRealtimeLogLines([fileLine('2', 'pushed')]); + + expect(stepMessages(logsState)).toEqual(['first', 'pushed', 'newer']); + }); +}); diff --git a/packages/eas-cli/src/commandUtils/logs/__tests__/watcher-test.ts b/packages/eas-cli/src/commandUtils/logs/__tests__/watcher-test.ts new file mode 100644 index 0000000000..64fb6b1e09 --- /dev/null +++ b/packages/eas-cli/src/commandUtils/logs/__tests__/watcher-test.ts @@ -0,0 +1,153 @@ +import { RealtimeLogsTargetType } from '../../../graphql/generated'; +import { RealtimeLogsClient } from '../../../utils/centrifuge'; +import { LogSource, LogsWatcher } from '../watcher'; + +function createFakeClient(): { + client: RealtimeLogsClient; + publish: (data: unknown) => void; + subscribeCalls: unknown[]; + closeCount: () => number; +} { + const listeners: ((data: unknown) => void)[] = []; + const subscribeCalls: unknown[] = []; + let closed = 0; + return { + subscribeCalls, + closeCount: () => closed, + publish: data => { + listeners.forEach(listener => { + listener(data); + }); + }, + client: { + subscribeAsync: async (args, onPublication) => { + subscribeCalls.push(args); + listeners.push(onPublication); + return { close: () => closed++ }; + }, + close: () => closed++, + }, + }; +} + +describe(LogsWatcher, () => { + let fetchRawLogLinesAsync: jest.Mock; + + beforeEach(() => { + fetchRawLogLinesAsync = jest + .fn() + .mockResolvedValue([{ logId: '1', buildStepId: 'install', msg: 'from the file' }]); + }); + + function inProgressSource(overrides: Partial = {}): LogSource { + return { + key: 'job1', + realtimeTarget: { type: RealtimeLogsTargetType.JobRun, id: 'job-run-id' }, + isInProgress: true, + fetchRawLogLinesAsync, + ...overrides, + }; + } + + it('subscribes once per in-progress source', async () => { + const fake = createFakeClient(); + const watcher = new LogsWatcher( + () => fake.client, + () => {} + ); + + await watcher.syncAsync([inProgressSource()]); + await watcher.syncAsync([inProgressSource()]); + + expect(fake.subscribeCalls).toEqual([ + { target: { type: RealtimeLogsTargetType.JobRun, id: 'job-run-id' } }, + ]); + }); + + it('reports realtime logs as they arrive', async () => { + const fake = createFakeClient(); + const onRealtimeLogs = jest.fn(); + const watcher = new LogsWatcher(() => fake.client, onRealtimeLogs); + await watcher.syncAsync([inProgressSource()]); + + fake.publish([{ logId: '2', buildStepId: 'install', msg: 'pushed' }]); + + expect(onRealtimeLogs).toHaveBeenCalledTimes(1); + }); + + it('does not report a publication that carries no usable log lines', async () => { + const fake = createFakeClient(); + const onRealtimeLogs = jest.fn(); + const watcher = new LogsWatcher(() => fake.client, onRealtimeLogs); + await watcher.syncAsync([inProgressSource()]); + + fake.publish([{ msg: 'no logId' }]); + + expect(onRealtimeLogs).not.toHaveBeenCalled(); + }); + + it('still fetches logs when the realtime logs client is unavailable', async () => { + const watcher = new LogsWatcher( + () => null, + () => {} + ); + + await watcher.syncAsync([inProgressSource()]); + + expect(fetchRawLogLinesAsync).toHaveBeenCalledTimes(1); + }); + + it('fetches logs on every sync while in progress, and stops once the source is not', async () => { + const fake = createFakeClient(); + const watcher = new LogsWatcher( + () => fake.client, + () => {} + ); + + await watcher.syncAsync([inProgressSource()]); + await watcher.syncAsync([inProgressSource()]); + expect(fetchRawLogLinesAsync).toHaveBeenCalledTimes(2); + + await watcher.syncAsync([inProgressSource({ isInProgress: false })]); + expect(fetchRawLogLinesAsync).toHaveBeenCalledTimes(2); + }); + + it('does not fetch logs for a source that is not in progress', async () => { + const fake = createFakeClient(); + const watcher = new LogsWatcher( + () => fake.client, + () => {} + ); + + await watcher.syncAsync([inProgressSource({ isInProgress: false })]); + + expect(fetchRawLogLinesAsync).not.toHaveBeenCalled(); + }); + + it('closes the subscription when a source leaves in-progress', async () => { + const fake = createFakeClient(); + const watcher = new LogsWatcher( + () => fake.client, + () => {} + ); + + await watcher.syncAsync([inProgressSource()]); + expect(fake.closeCount()).toBe(0); + + await watcher.syncAsync([inProgressSource({ isInProgress: false })]); + expect(fake.closeCount()).toBe(1); + }); + + it('closes the client and its subscriptions', async () => { + const fake = createFakeClient(); + const watcher = new LogsWatcher( + () => fake.client, + () => {} + ); + + await watcher.syncAsync([inProgressSource()]); + watcher.close(); + + expect(fake.closeCount()).toBe(2); + }); +}); diff --git a/packages/eas-cli/src/commandUtils/logs/format.ts b/packages/eas-cli/src/commandUtils/logs/format.ts new file mode 100644 index 0000000000..fdc8afb585 --- /dev/null +++ b/packages/eas-cli/src/commandUtils/logs/format.ts @@ -0,0 +1,25 @@ +import { JobLogs, LogLine } from './types'; +import { Choice } from '../../prompts'; + +export function choicesFromJobLogs( + logs: JobLogs +): (Choice & { name: string; status: string; logLines: LogLine[] | undefined })[] { + return Array.from(logs.values()) + .map(({ key, label, result, logLines }) => ({ + title: `${label} - ${result ?? ''}`, + name: label, + status: result ?? '', + value: key, + logLines, + })) + .filter(step => step.status !== 'skipped'); +} + +export function stepLogTail( + step: { logLines?: LogLine[] }, + maxLogLines: number // -1 means no limit +): string[] { + const logLines = step.logLines ?? []; + const tail = maxLogLines === -1 ? logLines : logLines.slice(-maxLogLines); + return tail.map(line => line.msg); +} diff --git a/packages/eas-cli/src/commandUtils/logs/parseLogs.ts b/packages/eas-cli/src/commandUtils/logs/parseLogs.ts new file mode 100644 index 0000000000..6889994b54 --- /dev/null +++ b/packages/eas-cli/src/commandUtils/logs/parseLogs.ts @@ -0,0 +1,56 @@ +import { JobLogs, RawLogLine } from './types'; +import uniqBy from '../../utils/expodash/uniqBy'; + +export function parseLogLines(rawLogs: string): { + logLines: RawLogLine[]; + errors: Error[]; +} { + const logLines: RawLogLine[] = []; + const errors: Error[] = []; + + for (const rawLogLine of rawLogs.split('\n')) { + if (!rawLogLine) { + continue; + } + try { + logLines.push(JSON.parse(rawLogLine)); + } catch (err) { + errors.push(err as Error); + } + } + + return { logLines, errors }; +} + +export function mergeLogLines(...logLineGroups: T[][]): T[] { + return uniqBy(logLineGroups.flat().reverse(), logLine => logLine.logId ?? Symbol()).reverse(); +} + +export function groupLogLinesIntoSteps( + logLines: RawLogLine[], + accumulator: JobLogs = new Map() +): JobLogs { + for (const logLine of logLines) { + const { buildStepDisplayName, buildStepId, phase, time, msg, result, marker, err } = logLine; + const stepKey = buildStepId ?? buildStepDisplayName ?? phase; + const stepLabel = buildStepDisplayName ?? buildStepId ?? phase; + if (!stepKey || !stepLabel || !msg) { + continue; + } + + let logGroup = accumulator.get(stepKey); + if (!logGroup) { + logGroup = { key: stepKey, label: stepLabel, logLines: [] }; + accumulator.set(stepKey, logGroup); + } + if (buildStepDisplayName) { + logGroup.label = buildStepDisplayName; + } + if (logGroup.result === undefined && (marker === 'end-step' || marker === 'END_PHASE')) { + logGroup.result = result ?? ''; + } + logGroup.logLines.push({ time, msg, result, marker, err }); + } + + return accumulator; +} diff --git a/packages/eas-cli/src/commandUtils/logs/state.ts b/packages/eas-cli/src/commandUtils/logs/state.ts new file mode 100644 index 0000000000..c3da2ca490 --- /dev/null +++ b/packages/eas-cli/src/commandUtils/logs/state.ts @@ -0,0 +1,94 @@ +import { groupLogLinesIntoSteps, mergeLogLines } from './parseLogs'; +import { JobLogs, RawLogLine } from './types'; + +type RealtimeLogLine = RawLogLine & { logId: string }; + +function isRealtimeLogLine(entry: unknown): entry is RealtimeLogLine { + return ( + typeof entry === 'object' && + entry !== null && + typeof (entry as Partial).logId === 'string' + ); +} + +export class LogsState { + private fileLogIds = new Set(); + private realtimeLogLines: RealtimeLogLine[] = []; + private realtimeLogIds = new Set(); + private haveFileLogsCaughtUp = false; + private realtimeLogsRevealed = false; + private jobLogs: JobLogs = new Map(); + + public ingestFileLogLines(logLines: RawLogLine[]): void { + this.fileLogIds = new Set(logLines.flatMap(logLine => (logLine.logId ? [logLine.logId] : []))); + + if ( + !this.haveFileLogsCaughtUp && + this.realtimeLogLines.some(logLine => this.fileLogIds.has(logLine.logId)) + ) { + this.haveFileLogsCaughtUp = true; + } + this.realtimeLogLines = this.realtimeLogLines.filter( + logLine => !this.fileLogIds.has(logLine.logId) + ); + this.realtimeLogIds = new Set(this.realtimeLogLines.map(logLine => logLine.logId)); + + if (this.haveFileLogsCaughtUp) { + this.realtimeLogsRevealed = true; + } + this.jobLogs = groupLogLinesIntoSteps( + mergeLogLines(logLines, this.realtimeLogsRevealed ? this.realtimeLogLines : []) + ); + } + + public ingestRealtimeLogLines(data: unknown): boolean { + if (!Array.isArray(data)) { + return false; + } + const publishedLogLines = data.filter(isRealtimeLogLine); + if (publishedLogLines.length === 0) { + return false; + } + + if ( + !this.haveFileLogsCaughtUp && + publishedLogLines.some(logLine => this.fileLogIds.has(logLine.logId)) + ) { + this.haveFileLogsCaughtUp = true; + } + + const newLogLines = publishedLogLines.filter( + logLine => !this.fileLogIds.has(logLine.logId) && !this.realtimeLogIds.has(logLine.logId) + ); + for (const logLine of newLogLines) { + this.realtimeLogLines.push(logLine); + this.realtimeLogIds.add(logLine.logId); + } + + if (!this.realtimeLogsRevealed) { + if (this.haveFileLogsCaughtUp) { + this.revealRealtimeLogs(); + } + } else if (newLogLines.length > 0) { + groupLogLinesIntoSteps(newLogLines, this.jobLogs); + } + + return true; + } + + public markCompleted(): void { + this.revealRealtimeLogs(); + } + + public getLogs(): JobLogs { + return this.jobLogs; + } + + private revealRealtimeLogs(): void { + if (this.realtimeLogsRevealed) { + return; + } + this.realtimeLogsRevealed = true; + groupLogLinesIntoSteps(this.realtimeLogLines, this.jobLogs); + } +} diff --git a/packages/eas-cli/src/commandUtils/logs/types.ts b/packages/eas-cli/src/commandUtils/logs/types.ts new file mode 100644 index 0000000000..d29ddb8066 --- /dev/null +++ b/packages/eas-cli/src/commandUtils/logs/types.ts @@ -0,0 +1,23 @@ +export type RawLogLine = { + logId?: string; + buildStepId?: string; + buildStepDisplayName?: string; + phase?: string; + time?: string; + msg?: string; + result?: string; + marker?: string; + err?: any; +}; + +export type LogLine = Pick & + Required>; + +export type StepLogs = { + key: string; + label: string; + result?: string; + logLines: LogLine[]; +}; + +export type JobLogs = Map; diff --git a/packages/eas-cli/src/commandUtils/logs/watcher.ts b/packages/eas-cli/src/commandUtils/logs/watcher.ts new file mode 100644 index 0000000000..84b05b7d08 --- /dev/null +++ b/packages/eas-cli/src/commandUtils/logs/watcher.ts @@ -0,0 +1,102 @@ +import { LogsState } from './state'; +import { RawLogLine } from './types'; +import { RealtimeLogsTargetInput } from '../../graphql/generated'; +import Log from '../../log'; +import { RealtimeLogsClient, RealtimeLogsSubscription } from '../../utils/centrifuge'; +import nullthrows from 'nullthrows'; + +export type LogSource = { + key: string; + realtimeTarget: RealtimeLogsTargetInput | null; + isInProgress: boolean; + fetchRawLogLinesAsync: () => Promise; +}; + +type TrackedSource = { + logsState: LogsState; + subscription: RealtimeLogsSubscription | null; +}; + +export class LogsWatcher { + private readonly trackedSources = new Map(); + private realtimeLogsClient?: RealtimeLogsClient | null; + + constructor( + private readonly createRealtimeLogsClient: () => RealtimeLogsClient | null, + private readonly onRealtimeLogs: () => void + ) {} + + public async syncAsync(sources: LogSource[]): Promise> { + await Promise.all(sources.map(source => this.syncSourceAsync(source))); + return new Map( + sources.map(source => [ + source.key, + nullthrows( + this.trackedSources.get(source.key), + 'source has to be in tracked sources after it was synced' + ).logsState, + ]) + ); + } + + public close(): void { + for (const trackedSource of this.trackedSources.values()) { + trackedSource.subscription?.close(); + trackedSource.subscription = null; + } + this.realtimeLogsClient?.close(); + } + + private async syncSourceAsync(source: LogSource): Promise { + let trackedSource = this.trackedSources.get(source.key); + if (!trackedSource) { + trackedSource = { logsState: new LogsState(), subscription: null }; + this.trackedSources.set(source.key, trackedSource); + } + + if (!source.isInProgress) { + trackedSource.subscription?.close(); + trackedSource.subscription = null; + return; + } + + await Promise.all([ + trackedSource.subscription ? Promise.resolve() : this.subscribeAsync(source, trackedSource), + this.fetchLogsAsync(source, trackedSource), + ]); + } + + private async fetchLogsAsync(source: LogSource, trackedSource: TrackedSource): Promise { + try { + const logLines = await source.fetchRawLogLinesAsync(); + if (logLines) { + trackedSource.logsState.ingestFileLogLines(logLines); + } + } catch (err: any) { + Log.debug(`Failed to fetch logs for job ${source.key}: ${err.message}`); + } + } + + private getRealtimeLogsClient(): RealtimeLogsClient | null { + if (this.realtimeLogsClient === undefined) { + this.realtimeLogsClient = this.createRealtimeLogsClient(); + } + return this.realtimeLogsClient; + } + + private async subscribeAsync(source: LogSource, trackedSource: TrackedSource): Promise { + const target = source.realtimeTarget; + if (!target) { + return; + } + const realtimeLogsClient = this.getRealtimeLogsClient(); + if (!realtimeLogsClient) { + return; + } + trackedSource.subscription = await realtimeLogsClient.subscribeAsync({ target }, data => { + if (trackedSource.logsState.ingestRealtimeLogLines(data)) { + this.onRealtimeLogs(); + } + }); + } +} diff --git a/packages/eas-cli/src/commandUtils/workflow/logs/__tests__/fetchLogs-test.ts b/packages/eas-cli/src/commandUtils/workflow/__tests__/fetchLogs-test.ts similarity index 71% rename from packages/eas-cli/src/commandUtils/workflow/logs/__tests__/fetchLogs-test.ts rename to packages/eas-cli/src/commandUtils/workflow/__tests__/fetchLogs-test.ts index 7d894e0950..77300c11a3 100644 --- a/packages/eas-cli/src/commandUtils/workflow/logs/__tests__/fetchLogs-test.ts +++ b/packages/eas-cli/src/commandUtils/workflow/__tests__/fetchLogs-test.ts @@ -1,9 +1,9 @@ -import { getMockWorkflowCustomJobFragment } from '../../../../__tests__/commands/utils'; -import { BuildQuery } from '../../../../graphql/queries/BuildQuery'; -import { ExpoGraphqlClient } from '../../../context/contextUtils/createGraphqlClient'; +import { getMockWorkflowCustomJobFragment } from '../../../__tests__/commands/utils'; +import { BuildQuery } from '../../../graphql/queries/BuildQuery'; +import { ExpoGraphqlClient } from '../../context/contextUtils/createGraphqlClient'; import { fetchRawLogsForJobAsync } from '../fetchLogs'; -jest.mock('../../../../graphql/queries/BuildQuery'); +jest.mock('../../../graphql/queries/BuildQuery'); describe(fetchRawLogsForJobAsync, () => { afterEach(() => { diff --git a/packages/eas-cli/src/commandUtils/workflow/__tests__/logs-test.ts b/packages/eas-cli/src/commandUtils/workflow/__tests__/logs-test.ts new file mode 100644 index 0000000000..598b2f8c82 --- /dev/null +++ b/packages/eas-cli/src/commandUtils/workflow/__tests__/logs-test.ts @@ -0,0 +1,108 @@ +import { getMockWorkflowRunWithJobsFragment } from '../../../__tests__/commands/utils'; +import { + RealtimeLogsTargetType, + WorkflowJobStatus, + WorkflowJobType, +} from '../../../graphql/generated'; +import { fetchRawLogsForJobAsync } from '../fetchLogs'; +import { logSourceForWorkflowJob } from '../logs'; +import { WorkflowJobResult } from '../types'; + +jest.mock('../fetchLogs'); + +function inProgressJob(): WorkflowJobResult { + const job = getMockWorkflowRunWithJobsFragment().jobs[0]; + return { ...job, status: WorkflowJobStatus.InProgress }; +} + +describe(logSourceForWorkflowJob, () => { + afterEach(() => { + jest.clearAllMocks(); + }); + + it('keys the source by the job id', () => { + expect(logSourceForWorkflowJob({} as any, inProgressJob()).key).toBe('job1'); + }); + + it('is in progress only while the job is in progress', () => { + const job = inProgressJob(); + + expect(logSourceForWorkflowJob({} as any, job).isInProgress).toBe(true); + for (const status of [ + WorkflowJobStatus.New, + WorkflowJobStatus.ActionRequired, + WorkflowJobStatus.PendingCancel, + WorkflowJobStatus.Success, + WorkflowJobStatus.Failure, + WorkflowJobStatus.Canceled, + WorkflowJobStatus.Skipped, + ]) { + expect(logSourceForWorkflowJob({} as any, { ...job, status }).isInProgress).toBe(false); + } + }); + + it('targets the turtle job run when there is one', () => { + const job = { ...inProgressJob(), turtleJobRun: { id: 'job-run-id' } } as WorkflowJobResult; + + expect(logSourceForWorkflowJob({} as any, job).realtimeTarget).toEqual({ + type: RealtimeLogsTargetType.JobRun, + id: 'job-run-id', + }); + }); + + it('falls back to the build when there is no turtle job run', () => { + const withTurtleBuild = { + ...inProgressJob(), + turtleJobRun: null, + turtleBuild: { id: 'build-id' }, + } as WorkflowJobResult; + const withBuildOutput = { + ...inProgressJob(), + turtleJobRun: null, + turtleBuild: null, + outputs: { build_id: 'output-build-id' }, + } as WorkflowJobResult; + + expect(logSourceForWorkflowJob({} as any, withTurtleBuild).realtimeTarget).toEqual({ + type: RealtimeLogsTargetType.Build, + id: 'build-id', + }); + expect(logSourceForWorkflowJob({} as any, withBuildOutput).realtimeTarget).toEqual({ + type: RealtimeLogsTargetType.Build, + id: 'output-build-id', + }); + }); + + it('has no realtime target when neither is present', () => { + const job = { + ...inProgressJob(), + turtleJobRun: null, + turtleBuild: null, + outputs: null, + } as WorkflowJobResult; + + expect(logSourceForWorkflowJob({} as any, job).realtimeTarget).toBeNull(); + }); + + it('fetches and parses the job logs with the graphql client it was given', async () => { + const graphqlClient = {} as any; + const job = { ...inProgressJob(), type: WorkflowJobType.Build } as WorkflowJobResult; + jest + .mocked(fetchRawLogsForJobAsync) + .mockResolvedValue( + [ + '{"logId":"1","buildStepId":"install","msg":"npm ci"}', + '{"logId":"2","buildStepId":"install","msg":"done"}', + ].join('\n') + ); + + await expect( + logSourceForWorkflowJob(graphqlClient, job).fetchRawLogLinesAsync() + ).resolves.toEqual([ + { logId: '1', buildStepId: 'install', msg: 'npm ci' }, + { logId: '2', buildStepId: 'install', msg: 'done' }, + ]); + + expect(fetchRawLogsForJobAsync).toHaveBeenCalledWith({ graphqlClient }, job); + }); +}); diff --git a/packages/eas-cli/src/commandUtils/workflow/__tests__/utils-test.ts b/packages/eas-cli/src/commandUtils/workflow/__tests__/utils-test.ts index a4cc5dbbc2..af62ce69b4 100644 --- a/packages/eas-cli/src/commandUtils/workflow/__tests__/utils-test.ts +++ b/packages/eas-cli/src/commandUtils/workflow/__tests__/utils-test.ts @@ -1,15 +1,15 @@ import { getMockWorkflowRunWithJobsFragment } from '../../../__tests__/commands/utils'; import { WorkflowJobStatus } from '../../../graphql/generated'; -import { groupLogLinesIntoSteps, parseLogLines } from '../logs/parseLogs'; -import { WorkflowLogs, WorkflowRawLogLine } from '../types'; +import { groupLogLinesIntoSteps, parseLogLines } from '../../logs/parseLogs'; +import { JobLogs, RawLogLine } from '../../logs/types'; import { formatActiveWorkflowRun, formatFailedWorkflowRun } from '../utils'; function jobWithLogs( - logLines: WorkflowRawLogLine[], + logLines: RawLogLine[], status: WorkflowJobStatus = WorkflowJobStatus.InProgress ): { job: ReturnType['jobs'][number]; - logs: WorkflowLogs; + logs: JobLogs; } { return { job: { ...getMockWorkflowRunWithJobsFragment().jobs[0], status }, @@ -17,7 +17,7 @@ function jobWithLogs( }; } -function stepLines(buildStepId: string, count: number): WorkflowRawLogLine[] { +function stepLines(buildStepId: string, count: number): RawLogLine[] { return Array.from({ length: count }, (_, index) => ({ buildStepId, msg: `line${index}` })); } diff --git a/packages/eas-cli/src/commandUtils/workflow/logs/fetchLogs.ts b/packages/eas-cli/src/commandUtils/workflow/fetchLogs.ts similarity index 78% rename from packages/eas-cli/src/commandUtils/workflow/logs/fetchLogs.ts rename to packages/eas-cli/src/commandUtils/workflow/fetchLogs.ts index 0332e7e6fb..e2213abf3d 100644 --- a/packages/eas-cli/src/commandUtils/workflow/logs/fetchLogs.ts +++ b/packages/eas-cli/src/commandUtils/workflow/fetchLogs.ts @@ -1,6 +1,6 @@ -import { WorkflowJobResult } from '../types'; -import { BuildQuery } from '../../../graphql/queries/BuildQuery'; -import { ExpoGraphqlClient } from '../../context/contextUtils/createGraphqlClient'; +import { WorkflowJobResult } from './types'; +import { BuildQuery } from '../../graphql/queries/BuildQuery'; +import { ExpoGraphqlClient } from '../context/contextUtils/createGraphqlClient'; export async function fetchRawLogsForJobAsync( state: { graphqlClient: ExpoGraphqlClient }, diff --git a/packages/eas-cli/src/commandUtils/workflow/logs.ts b/packages/eas-cli/src/commandUtils/workflow/logs.ts new file mode 100644 index 0000000000..4040e17959 --- /dev/null +++ b/packages/eas-cli/src/commandUtils/workflow/logs.ts @@ -0,0 +1,59 @@ +import { fetchRawLogsForJobAsync } from './fetchLogs'; +import { WorkflowJobResult } from './types'; +import { + RealtimeLogsTargetInput, + RealtimeLogsTargetType, + WorkflowJobStatus, +} from '../../graphql/generated'; +import Log from '../../log'; +import { groupLogLinesIntoSteps, parseLogLines } from '../logs/parseLogs'; +import { JobLogs, RawLogLine } from '../logs/types'; +import { LogSource } from '../logs/watcher'; +import { ExpoGraphqlClient } from '../context/contextUtils/createGraphqlClient'; + +async function fetchAndParseLogsFromJobAsync( + state: { graphqlClient: ExpoGraphqlClient }, + job: WorkflowJobResult +): Promise { + const rawLogs = await fetchRawLogsForJobAsync(state, job); + if (!rawLogs) { + return null; + } + Log.debug(`rawLogs = ${JSON.stringify(rawLogs, null, 2)}`); + const { logLines, errors } = parseLogLines(rawLogs); + for (const error of errors) { + Log.debug(`Failed to parse a log line: ${error.message}`); + } + return logLines; +} + +export async function fetchAndProcessLogsFromJobAsync( + state: { graphqlClient: ExpoGraphqlClient }, + job: WorkflowJobResult +): Promise { + const logLines = await fetchAndParseLogsFromJobAsync(state, job); + return logLines && groupLogLinesIntoSteps(logLines); +} + +export function logSourceForWorkflowJob( + graphqlClient: ExpoGraphqlClient, + job: WorkflowJobResult +): LogSource { + return { + key: job.id, + realtimeTarget: realtimeLogsTargetForJob(job), + isInProgress: job.status === WorkflowJobStatus.InProgress, + fetchRawLogLinesAsync: async () => await fetchAndParseLogsFromJobAsync({ graphqlClient }, job), + }; +} + +function realtimeLogsTargetForJob(job: WorkflowJobResult): RealtimeLogsTargetInput | null { + if (job.turtleJobRun?.id) { + return { type: RealtimeLogsTargetType.JobRun, id: job.turtleJobRun.id }; + } + const buildId = job.turtleBuild?.id ?? job.outputs?.build_id; + if (buildId) { + return { type: RealtimeLogsTargetType.Build, id: buildId }; + } + return null; +} diff --git a/packages/eas-cli/src/commandUtils/workflow/logs/__tests__/watcher-test.ts b/packages/eas-cli/src/commandUtils/workflow/logs/__tests__/watcher-test.ts deleted file mode 100644 index 9d93dc6b3d..0000000000 --- a/packages/eas-cli/src/commandUtils/workflow/logs/__tests__/watcher-test.ts +++ /dev/null @@ -1,308 +0,0 @@ -import { getMockWorkflowRunWithJobsFragment } from '../../../../__tests__/commands/utils'; -import { RealtimeLogsTargetType, WorkflowJobStatus } from '../../../../graphql/generated'; -import { RealtimeLogsClient } from '../../../../utils/centrifuge'; -import { fetchAndParseLogsFromJobAsync } from '../parseLogs'; -import { WorkflowJobLogsState, WorkflowRunLogsWatcher, realtimeLogsTargetForJob } from '../watcher'; -import { WorkflowJobResult, WorkflowRawLogLine } from '../../types'; - -jest.mock('../parseLogs', () => ({ - ...jest.requireActual('../parseLogs'), - fetchAndParseLogsFromJobAsync: jest.fn(), -})); - -function createFakeClient(): { - client: RealtimeLogsClient; - publish: (data: unknown) => void; - subscribeCalls: unknown[]; - closeCount: () => number; -} { - const listeners: ((data: unknown) => void)[] = []; - const subscribeCalls: unknown[] = []; - let closed = 0; - return { - subscribeCalls, - closeCount: () => closed, - publish: data => { - listeners.forEach(listener => { - listener(data); - }); - }, - client: { - subscribeAsync: async (args, onPublication) => { - subscribeCalls.push(args); - listeners.push(onPublication); - return { close: () => closed++ }; - }, - close: () => closed++, - }, - }; -} - -function inProgressJob(): WorkflowJobResult { - const job = getMockWorkflowRunWithJobsFragment().jobs[0]; - return { ...job, status: WorkflowJobStatus.InProgress }; -} - -describe(realtimeLogsTargetForJob, () => { - it('targets the turtle job run when there is one', () => { - const job = { ...inProgressJob(), turtleJobRun: { id: 'job-run-id' } } as WorkflowJobResult; - - expect(realtimeLogsTargetForJob(job)).toEqual({ - type: RealtimeLogsTargetType.JobRun, - id: 'job-run-id', - }); - }); - - it('falls back to the build when there is no turtle job run', () => { - const job = { - ...inProgressJob(), - turtleJobRun: null, - turtleBuild: { id: 'build-id' }, - } as WorkflowJobResult; - - expect(realtimeLogsTargetForJob(job)).toEqual({ - type: RealtimeLogsTargetType.Build, - id: 'build-id', - }); - }); - - it('has no target when neither is present', () => { - const job = { - ...inProgressJob(), - turtleJobRun: null, - turtleBuild: null, - outputs: null, - } as WorkflowJobResult; - - expect(realtimeLogsTargetForJob(job)).toBeNull(); - }); -}); - -describe(WorkflowRunLogsWatcher, () => { - beforeEach(() => { - jest - .mocked(fetchAndParseLogsFromJobAsync) - .mockResolvedValue([{ logId: '1', buildStepId: 'install', msg: 'from the file' }]); - }); - - afterEach(() => { - jest.clearAllMocks(); - }); - - it('subscribes once per in-progress job', async () => { - const fake = createFakeClient(); - const watcher = new WorkflowRunLogsWatcher( - {} as any, - () => fake.client, - () => {} - ); - const job = inProgressJob(); - - await watcher.syncJobsAsync([job]); - await watcher.syncJobsAsync([job]); - - expect(fake.subscribeCalls).toHaveLength(1); - }); - - it('reports realtime logs as they arrive', async () => { - const fake = createFakeClient(); - const onRealtimeLogs = jest.fn(); - const watcher = new WorkflowRunLogsWatcher({} as any, () => fake.client, onRealtimeLogs); - await watcher.syncJobsAsync([inProgressJob()]); - - fake.publish([{ logId: '2', buildStepId: 'install', msg: 'pushed' }]); - - expect(onRealtimeLogs).toHaveBeenCalledTimes(1); - }); - - it('does not report a publication that carries no usable log lines', async () => { - const fake = createFakeClient(); - const onRealtimeLogs = jest.fn(); - const watcher = new WorkflowRunLogsWatcher({} as any, () => fake.client, onRealtimeLogs); - await watcher.syncJobsAsync([inProgressJob()]); - - fake.publish([{ msg: 'no logId' }]); - - expect(onRealtimeLogs).not.toHaveBeenCalled(); - }); - - it('still fetches logs when the realtime logs client is unavailable', async () => { - const watcher = new WorkflowRunLogsWatcher( - {} as any, - () => null, - () => {} - ); - - await watcher.syncJobsAsync([inProgressJob()]); - - expect(fetchAndParseLogsFromJobAsync).toHaveBeenCalledTimes(1); - }); - - it('fetches logs on every sync while in progress, and stops once the job completes', async () => { - const fake = createFakeClient(); - const watcher = new WorkflowRunLogsWatcher( - {} as any, - () => fake.client, - () => {} - ); - const job = inProgressJob(); - - await watcher.syncJobsAsync([job]); - await watcher.syncJobsAsync([job]); - expect(fetchAndParseLogsFromJobAsync).toHaveBeenCalledTimes(2); - - await watcher.syncJobsAsync([{ ...job, status: WorkflowJobStatus.Success }]); - expect(fetchAndParseLogsFromJobAsync).toHaveBeenCalledTimes(2); - }); - - it('does not fetch logs for a job that has not started', async () => { - const fake = createFakeClient(); - const watcher = new WorkflowRunLogsWatcher( - {} as any, - () => fake.client, - () => {} - ); - - await watcher.syncJobsAsync([{ ...inProgressJob(), status: WorkflowJobStatus.New }]); - - expect(fetchAndParseLogsFromJobAsync).not.toHaveBeenCalled(); - }); - - it('closes the subscription when a job leaves in-progress', async () => { - const fake = createFakeClient(); - const watcher = new WorkflowRunLogsWatcher( - {} as any, - () => fake.client, - () => {} - ); - const job = inProgressJob(); - - await watcher.syncJobsAsync([job]); - expect(fake.closeCount()).toBe(0); - - await watcher.syncJobsAsync([{ ...job, status: WorkflowJobStatus.Failure }]); - expect(fake.closeCount()).toBe(1); - }); - - it('closes the client and its subscriptions', async () => { - const fake = createFakeClient(); - const watcher = new WorkflowRunLogsWatcher( - {} as any, - () => fake.client, - () => {} - ); - - await watcher.syncJobsAsync([inProgressJob()]); - watcher.close(); - - expect(fake.closeCount()).toBe(2); - }); -}); - -function fileLine(logId: string, msg: string, buildStepId = 'install'): WorkflowRawLogLine { - return { logId, buildStepId, msg }; -} - -function stepMessages(logsState: WorkflowJobLogsState): string[] { - return Array.from(logsState.getLogs().values()).flatMap(group => - group.logLines.map(logLine => logLine.msg) - ); -} - -describe(WorkflowJobLogsState, () => { - it('hides realtime lines until the file logs reach them', () => { - const logsState = new WorkflowJobLogsState(); - logsState.ingestFileLogLines([fileLine('1', 'first')]); - logsState.ingestRealtimeLogLines([fileLine('5', 'pushed')]); - - expect(stepMessages(logsState)).toEqual(['first']); - }); - - it('shows realtime lines once a published logId also appears in the file', () => { - const logsState = new WorkflowJobLogsState(); - logsState.ingestFileLogLines([fileLine('1', 'first')]); - logsState.ingestRealtimeLogLines([fileLine('2', 'pushed')]); - logsState.ingestFileLogLines([fileLine('1', 'first'), fileLine('2', 'pushed')]); - logsState.ingestRealtimeLogLines([fileLine('3', 'newer')]); - - expect(stepMessages(logsState)).toEqual(['first', 'pushed', 'newer']); - }); - - it('shows realtime logs when a publication repeats a logId already in the file', () => { - const logsState = new WorkflowJobLogsState(); - logsState.ingestFileLogLines([fileLine('1', 'first')]); - logsState.ingestRealtimeLogLines([fileLine('1', 'first'), fileLine('2', 'pushed')]); - - expect(stepMessages(logsState)).toEqual(['first', 'pushed']); - }); - - it('shows buffered realtime lines once the job is completed', () => { - const logsState = new WorkflowJobLogsState(); - logsState.ingestFileLogLines([fileLine('1', 'first')]); - logsState.ingestRealtimeLogLines([fileLine('9', 'pushed')]); - - logsState.markCompleted(); - logsState.markCompleted(); - - expect(stepMessages(logsState)).toEqual(['first', 'pushed']); - }); - - it('folds later publications once completion showed them', () => { - const logsState = new WorkflowJobLogsState(); - logsState.ingestFileLogLines([fileLine('1', 'first')]); - logsState.ingestRealtimeLogLines([fileLine('9', 'buffered')]); - logsState.markCompleted(); - - logsState.ingestRealtimeLogLines([fileLine('10', 'pushed')]); - - expect(stepMessages(logsState)).toEqual(['first', 'buffered', 'pushed']); - }); - - it('replaces the file snapshot instead of accumulating it', () => { - const logsState = new WorkflowJobLogsState(); - const keyless: WorkflowRawLogLine = { buildStepId: 'install', msg: 'submission log' }; - - logsState.ingestFileLogLines([keyless]); - logsState.ingestFileLogLines([keyless]); - - expect(stepMessages(logsState)).toEqual(['submission log']); - }); - - it('drops a buffered realtime line once it lands in the file', () => { - const logsState = new WorkflowJobLogsState(); - logsState.ingestFileLogLines([fileLine('1', 'first')]); - logsState.ingestRealtimeLogLines([fileLine('2', 'pushed')]); - logsState.ingestFileLogLines([fileLine('1', 'first'), fileLine('2', 'pushed')]); - - expect(stepMessages(logsState)).toEqual(['first', 'pushed']); - }); - - it('ignores publications that are not arrays of log lines', () => { - const logsState = new WorkflowJobLogsState(); - logsState.ingestFileLogLines([fileLine('1', 'first')]); - - expect(logsState.ingestRealtimeLogLines({ logId: '2', msg: 'not an array' })).toBe(false); - expect(logsState.ingestRealtimeLogLines(['a string', 42, null])).toBe(false); - expect(logsState.ingestRealtimeLogLines([{ msg: 'no logId' }])).toBe(false); - expect(stepMessages(logsState)).toEqual(['first']); - }); - - it('deduplicates a line republished on the same channel', () => { - const logsState = new WorkflowJobLogsState(); - logsState.ingestFileLogLines([fileLine('1', 'first')]); - logsState.ingestRealtimeLogLines([fileLine('1', 'first'), fileLine('2', 'pushed')]); - logsState.ingestRealtimeLogLines([fileLine('2', 'pushed')]); - - expect(stepMessages(logsState)).toEqual(['first', 'pushed']); - }); - - it('deduplicates a line republished later', () => { - const logsState = new WorkflowJobLogsState(); - logsState.ingestFileLogLines([fileLine('1', 'first')]); - logsState.ingestRealtimeLogLines([fileLine('1', 'first'), fileLine('2', 'pushed')]); - logsState.ingestRealtimeLogLines([fileLine('3', 'newer')]); - logsState.ingestRealtimeLogLines([fileLine('2', 'pushed')]); - - expect(stepMessages(logsState)).toEqual(['first', 'pushed', 'newer']); - }); -}); diff --git a/packages/eas-cli/src/commandUtils/workflow/logs/parseLogs.ts b/packages/eas-cli/src/commandUtils/workflow/logs/parseLogs.ts deleted file mode 100644 index 4fc54af7d6..0000000000 --- a/packages/eas-cli/src/commandUtils/workflow/logs/parseLogs.ts +++ /dev/null @@ -1,83 +0,0 @@ -import { fetchRawLogsForJobAsync } from './fetchLogs'; -import { WorkflowJobResult, WorkflowLogs, WorkflowRawLogLine } from '../types'; -import Log from '../../../log'; -import uniqBy from '../../../utils/expodash/uniqBy'; -import { ExpoGraphqlClient } from '../../context/contextUtils/createGraphqlClient'; - -export function parseLogLines(rawLogs: string): { - logLines: WorkflowRawLogLine[]; - errors: Error[]; -} { - const logLines: WorkflowRawLogLine[] = []; - const errors: Error[] = []; - - for (const rawLogLine of rawLogs.split('\n')) { - if (!rawLogLine) { - continue; - } - try { - logLines.push(JSON.parse(rawLogLine)); - } catch (err) { - errors.push(err as Error); - } - } - - return { logLines, errors }; -} - -export function mergeLogLines(...logLineGroups: T[][]): T[] { - return uniqBy(logLineGroups.flat().reverse(), logLine => logLine.logId ?? Symbol()).reverse(); -} - -export function groupLogLinesIntoSteps( - logLines: WorkflowRawLogLine[], - accumulator: WorkflowLogs = new Map() -): WorkflowLogs { - for (const logLine of logLines) { - const { buildStepDisplayName, buildStepId, phase, time, msg, result, marker, err } = logLine; - const stepKey = buildStepId ?? buildStepDisplayName ?? phase; - const stepLabel = buildStepDisplayName ?? buildStepId ?? phase; - if (!stepKey || !stepLabel || !msg) { - continue; - } - - let logGroup = accumulator.get(stepKey); - if (!logGroup) { - logGroup = { key: stepKey, label: stepLabel, logLines: [] }; - accumulator.set(stepKey, logGroup); - } - if (buildStepDisplayName) { - logGroup.label = buildStepDisplayName; - } - if (logGroup.result === undefined && (marker === 'end-step' || marker === 'END_PHASE')) { - logGroup.result = result ?? ''; - } - logGroup.logLines.push({ time, msg, result, marker, err }); - } - - return accumulator; -} - -export async function fetchAndParseLogsFromJobAsync( - state: { graphqlClient: ExpoGraphqlClient }, - job: WorkflowJobResult -): Promise { - const rawLogs = await fetchRawLogsForJobAsync(state, job); - if (!rawLogs) { - return null; - } - Log.debug(`rawLogs = ${JSON.stringify(rawLogs, null, 2)}`); - const { logLines, errors } = parseLogLines(rawLogs); - for (const error of errors) { - Log.debug(`Failed to parse a log line: ${error.message}`); - } - return logLines; -} - -export async function fetchAndProcessLogsFromJobAsync( - state: { graphqlClient: ExpoGraphqlClient }, - job: WorkflowJobResult -): Promise { - const logLines = await fetchAndParseLogsFromJobAsync(state, job); - return logLines && groupLogLinesIntoSteps(logLines); -} diff --git a/packages/eas-cli/src/commandUtils/workflow/logs/watcher.ts b/packages/eas-cli/src/commandUtils/workflow/logs/watcher.ts deleted file mode 100644 index 1657e69585..0000000000 --- a/packages/eas-cli/src/commandUtils/workflow/logs/watcher.ts +++ /dev/null @@ -1,210 +0,0 @@ -import { fetchAndParseLogsFromJobAsync, groupLogLinesIntoSteps, mergeLogLines } from './parseLogs'; -import { WorkflowJobResult, WorkflowLogs, WorkflowRawLogLine } from '../types'; -import { - RealtimeLogsTargetInput, - RealtimeLogsTargetType, - WorkflowJobStatus, -} from '../../../graphql/generated'; -import Log from '../../../log'; -import { RealtimeLogsClient, RealtimeLogsSubscription } from '../../../utils/centrifuge'; -import { ExpoGraphqlClient } from '../../context/contextUtils/createGraphqlClient'; -import nullthrows from 'nullthrows'; - -type RealtimeLogLine = WorkflowRawLogLine & { logId: string }; - -function isRealtimeLogLine(entry: unknown): entry is RealtimeLogLine { - return ( - typeof entry === 'object' && - entry !== null && - typeof (entry as Partial).logId === 'string' - ); -} - -export class WorkflowJobLogsState { - private fileLogIds = new Set(); - private realtimeLogLines: RealtimeLogLine[] = []; - private realtimeLogIds = new Set(); - private haveFileLogsCaughtUp = false; - private realtimeLogsRevealed = false; - private groupedLogs: WorkflowLogs = new Map(); - - public ingestFileLogLines(logLines: WorkflowRawLogLine[]): void { - this.fileLogIds = new Set(logLines.flatMap(logLine => (logLine.logId ? [logLine.logId] : []))); - - if ( - !this.haveFileLogsCaughtUp && - this.realtimeLogLines.some(logLine => this.fileLogIds.has(logLine.logId)) - ) { - this.haveFileLogsCaughtUp = true; - } - this.realtimeLogLines = this.realtimeLogLines.filter( - logLine => !this.fileLogIds.has(logLine.logId) - ); - this.realtimeLogIds = new Set(this.realtimeLogLines.map(logLine => logLine.logId)); - - if (this.haveFileLogsCaughtUp) { - this.realtimeLogsRevealed = true; - } - this.groupedLogs = groupLogLinesIntoSteps( - mergeLogLines(logLines, this.realtimeLogsRevealed ? this.realtimeLogLines : []) - ); - } - - public ingestRealtimeLogLines(data: unknown): boolean { - if (!Array.isArray(data)) { - return false; - } - const publishedLogLines = data.filter(isRealtimeLogLine); - if (publishedLogLines.length === 0) { - return false; - } - - if ( - !this.haveFileLogsCaughtUp && - publishedLogLines.some(logLine => this.fileLogIds.has(logLine.logId)) - ) { - this.haveFileLogsCaughtUp = true; - } - - const newLogLines = publishedLogLines.filter( - logLine => !this.fileLogIds.has(logLine.logId) && !this.realtimeLogIds.has(logLine.logId) - ); - for (const logLine of newLogLines) { - this.realtimeLogLines.push(logLine); - this.realtimeLogIds.add(logLine.logId); - } - - if (!this.realtimeLogsRevealed) { - if (this.haveFileLogsCaughtUp) { - this.revealRealtimeLogs(); - } - } else if (newLogLines.length > 0) { - groupLogLinesIntoSteps(newLogLines, this.groupedLogs); - } - - return true; - } - - public markCompleted(): void { - this.revealRealtimeLogs(); - } - - public getLogs(): WorkflowLogs { - return this.groupedLogs; - } - - private revealRealtimeLogs(): void { - if (this.realtimeLogsRevealed) { - return; - } - this.realtimeLogsRevealed = true; - groupLogLinesIntoSteps(this.realtimeLogLines, this.groupedLogs); - } -} - -type TrackedJob = { - logsState: WorkflowJobLogsState; - subscription: RealtimeLogsSubscription | null; -}; - -export function realtimeLogsTargetForJob(job: WorkflowJobResult): RealtimeLogsTargetInput | null { - if (job.turtleJobRun?.id) { - return { type: RealtimeLogsTargetType.JobRun, id: job.turtleJobRun.id }; - } - const buildId = job.turtleBuild?.id ?? job.outputs?.build_id; - if (buildId) { - return { type: RealtimeLogsTargetType.Build, id: buildId }; - } - return null; -} - -export class WorkflowRunLogsWatcher { - private readonly trackedJobs = new Map(); - private realtimeLogsClient?: RealtimeLogsClient | null; - - constructor( - private readonly graphqlClient: ExpoGraphqlClient, - private readonly createRealtimeLogsClient: () => RealtimeLogsClient | null, - private readonly onRealtimeLogs: () => void - ) {} - - public async syncJobsAsync( - jobs: WorkflowJobResult[] - ): Promise> { - await Promise.all(jobs.map(job => this.syncJobAsync(job))); - return new Map( - jobs.map(job => [ - job.id, - nullthrows( - this.trackedJobs.get(job.id), - 'job has to be in tracked jobs after it was synced' - ).logsState, - ]) - ); - } - - public close(): void { - for (const trackedJob of this.trackedJobs.values()) { - trackedJob.subscription?.close(); - trackedJob.subscription = null; - } - this.realtimeLogsClient?.close(); - } - - private async syncJobAsync(job: WorkflowJobResult): Promise { - let trackedJob = this.trackedJobs.get(job.id); - if (!trackedJob) { - trackedJob = { logsState: new WorkflowJobLogsState(), subscription: null }; - this.trackedJobs.set(job.id, trackedJob); - } - - const workflowInProgress = job.status === WorkflowJobStatus.InProgress; - if (!workflowInProgress) { - trackedJob.subscription?.close(); - trackedJob.subscription = null; - return; - } - - await Promise.all([ - trackedJob.subscription ? Promise.resolve() : this.subscribeAsync(job, trackedJob), - this.fetchLogsAsync(job, trackedJob), - ]); - } - - private async fetchLogsAsync(job: WorkflowJobResult, trackedJob: TrackedJob): Promise { - try { - const logLines = await fetchAndParseLogsFromJobAsync( - { graphqlClient: this.graphqlClient }, - job - ); - if (logLines) { - trackedJob.logsState.ingestFileLogLines(logLines); - } - } catch (err: any) { - Log.debug(`Failed to fetch logs for job ${job.id}: ${err.message}`); - } - } - - private getRealtimeLogsClient(): RealtimeLogsClient | null { - if (this.realtimeLogsClient === undefined) { - this.realtimeLogsClient = this.createRealtimeLogsClient(); - } - return this.realtimeLogsClient; - } - - private async subscribeAsync(job: WorkflowJobResult, trackedJob: TrackedJob): Promise { - const target = realtimeLogsTargetForJob(job); - if (!target) { - return; - } - const realtimeLogsClient = this.getRealtimeLogsClient(); - if (!realtimeLogsClient) { - return; - } - trackedJob.subscription = await realtimeLogsClient.subscribeAsync({ target }, data => { - if (trackedJob.logsState.ingestRealtimeLogLines(data)) { - this.onRealtimeLogs(); - } - }); - } -} diff --git a/packages/eas-cli/src/commandUtils/workflow/stateMachine.ts b/packages/eas-cli/src/commandUtils/workflow/stateMachine.ts index c62a762927..9a3be4a858 100644 --- a/packages/eas-cli/src/commandUtils/workflow/stateMachine.ts +++ b/packages/eas-cli/src/commandUtils/workflow/stateMachine.ts @@ -1,13 +1,10 @@ import { Choice } from 'prompts'; -import { WorkflowJobResult, WorkflowLogs } from './types'; -import { fetchAndProcessLogsFromJobAsync } from './logs/parseLogs'; -import { - choiceFromWorkflowJob, - choiceFromWorkflowRun, - choicesFromWorkflowLogs, - processWorkflowRuns, -} from './utils'; +import { WorkflowJobResult } from './types'; +import { fetchAndProcessLogsFromJobAsync } from './logs'; +import { choicesFromJobLogs } from '../logs/format'; +import { JobLogs } from '../logs/types'; +import { choiceFromWorkflowJob, choiceFromWorkflowRun, processWorkflowRuns } from './utils'; import { AppQuery } from '../../graphql/queries/AppQuery'; import { WorkflowJobQuery } from '../../graphql/queries/WorkflowJobQuery'; import { WorkflowRunQuery } from '../../graphql/queries/WorkflowRunQuery'; @@ -58,7 +55,7 @@ export type WorkflowCommandSelectionState = { jobId?: string; step?: string; job?: WorkflowJobResult; - logs?: WorkflowLogs | null; + logs?: JobLogs | null; message?: string; }; @@ -140,7 +137,7 @@ export function moveToWorkflowSelectionFinishedState( previousState: WorkflowCommandSelectionState, params: { step: string; - logs: WorkflowLogs; + logs: JobLogs; } ): WorkflowCommandSelectionState { return moveToNewWorkflowCommandSelectionState( @@ -276,7 +273,7 @@ export const workflowStepSelectionAction: WorkflowCommandSelectionAction = async return moveToWorkflowSelectionFinishedState(prevState, { step: '', logs }); } const choices: Choice[] = [ - ...choicesFromWorkflowLogs(logs), + ...choicesFromJobLogs(logs), { title: 'Go back and select a different workflow job', value: 'go-back', diff --git a/packages/eas-cli/src/commandUtils/workflow/types.ts b/packages/eas-cli/src/commandUtils/workflow/types.ts index 7598e47cbb..b519fbe42d 100644 --- a/packages/eas-cli/src/commandUtils/workflow/types.ts +++ b/packages/eas-cli/src/commandUtils/workflow/types.ts @@ -41,27 +41,3 @@ export type WorkflowRunWithJobsResult = WorkflowRunResult & { jobs: WorkflowJobResult[]; logs?: string; }; - -export type WorkflowRawLogLine = { - logId?: string; - buildStepId?: string; - buildStepDisplayName?: string; - phase?: string; - time?: string; - msg?: string; - result?: string; - marker?: string; - err?: any; -}; - -export type WorkflowLogLine = Pick & - Required>; - -export type StepLogs = { - key: string; - label: string; - result?: string; - logLines: WorkflowLogLine[]; -}; - -export type WorkflowLogs = Map; diff --git a/packages/eas-cli/src/commandUtils/workflow/utils.ts b/packages/eas-cli/src/commandUtils/workflow/utils.ts index e1bec9acec..0b6875b4f2 100644 --- a/packages/eas-cli/src/commandUtils/workflow/utils.ts +++ b/packages/eas-cli/src/commandUtils/workflow/utils.ts @@ -1,14 +1,8 @@ import chalk from 'chalk'; import * as fs from 'node:fs'; -import { fetchAndProcessLogsFromJobAsync } from './logs/parseLogs'; -import { - WorkflowJobResult, - WorkflowLogLine, - WorkflowLogs, - WorkflowRunResult, - WorkflowTriggerType, -} from './types'; +import { fetchAndProcessLogsFromJobAsync, logSourceForWorkflowJob } from './logs'; +import { WorkflowJobResult, WorkflowRunResult, WorkflowTriggerType } from './types'; import { WorkflowJobStatus, WorkflowRunByIdQuery, @@ -17,7 +11,9 @@ import { WorkflowRunStatus, WorkflowRunTriggerEventType, } from '../../graphql/generated'; -import { WorkflowRunLogsWatcher } from './logs/watcher'; +import { choicesFromJobLogs, stepLogTail } from '../logs/format'; +import { JobLogs } from '../logs/types'; +import { LogsWatcher } from '../logs/watcher'; import { WorkflowRunQuery } from '../../graphql/queries/WorkflowRunQuery'; import Log from '../../log'; import { ora, updateSpinnerText } from '../../ora'; @@ -83,20 +79,6 @@ export function choiceFromWorkflowJob(job: WorkflowJobResult, index: number): Ch }; } -export function choicesFromWorkflowLogs( - logs: WorkflowLogs -): (Choice & { name: string; status: string; logLines: WorkflowLogLine[] | undefined })[] { - return Array.from(logs.values()) - .map(({ key, label, result, logLines }) => ({ - title: `${label} - ${result ?? ''}`, - name: label, - status: result ?? '', - value: key, - logLines, - })) - .filter(step => step.status !== 'skipped'); -} - export function processWorkflowRuns(runs: WorkflowRunFragment[]): WorkflowRunResult[] { return runs.map(run => { const finishedAt = run.status === WorkflowRunStatus.InProgress ? null : run.updatedAt; @@ -157,18 +139,9 @@ type WorkflowRunWithJobs = WorkflowRunByIdWithJobsQuery['workflowRuns']['byId']; type JobWithLogs = { job: WorkflowRunWithJobs['jobs'][number]; - logs: WorkflowLogs; + logs: JobLogs; }; -function stepLogTail( - step: { logLines?: WorkflowLogLine[] }, - maxLogLines: number // -1 means no limit -): string[] { - const logLines = step.logLines ?? []; - const tail = maxLogLines === -1 ? logLines : logLines.slice(-maxLogLines); - return tail.map(line => line.msg); -} - export async function logsForFailedWorkflowRunAsync( graphqlClient: ExpoGraphqlClient, workflowRun: WorkflowRunWithJobs @@ -195,7 +168,7 @@ export function formatActiveWorkflowRun( if (job.status !== WorkflowJobStatus.InProgress) { continue; } - const steps = choicesFromWorkflowLogs(logs); + const steps = choicesFromJobLogs(logs); if (steps.length === 0) { continue; } @@ -222,7 +195,7 @@ export function formatFailedWorkflowRun( for (const { job, logs } of jobLogs) { statusValues.push({ label: '', value: '' }); statusValues.push({ label: ' Failed job', value: job.name }); - const steps = choicesFromWorkflowLogs(logs); + const steps = choicesFromJobLogs(logs); const failedStep = steps.find(step => step.status === 'fail' || step.status === 'failed'); if (!failedStep) { continue; @@ -290,8 +263,7 @@ export async function showWorkflowStatusAsync( prefixText: chalk`{bold.yellow Workflow run is waiting to start:}`, }); - const watcher = new WorkflowRunLogsWatcher( - graphqlClient, + const watcher = new LogsWatcher( () => createRealtimeLogsClient(graphqlClient), () => { renderActiveWorkflowRun(); @@ -316,12 +288,14 @@ export async function showWorkflowStatusAsync( updateSpinnerText(spinner, { prefixText: chalk`{bold.green Workflow run is in progress:}`, }); - const logsStates = await watcher.syncJobsAsync(workflowRun.jobs); + const logsStates = await watcher.syncAsync( + workflowRun.jobs.map(job => logSourceForWorkflowJob(graphqlClient, job)) + ); for (const job of workflowRun.jobs) { if (isJobCompleted(job.status)) { nullthrows( logsStates.get(job.id), - 'syncJobsAsync must have been called before markCompleted' + 'syncAsync must have been called before markCompleted' ).markCompleted(); } } @@ -331,7 +305,7 @@ export async function showWorkflowStatusAsync( job, logs: nullthrows( logsStates.get(job.id), - 'syncJobsAsync must have been called before getLogs' + 'syncAsync must have been called before getLogs' ).getLogs(), })) ); diff --git a/packages/eas-cli/src/commands/workflow/logs.ts b/packages/eas-cli/src/commands/workflow/logs.ts index 51db3d0c08..aac3597acd 100644 --- a/packages/eas-cli/src/commands/workflow/logs.ts +++ b/packages/eas-cli/src/commands/workflow/logs.ts @@ -7,11 +7,11 @@ import { WorkflowCommandSelectionStateValue, executeWorkflowSelectionActionsAsync, } from '../../commandUtils/workflow/stateMachine'; -import { WorkflowLogLine, WorkflowLogs } from '../../commandUtils/workflow/types'; +import { JobLogs, LogLine } from '../../commandUtils/logs/types'; import Log from '../../log'; import { enableJsonOutput, printJsonOnlyOutput } from '../../utils/json'; -function printLogsForAllSteps(logs: WorkflowLogs): void { +function printLogsForAllSteps(logs: JobLogs): void { [...logs.values()].forEach(({ label, logLines }) => { if (logLines.length === 0) { return; @@ -85,7 +85,7 @@ export default class WorkflowLogView extends EasCommand { return; } - const logs = finalSelectionState?.logs as unknown as WorkflowLogs | null; + const logs = finalSelectionState?.logs; if (allSteps) { if (logs) { if (flags.json) { @@ -103,7 +103,7 @@ export default class WorkflowLogView extends EasCommand { const logGroup = logs?.get(selectedStep); if (logGroup) { if (flags.json) { - const output: { [key: string]: WorkflowLogLine[] | null } = {}; + const output: { [key: string]: LogLine[] | null } = {}; output[selectedStep] = logGroup.logLines; printJsonOnlyOutput(output); } else { diff --git a/packages/eas-cli/src/ora.ts b/packages/eas-cli/src/ora.ts index 707614c65e..6f5bd877ef 100644 --- a/packages/eas-cli/src/ora.ts +++ b/packages/eas-cli/src/ora.ts @@ -17,6 +17,10 @@ const errorReal = console.error; const isCi = boolish('CI', false); +export function isSpinnerEnabled(): boolean { + return !(Log.isDebug || !process.stdin.isTTY || isCi); +} + /** * A custom ora spinner that sends the stream to stdout in CI, or non-TTY, instead of stderr (the default). * @@ -25,7 +29,7 @@ const isCi = boolish('CI', false); */ export function ora(options?: Options | string): Ora { const inputOptions = typeof options === 'string' ? { text: options } : (options ?? {}); - const disabled = Log.isDebug || !process.stdin.isTTY || isCi; + const disabled = !isSpinnerEnabled(); const spinner = oraReal({ // Ensure our non-interactive mode emulates CI mode. isEnabled: !disabled,