diff --git a/src/graphql/queries.ts b/src/graphql/queries.ts index 407fcd8..cdef046 100755 --- a/src/graphql/queries.ts +++ b/src/graphql/queries.ts @@ -128,6 +128,9 @@ const deploymentQuery: DocumentNode = gql` } `; +// Legacy timestamp-paged deployment logs. Retained only as the fallback for +// regions whose logs service predates getDeploymentLogsV2 — see +// LogPolling.deploymentLogs. const deploymentLogsQuery: DocumentNode = gql` query GetLogs($deploymentUid: ID!, $timestamp: String) { getLogs(deploymentUid: $deploymentUid, timestamp: $timestamp) { @@ -139,6 +142,26 @@ const deploymentLogsQuery: DocumentNode = gql` } `; +// Cursor-paged deployment logs. The cursor is search_after over +// [timestampMs, _id], so paging can't skip or duplicate logs that share a +// millisecond — which timestamp paging cannot express. +const deploymentLogsV2Query: DocumentNode = gql` + query GetDeploymentLogsV2($query: DeploymentLogsV2QueryInput!) { + getDeploymentLogsV2(query: $query) { + logs { + deploymentUid + message + stage + timestamp + } + pageInfo { + hasNewer + newestCursor + } + } + } +`; + const serverlessLogsQuery: DocumentNode = gql` query GetServerlessLogsV2($query: QueryLogMessagesV2InputType!) { getServerlessLogsV2(query: $query) { @@ -206,6 +229,7 @@ export { cmsEnvironmentVariablesQuery, deploymentQuery, deploymentLogsQuery, + deploymentLogsV2Query, serverlessLogsQuery, latestLiveDeploymentQuery, environmentsQuery, diff --git a/src/util/logs-polling-utilities.test.ts b/src/util/logs-polling-utilities.test.ts index 83494e0..fbb3c8d 100644 --- a/src/util/logs-polling-utilities.test.ts +++ b/src/util/logs-polling-utilities.test.ts @@ -6,8 +6,15 @@ import defaultConfig from '../config'; type LogPollingCtor = typeof import('./logs-polling-utilities').default; jest.mock('@contentstack/cli-utilities', () => cliUtilitiesJestMock); +// The terminal-status branch awaits sleep(1_000) before it stops polling. jest.mock('timers/promises', () => ({ setTimeout: jest.fn().mockResolvedValue(undefined) })); +const CONFIG = { + deployment: 'd1', + environment: 'e1', + pollingInterval: 1000, +}; + function makeWatchQuery() { let subscriber: (result: any) => void = () => {}; return { @@ -21,11 +28,12 @@ function makeWatchQuery() { }; } -const CONFIG = { - deployment: 'd1', - environment: 'e1', - pollingInterval: 1000, -}; +function page(logs: any[], pageInfo: Record = {}) { + return { + logs, + pageInfo: { hasNewer: null, newestCursor: null, ...pageInfo }, + }; +} function getDeploymentStatus(LogPollingClass: LogPollingCtor, watchQuery: jest.Mock): void { new LogPollingClass({ @@ -195,3 +203,126 @@ describe('cancelled deployment stops log polling', () => { expect(defaultConfig.deploymentStatus).toContain('CANCELLED'); }); }); + +describe('deployment logs use cursor paging (getDeploymentLogsV2)', () => { + function buildInstance(deploymentStatus: string[] = ['DEPLOYED']) { + const statusWatchQuery = makeWatchQuery(); + const logsWatchQuery = makeWatchQuery(); + const fallbackWatchQuery = makeWatchQuery(); + const logsClientWatchQuery = jest + .fn() + .mockReturnValueOnce(logsWatchQuery) + .mockReturnValue(fallbackWatchQuery); + const instance = new LogPolling({ + apolloManageClient: { watchQuery: jest.fn().mockReturnValue(statusWatchQuery) } as any, + apolloLogsClient: { watchQuery: logsClientWatchQuery } as any, + config: { deployment: 'd1', environment: 'e1', pollingInterval: 1000, deploymentStatus } as any, + $event: new EventEmitter(), + }); + return { instance, statusWatchQuery, logsWatchQuery, fallbackWatchQuery, logsClientWatchQuery }; + } + + it('opens with sortDirection desc and no cursor, tailing the newest page like the legacy query did', async () => { + const { instance, logsClientWatchQuery } = buildInstance(); + + await instance.deploymentLogs(); + + const { query } = logsClientWatchQuery.mock.calls[0][0].variables; + expect(query).toEqual({ deploymentUid: 'd1', limit: 5000, sortDirection: 'desc' }); + expect(query).not.toHaveProperty('cursor'); + }); + + it('advances by cursor in asc order — never by timestamp', async () => { + const { instance, statusWatchQuery, logsWatchQuery } = buildInstance(['DEPLOYED']); + + await instance.deploymentLogs(); + statusWatchQuery.emit({ data: { Deployment: { status: 'LIVE' } } }); + await logsWatchQuery.emit({ + data: { + getDeploymentLogsV2: page([{ message: 'build started', timestamp: '2026-08-06T10:00:00.123Z' }], { + newestCursor: '[1775462400123,"abc"]', + }), + }, + }); + + expect(logsWatchQuery.setVariables).toHaveBeenCalledWith({ + query: { + deploymentUid: 'd1', + limit: 5000, + sortDirection: 'asc', + cursor: '[1775462400123,"abc"]', + }, + }); + }); + + it('does not re-arm when the cursor has not moved, so a repeated page cannot loop forever', async () => { + const { instance, statusWatchQuery, logsWatchQuery } = buildInstance(['DEPLOYED']); + + await instance.deploymentLogs(); + statusWatchQuery.emit({ data: { Deployment: { status: 'LIVE' } } }); + const samePage = { + data: { + getDeploymentLogsV2: page([{ message: 'x', timestamp: '2026-08-06T10:00:00.000Z' }], { + newestCursor: 'c1', + }), + }, + }; + await logsWatchQuery.emit(samePage); + await logsWatchQuery.emit(samePage); + + expect(logsWatchQuery.setVariables).toHaveBeenCalledTimes(1); + }); + + it('keeps draining past a terminal status while hasNewer reports another page', async () => { + const { instance, statusWatchQuery, logsWatchQuery } = buildInstance(['DEPLOYED']); + + await instance.deploymentLogs(); + statusWatchQuery.emit({ data: { Deployment: { status: 'DEPLOYED' } } }); + await logsWatchQuery.emit({ + data: { getDeploymentLogsV2: page([{ message: 'a', timestamp: 'x' }], { hasNewer: true, newestCursor: 'c1' }) }, + }); + + expect(logsWatchQuery.stopPolling).not.toHaveBeenCalled(); + + await logsWatchQuery.emit({ + data: { getDeploymentLogsV2: page([{ message: 'b', timestamp: 'y' }], { hasNewer: false, newestCursor: 'c2' }) }, + }); + + expect(logsWatchQuery.stopPolling).toHaveBeenCalledTimes(1); + }); + + it('falls back to the legacy getLogs query when the region has no V2 field', async () => { + const { instance, logsWatchQuery, fallbackWatchQuery, logsClientWatchQuery } = buildInstance(); + const errors: any[] = []; + (instance as any).$event.on('deployment-logs', (e: any) => { + if (e.msgType === 'error') errors.push(e.message); + }); + + await instance.deploymentLogs(); + await logsWatchQuery.emit({ + data: null, + error: { message: 'Cannot query field "getDeploymentLogsV2" on type "Query".' }, + }); + + expect(logsWatchQuery.stopPolling).toHaveBeenCalledTimes(1); + expect(logsClientWatchQuery).toHaveBeenCalledTimes(2); + expect(logsClientWatchQuery.mock.calls[1][0].variables).toEqual({ deploymentUid: 'd1' }); + expect(fallbackWatchQuery.subscribe).toHaveBeenCalledTimes(1); + // The schema mismatch is not the user's problem — nothing surfaces. + expect(errors).toHaveLength(0); + }); + + it('does not demote to the legacy query on a transient network error', async () => { + const { instance, logsWatchQuery, logsClientWatchQuery } = buildInstance(); + const errors: any[] = []; + (instance as any).$event.on('deployment-logs', (e: any) => { + if (e.msgType === 'error') errors.push(e.message); + }); + + await instance.deploymentLogs(); + await logsWatchQuery.emit({ data: null, error: { message: 'Failed to fetch' } }); + + expect(logsClientWatchQuery).toHaveBeenCalledTimes(1); + expect(errors).toContain('Failed to fetch'); + }); +}); diff --git a/src/util/logs-polling-utilities.ts b/src/util/logs-polling-utilities.ts index 5536309..fdc2861 100755 --- a/src/util/logs-polling-utilities.ts +++ b/src/util/logs-polling-utilities.ts @@ -5,13 +5,30 @@ import { ApolloClient, ObservableQuery } from '@apollo/client/core'; import { Ora } from 'ora'; import { LogPollingInput, ConfigType } from '../types'; -import { deploymentQuery, deploymentLogsQuery, serverlessLogsQuery } from '../graphql'; +import { + deploymentQuery, + deploymentLogsQuery, + deploymentLogsV2Query, + serverlessLogsQuery, +} from '../graphql'; import { setTimeout as sleep } from 'timers/promises'; import { isNotDevelopment } from './apollo-client'; const requireApolloDeprecation = createRequire(__filename); export default class LogPolling { + // Matches the logs service's LAST_FEW_LOGS_SIZE, which is both the cap the + // legacy getLogs query tailed on its first call and the ceiling + // getDeploymentLogsV2 clamps `limit` to. Keeps the first page identical to + // what the timestamp query used to return. + private static readonly DEPLOYMENT_LOGS_PAGE_SIZE = 5_000; + + // Only a schema mismatch means "this region has no V2 yet". Network blips and + // auth failures must NOT match, or a transient error would silently demote + // the session to the legacy query. + private static readonly V2_UNSUPPORTED_PATTERN = + /cannot query field ["'`]?getDeploymentLogsV2|unknown type ["'`]?DeploymentLogsV2QueryInput/i; + private config: ConfigType; private $event!: EventEmitter; private apolloLogsClient!: ApolloClient; @@ -20,6 +37,10 @@ export default class LogPolling { public startTime!: number; public endTime!: number; public loader!: Ora | void; + // Opaque search_after cursor for the newest log already emitted. Null until + // the first non-empty page arrives. + private deploymentLogsCursor: string | null = null; + private deploymentLogsV1FallbackStarted = false; constructor(params: LogPollingInput) { const { apolloLogsClient, apolloManageClient, config, $event } = params; @@ -159,6 +180,71 @@ export default class LogPolling { statusWatchQuery.stopPolling(); } }); + const logsWatchQuery = this.withDeprecationsDisabled(() => { + return this.apolloLogsClient.watchQuery({ + fetchPolicy: 'network-only', + query: deploymentLogsV2Query, + variables: { + query: this.deploymentLogsV2Variables(), + }, + pollInterval: this.config.pollingInterval, + errorPolicy: 'all', + }); + }); + this.subscribeDeploymentLogsV2(logsWatchQuery); + } + + /** + * @method deploymentLogsV2Variables - build the getDeploymentLogsV2 query input + * + * With no cursor yet, `desc` tails the newest page — the same thing the legacy + * getLogs query did when called without a timestamp. Once a cursor exists, + * `asc` walks strictly forward from it. + * + * @return {*} {Record} + * @memberof LogPolling + */ + private deploymentLogsV2Variables(): Record { + return { + deploymentUid: this.config.deployment, + limit: LogPolling.DEPLOYMENT_LOGS_PAGE_SIZE, + sortDirection: this.deploymentLogsCursor ? 'asc' : 'desc', + ...(this.deploymentLogsCursor ? { cursor: this.deploymentLogsCursor } : {}), + }; + } + + /** + * @method isUnsupportedQueryError - detect a logs service with no getDeploymentLogsV2 + * + * @return {*} {boolean} + * @memberof LogPolling + */ + private isUnsupportedQueryError(error: any, errors?: readonly any[] | null): boolean { + const messages: string[] = []; + if (error?.message) messages.push(error.message); + for (const graphQLError of error?.graphQLErrors ?? []) { + if (graphQLError?.message) messages.push(graphQLError.message); + } + for (const graphQLError of errors ?? []) { + if (graphQLError?.message) messages.push(graphQLError.message); + } + return messages.some((message) => LogPolling.V2_UNSUPPORTED_PATTERN.test(message)); + } + + /** + * @method fallBackToDeploymentLogsV1 - re-poll through the legacy getLogs query + * + * Reached only when the region's logs service does not expose + * getDeploymentLogsV2. Delegates to the untouched V1 subscriber so behaviour + * there is exactly what it was before cursor paging landed. + * + * @return {*} {void} + * @memberof LogPolling + */ + private fallBackToDeploymentLogsV1(): void { + if (this.deploymentLogsV1FallbackStarted) return; + this.deploymentLogsV1FallbackStarted = true; + const logsWatchQuery = this.withDeprecationsDisabled(() => { return this.apolloLogsClient.watchQuery({ fetchPolicy: 'network-only', @@ -173,6 +259,100 @@ export default class LogPolling { this.subscribeDeploymentLogs(logsWatchQuery); } + /** + * @method subscribeDeploymentLogsV2 - subscribe cursor-paged deployment logs + * + * @return {*} {void} + * @memberof LogPolling + */ + subscribeDeploymentLogsV2( + logsWatchQuery: ObservableQuery< + any, + { + query: Record; + } + >, + ): void { + logsWatchQuery.subscribe(async({ data, errors, error }) => { + if(!this.loader){ + this.loader = cliux.loaderV2('Loading deployment logs...'); + } + // Demote to the legacy query rather than surfacing a schema error the + // user can do nothing about. + if (this.isUnsupportedQueryError(error, errors)) { + logsWatchQuery.stopPolling(); + this.fallBackToDeploymentLogsV1(); + return; + } + if (error) { + this.loader=cliux.loaderV2('done', this.loader); + this.$event.emit('deployment-logs', { + message: error?.message, + msgType: 'error', + }); + this.$event.emit('deployment-logs', { + message: 'DONE', + msgType: 'debug', + }); + logsWatchQuery.stopPolling(); + } + if (errors?.length && data === null) { + this.loader=cliux.loaderV2('done', this.loader); + this.$event.emit('deployment-logs', { + message: errors, + msgType: 'error', + }); + this.$event.emit('deployment-logs', { + message: 'DONE', + msgType: 'debug', + }); + logsWatchQuery.stopPolling(); + } + if (this.deploymentStatus) { + const page = data?.getDeploymentLogsV2; + const logsData = page?.logs; + // Authoritative only for asc queries; null on the initial desc page. + const hasNewer = page?.pageInfo?.hasNewer === true; + let advanced = false; + + if (logsData?.length) { + this.loader=cliux.loaderV2('done', this.loader); + this.$event.emit('deployment-logs', { + message: logsData, + msgType: 'info', + }); + + const nextCursor = page?.pageInfo?.newestCursor; + // Re-arming on an unchanged cursor would refetch the same page for + // the rest of the session, so only advance when it actually moved. + if (nextCursor && nextCursor !== this.deploymentLogsCursor) { + this.deploymentLogsCursor = nextCursor; + advanced = true; + logsWatchQuery.setVariables({ + query: this.deploymentLogsV2Variables(), + } as any); + } + } + + // A full page means the build wrote more than one page's worth since the + // last poll — keep draining instead of cutting the tail off at the + // terminal status. `advanced` guards the case where more logs exist but + // the cursor didn't move, which would otherwise never stop. + if (this.config.deploymentStatus.includes(this.deploymentStatus) && !(hasNewer && advanced)) { + await sleep(1_000); + logsWatchQuery.stopPolling(); + this.$event.emit('deployment-logs', { + message: 'DONE', + msgType: 'debug', + }); + if(this.loader){ + this.loader=cliux.loaderV2('done', this.loader); + } + } + } + }); + } + /** * @method subscribeDeploymentLogs - subscribe deployment logs *