diff --git a/packages/cli/src/commands/deploy.ts b/packages/cli/src/commands/deploy.ts index da157a73..3db45744 100644 --- a/packages/cli/src/commands/deploy.ts +++ b/packages/cli/src/commands/deploy.ts @@ -17,6 +17,7 @@ import { splitConfigFilePath, getGitInformation } from '../services/util' import commonMessages from '../messages/common-messages' import { ProjectDeployResponse } from '../rest/projects' import { uploadSnapshots } from '../services/snapshot-service' +import { rootLogger } from '../services/logger' // eslint-disable-next-line no-restricted-syntax enum ResourceDeployStatus { @@ -58,6 +59,12 @@ export default class Deploy extends AuthCommand { } async run (): Promise { + const logger = rootLogger.child({ + cli: { + cmd: 'deploy', + }, + }) + ux.action.start('Parsing your project', undefined, { stdout: true }) const { flags } = await this.parse(Deploy) const { @@ -126,7 +133,21 @@ export default class Deploy extends AuthCommand { } try { - const { data } = await api.projects.deploy({ ...projectPayload, repoInfo }, { dryRun: preview, scheduleOnDeploy }) + const { data } = await api.projects.deploy( + { ...projectPayload, repoInfo }, + { dryRun: preview, scheduleOnDeploy }, + { + onUploadProgress: (event) => { + logger.trace({ + progress: { + sent: event.loaded, + total: event.total, + lengthComputable: event.lengthComputable, + }, + }, 'Project payload upload progress') + }, + }, + ) if (preview || output) { this.log(this.formatPreview(data, project)) } diff --git a/packages/cli/src/commands/test.ts b/packages/cli/src/commands/test.ts index 280283e2..b085d8be 100644 --- a/packages/cli/src/commands/test.ts +++ b/packages/cli/src/commands/test.ts @@ -24,6 +24,7 @@ import commonMessages from '../messages/common-messages' import { TestResultsShortLinks } from '../rest/test-sessions' import { printLn, formatCheckTitle, CheckStatus } from '../reporters/util' import { uploadSnapshots } from '../services/snapshot-service' +import { rootLogger } from '../services/logger' const DEFAULT_REGION = 'eu-central-1' const MAX_RETRIES = 3 @@ -118,6 +119,12 @@ export default class Test extends AuthCommand { static strict = false async run (): Promise { + const logger = rootLogger.child({ + cli: { + cmd: 'test', + }, + }) + ux.action.start('Parsing your project', undefined, { stdout: true }) const { flags, argv } = await this.parse(Test) @@ -154,6 +161,7 @@ export default class Test extends AuthCommand { const reporterTypes = this.prepareReportersTypes(reporterFlag as ReporterType, checklyConfig.cli?.reporters) const { data: availableRuntimes } = await api.runtimes.getAll() + logger.debug('Parsing project') const project = await parseProject({ directory: configDirectory, projectLogicalId: checklyConfig.logicalId, @@ -171,6 +179,8 @@ export default class Test extends AuthCommand { }, > {}), checklyConfigConstructs, }) + + logger.debug({ project }, 'Finished parsing project') const checks = Object.entries(project.data.check) .filter(([, check]) => { return !(check instanceof HeartbeatCheck) @@ -211,11 +221,47 @@ export default class Test extends AuthCommand { return check }) + // Separate browser checks for snapshot uploads. + const browserChecks: Array = [] for (const check of checks) { if (!(check instanceof BrowserCheck)) { continue } - check.snapshots = await uploadSnapshots(check.rawSnapshots) + if (!check.rawSnapshots?.length) { + logger.trace( + { check: { logicalId: check.logicalId } }, + 'Check has no snapshots to upload', + ) + continue + } + browserChecks.push(check) + } + + logger.info( + { count: browserChecks.length }, + 'Collected all snapshots to upload', + ) + + for (const check of browserChecks) { + const sublogger = logger.child( + { check: { logicalId: check.logicalId } }, + ) + sublogger.info( + { rawSnapshots: check.rawSnapshots }, + 'Uploading check snapshots', + ) + check.snapshots = await uploadSnapshots(check.rawSnapshots, { + onUploadProgress: (snapshot, event) => { + sublogger.trace({ + snapshot, + progress: { + sent: event.loaded, + total: event.total, + lengthComputable: event.lengthComputable, + }, + }, 'Snapshot upload progress') + }, + }) } ux.action.stop() @@ -236,6 +282,7 @@ export default class Test extends AuthCommand { const testRetryStrategy = this.prepareTestRetryStrategy(retries, checklyConfig?.cli?.retries) const runner = new TestRunner( + logger, config.getAccountId(), project, checks, @@ -251,9 +298,9 @@ export default class Test extends AuthCommand { ) runner.on(Events.RUN_STARTED, - (checks: Array<{ check: any, sequenceId: SequenceId }>, testSessionId: string) => - reporters.forEach(r => r.onBegin(checks, testSessionId)), - ) + (checks: Array<{ check: any, sequenceId: SequenceId }>, testSessionId: string) => { + reporters.forEach(r => r.onBegin(checks, testSessionId)) + }) runner.on(Events.CHECK_INPROGRESS, (check: any, sequenceId: SequenceId) => { reporters.forEach(r => r.onCheckInProgress(check, sequenceId)) diff --git a/packages/cli/src/commands/trigger.ts b/packages/cli/src/commands/trigger.ts index 0315e7e1..38e7080a 100644 --- a/packages/cli/src/commands/trigger.ts +++ b/packages/cli/src/commands/trigger.ts @@ -19,6 +19,7 @@ import { createReporters, ReporterType } from '../reporters/reporter' import { printLn } from '../reporters/util' import { TestResultsShortLinks } from '../rest/test-sessions' import { Session, RetryStrategyBuilder } from '../constructs' +import { rootLogger } from '../services/logger' const DEFAULT_REGION = 'eu-central-1' const MAX_RETRIES = 3 @@ -88,6 +89,12 @@ export default class Trigger extends AuthCommand { } async run (): Promise { + const logger = rootLogger.child({ + cli: { + cmd: 'trigger', + }, + }) + const { flags } = await this.parse(Trigger) const { location: runLocation, @@ -124,6 +131,7 @@ export default class Trigger extends AuthCommand { const ciInfo = getCiInformation() const runner = new TriggerRunner( + logger, config.getAccountId(), timeout, verbose, diff --git a/packages/cli/src/rest/checkly-storage.ts b/packages/cli/src/rest/checkly-storage.ts index 114ab3d7..f36ef3e6 100644 --- a/packages/cli/src/rest/checkly-storage.ts +++ b/packages/cli/src/rest/checkly-storage.ts @@ -1,22 +1,36 @@ -import type { AxiosInstance } from 'axios' +import type { AxiosInstance, AxiosProgressEvent } from 'axios' import type { Readable } from 'node:stream' +type UploadOptions = { + onUploadProgress?: (progressEvent: AxiosProgressEvent) => void +} + +type DownloadOptions = { + onDownloadProgress?: (progressEvent: AxiosProgressEvent) => void +} + class ChecklyStorage { api: AxiosInstance constructor (api: AxiosInstance) { this.api = api } - upload (stream: Readable) { + upload (stream: Readable, options?: UploadOptions) { return this.api.post<{ key: string }>( '/next/checkly-storage/upload', stream, - { headers: { 'Content-Type': 'application/octet-stream' } }, + { + headers: { 'Content-Type': 'application/octet-stream' }, + onUploadProgress: options?.onUploadProgress, + }, ) } - download (key: string) { - return this.api.post('/next/checkly-storage/download', { key }, { responseType: 'stream' }) + download (key: string, options?: DownloadOptions) { + return this.api.post('/next/checkly-storage/download', { key }, { + responseType: 'stream', + onDownloadProgress: options?.onDownloadProgress, + }) } } diff --git a/packages/cli/src/rest/projects.ts b/packages/cli/src/rest/projects.ts index 0e32539c..1b04cec6 100644 --- a/packages/cli/src/rest/projects.ts +++ b/packages/cli/src/rest/projects.ts @@ -1,5 +1,6 @@ -import type { AxiosInstance } from 'axios' +import type { AxiosInstance, AxiosProgressEvent } from 'axios' import type { GitInformation } from '../services/util' +import Deploy from '../commands/deploy' export interface Project { name: string @@ -34,6 +35,10 @@ export interface ProjectDeployResponse { diff: Array } +export type DeployOptions = { + onUploadProgress?: (progressEvent: AxiosProgressEvent) => void +} + class Projects { api: AxiosInstance constructor (api: AxiosInstance) { @@ -56,10 +61,11 @@ class Projects { return this.api.delete(`/next/projects/${logicalId}`) } - deploy (resources: ProjectSync, { dryRun = false, scheduleOnDeploy = true } = {}) { + deploy (resources: ProjectSync, { dryRun = false, scheduleOnDeploy = true } = {}, options?: DeployOptions) { return this.api.post( `/next-v2/projects/deploy?dryRun=${dryRun}&scheduleOnDeploy=${scheduleOnDeploy}`, resources, + { onUploadProgress: options?.onUploadProgress }, ) } } diff --git a/packages/cli/src/rest/test-sessions.ts b/packages/cli/src/rest/test-sessions.ts index cea6eb59..a31df9f2 100644 --- a/packages/cli/src/rest/test-sessions.ts +++ b/packages/cli/src/rest/test-sessions.ts @@ -1,4 +1,4 @@ -import type { AxiosInstance } from 'axios' +import type { AxiosInstance, AxiosProgressEvent } from 'axios' import { GitInformation } from '../services/util' import { RetryStrategy } from '../constructs' @@ -31,14 +31,20 @@ export type TestResultsShortLinks = { screenshotLinks: string[] } +export type RunOptions = { + onUploadProgress?: (progressEvent: AxiosProgressEvent) => void +} + class TestSessions { api: AxiosInstance constructor (api: AxiosInstance) { this.api = api } - run (payload: RunTestSessionRequest) { - return this.api.post('/next/test-sessions/run', payload) + run (payload: RunTestSessionRequest, options?: RunOptions) { + return this.api.post('/next/test-sessions/run', payload, { + onUploadProgress: options?.onUploadProgress, + }) } trigger (payload: TriggerTestSessionRequest) { diff --git a/packages/cli/src/services/abstract-check-runner.ts b/packages/cli/src/services/abstract-check-runner.ts index 73ee504c..cd5965fb 100644 --- a/packages/cli/src/services/abstract-check-runner.ts +++ b/packages/cli/src/services/abstract-check-runner.ts @@ -6,6 +6,7 @@ import { EventEmitter } from 'node:events' import type { MqttClient } from 'mqtt' import type { Region } from '..' import { TestResultsShortLinks } from '../rest/test-sessions' +import type { Logger } from './logger' // eslint-disable-next-line no-restricted-syntax export enum Events { @@ -40,6 +41,8 @@ export const DEFAULT_CHECK_RUN_TIMEOUT_SECONDS = 600 const DEFAULT_SCHEDULING_DELAY_EXCEEDED_MS = 20000 export default abstract class AbstractCheckRunner extends EventEmitter { + originalLogger: Logger + logger: Logger checks: Map testSessionId?: string // If there's an error in the backend and no check result is sent, the check run could block indefinitely. @@ -52,11 +55,14 @@ export default abstract class AbstractCheckRunner extends EventEmitter { queue: PQueue constructor ( + logger: Logger, accountId: string, timeout: number, verbose: boolean, ) { super() + this.originalLogger = logger + this.logger = logger this.checks = new Map() this.timeouts = new Map() this.queue = new PQueue({ autoStart: false, concurrency: 1 }) @@ -72,14 +78,45 @@ export default abstract class AbstractCheckRunner extends EventEmitter { }> async run () { + const checkRunSuiteId = uuid.v4() + + const logger = this.logger = this.originalLogger.child({ + checkRunSuiteId, + }) + let socketClient = null try { - socketClient = await SocketClient.connect() + logger.info('Starting check run') + + socketClient = await SocketClient.connect(logger) + + socketClient.on('close', () => { + logger.debug('MQTT client connection closed') + }) + socketClient.on('connect', () => { + // Note: does not trigger for the initial connection because by this time we're already connected. + logger.debug('MQTT client is connected') + }) + socketClient.on('disconnect', () => { + logger.debug('MQTT client has disconnected') + }) + socketClient.on('end', () => { + logger.debug('MQTT client connection has ended') + }) + socketClient.on('error', (err) => { + logger.warn({ err }, 'MQTT client encountered an error') + }) + socketClient.on('offline', () => { + logger.debug('MQTT client is offline') + }) + socketClient.on('reconnect', () => { + logger.debug('MQTT client is reconnecting') + }) - const checkRunSuiteId = uuid.v4() // Configure the socket listener and allChecksFinished listener before starting checks to avoid race conditions await this.configureResultListener(checkRunSuiteId, socketClient) + logger.info('Scheduling checks') const { testSessionId, checks } = await this.scheduleChecks(checkRunSuiteId) this.testSessionId = testSessionId this.checks = new Map( @@ -98,25 +135,37 @@ export default abstract class AbstractCheckRunner extends EventEmitter { // Otherwise, there could be a race condition causing check results to be missed by `allChecksFinished()`. const allChecksFinished = this.allChecksFinished() /// / Need to structure the checks depending on how it went + + logger.info({ checks, testSessionId }, 'Run started') this.emit(Events.RUN_STARTED, checks, testSessionId) // Start the queue after the test session run rest call is completed to avoid race conditions this.queue.start() + logger.info('Waiting for all checks to finish') await allChecksFinished + + logger.info('All checks have finished') this.emit(Events.RUN_FINISHED, testSessionId) + + logger.info('Check run completed successfully') } catch (err) { + logger.error({ err }, 'Check run failed') this.disableAllTimeouts() this.emit(Events.ERROR, err) } finally { if (socketClient) { + logger.info('Ending connection to MQTT broker') await socketClient.endAsync() } + logger.info('Finished processing check run') } } private async configureResultListener (checkRunSuiteId: string, socketClient: MqttClient): Promise { socketClient.on('message', (topic: string, rawMessage: string|Buffer) => { const message = JSON.parse(rawMessage.toString('utf8')) + this.logger.trace({ message }, 'Received message from MQTT broker') + const topicComponents = topic.split('/') const sequenceId = topicComponents[4] const checkRunId = topicComponents[5] @@ -163,6 +212,20 @@ export default abstract class AbstractCheckRunner extends EventEmitter { } } + emit (eventName: string | symbol, ...args: any[]): boolean { + this.logger.trace( + { + event: { + name: eventName, + args, + }, + }, + 'Runner event', + ) + + return super.emit(eventName, ...args) + } + async processCheckResult (result: any) { const { region, diff --git a/packages/cli/src/services/project-parser.ts b/packages/cli/src/services/project-parser.ts index d38c2fe0..4fbfd29b 100644 --- a/packages/cli/src/services/project-parser.ts +++ b/packages/cli/src/services/project-parser.ts @@ -7,6 +7,7 @@ import { } from '../constructs' import { Ref } from '../constructs/ref' import { CheckConfigDefaults } from './checkly-config-loader' +import { rootLogger } from './logger' import type { Runtime } from '../rest/runtimes' import type { Construct } from '../constructs/construct' diff --git a/packages/cli/src/services/snapshot-service.ts b/packages/cli/src/services/snapshot-service.ts index d4ba238c..f743a6bf 100644 --- a/packages/cli/src/services/snapshot-service.ts +++ b/packages/cli/src/services/snapshot-service.ts @@ -3,6 +3,8 @@ import * as fs from 'node:fs' import * as path from 'node:path' import * as stream from 'node:stream/promises' +import type { AxiosProgressEvent } from 'axios' + import { checklyStorage } from '../rest/api' import { findFilesRecursively, pathToPosix } from './util' @@ -45,7 +47,16 @@ export function detectSnapshots (projectBasePath: string, scriptFilePath: string })) } -export async function uploadSnapshots (rawSnapshots?: Array<{ absolutePath: string, path: string }>) { +type UploadSnapshot = { + absolutePath: string + path: string +} + +type UploadSnapshotOptions = { + onUploadProgress?: (snapshot: UploadSnapshot, event: AxiosProgressEvent) => void +} + +export async function uploadSnapshots (rawSnapshots?: Array, options?: UploadSnapshotOptions) { if (!rawSnapshots?.length) { return [] } @@ -54,7 +65,11 @@ export async function uploadSnapshots (rawSnapshots?: Array<{ absolutePath: stri const snapshots: Array = [] for (const rawSnapshot of rawSnapshots) { const snapshotStream = fs.createReadStream(rawSnapshot.absolutePath) - const { data: { key } } = await checklyStorage.upload(snapshotStream) + const { data: { key } } = await checklyStorage.upload(snapshotStream, { + onUploadProgress: (event) => { + options?.onUploadProgress?.(rawSnapshot, event) + }, + }) snapshots.push({ key, path: rawSnapshot.path }) } return snapshots diff --git a/packages/cli/src/services/socket-client.ts b/packages/cli/src/services/socket-client.ts index 4465da4f..fcd11339 100644 --- a/packages/cli/src/services/socket-client.ts +++ b/packages/cli/src/services/socket-client.ts @@ -3,27 +3,44 @@ import config from '../services/config' // @ts-ignore import { getProxyForUrl } from 'proxy-from-env' import { httpsOverHttp, httpsOverHttps } from 'tunnel' +import type { Logger } from './logger' const isHttps = (protocol: string) => protocol.startsWith('https') const wait = (ms: number) => new Promise((resolve) => setTimeout(resolve, ms)) -async function backOffConnect (url: string, options: mqtt.IClientOptions, retryCount = 0): +async function backOffConnect (logger: Logger, url: string, options: mqtt.IClientOptions, retryCount = 0): Promise { + const sublogger = logger.child({ + retryCount, + url, + }) + try { + sublogger.info('Connecting to MQTT broker') return mqtt.connectAsync(url, options, false) - } catch (error) { + } catch (err) { + sublogger.setBindings({ err }) + sublogger.warn('Failed to connect to MQTT broker') + if (retryCount > 3) { - throw error + sublogger.error('Giving up further connection attempts to MQTT broker') + throw err } + + const ms = 100 * retryCount + sublogger.setBindings({ wait: ms }) + sublogger.info('Scheduling a reconnection attempt to MQTT broker') retryCount += 1 - await wait(100 * retryCount) - return backOffConnect(url, options, retryCount) + await wait(ms) + + // Note: use original logger here since we'll be doing the same operation. + return backOffConnect(logger, url, options, retryCount) } } export class SocketClient { - static connect (): Promise { + static connect (logger: Logger): Promise { const url = config.getMqttUrl() const accountId = config.getAccountId() const apiKey = config.getApiKey() @@ -33,9 +50,18 @@ export class SocketClient { password: apiKey, } + const sublogger = logger.child({ + url, + username: accountId, + password: apiKey, + }) + // Replace wss with https so the get proxy url thing the env path const proxyUrlEnv = getProxyForUrl(url.replace('wss', 'https')) if (proxyUrlEnv) { + sublogger.setBindings({ proxy: proxyUrlEnv }) + sublogger.info('Must use proxy for MQTT broker connection') + const parsedProxyUrl = new URL(proxyUrlEnv) const isProxyHttps = isHttps(parsedProxyUrl.protocol) const proxy: any = { @@ -56,6 +82,6 @@ export class SocketClient { } } } - return backOffConnect(`${url}?authenticationScheme=userApiKey`, options, 0) + return backOffConnect(sublogger, `${url}?authenticationScheme=userApiKey`, options, 0) } } diff --git a/packages/cli/src/services/test-runner.ts b/packages/cli/src/services/test-runner.ts index cb132353..10f69b2e 100644 --- a/packages/cli/src/services/test-runner.ts +++ b/packages/cli/src/services/test-runner.ts @@ -4,6 +4,7 @@ import { GitInformation } from './util' import { Check } from '../constructs/check' import { RetryStrategy, Project } from '../constructs' import { pullSnapshots } from '../services/snapshot-service' +import { Logger } from './logger' import * as uuid from 'uuid' @@ -19,6 +20,7 @@ export default class TestRunner extends AbstractCheckRunner { testRetryStrategy: RetryStrategy | null constructor ( + logger: Logger, accountId: string, project: Project, checks: Check[], @@ -32,7 +34,7 @@ export default class TestRunner extends AbstractCheckRunner { baseDirectory: string, testRetryStrategy: RetryStrategy | null, ) { - super(accountId, timeout, verbose) + super(logger, accountId, timeout, verbose) this.project = project this.checkConstructs = checks this.location = location @@ -75,6 +77,16 @@ export default class TestRunner extends AbstractCheckRunner { repoInfo: this.repoInfo, environment: this.environment, shouldRecord: this.shouldRecord, + }, { + onUploadProgress: (event) => { + this.logger.trace({ + progress: { + sent: event.loaded, + total: event.total, + lengthComputable: event.lengthComputable, + }, + }, 'Test session payload upload progress') + }, }) const { testSessionId, sequenceIds } = data const checks = this.checkConstructs.map(check => ({ check, sequenceId: sequenceIds?.[check.logicalId] })) diff --git a/packages/cli/src/services/trigger-runner.ts b/packages/cli/src/services/trigger-runner.ts index 9d6beba6..e00f1667 100644 --- a/packages/cli/src/services/trigger-runner.ts +++ b/packages/cli/src/services/trigger-runner.ts @@ -2,6 +2,7 @@ import { RetryStrategy } from '../constructs' import { testSessions } from '../rest/api' import AbstractCheckRunner, { RunLocation, SequenceId } from './abstract-check-runner' import { GitInformation } from './util' +import type { Logger } from './logger' export class NoMatchingChecksError extends Error {} @@ -16,6 +17,7 @@ export default class TriggerRunner extends AbstractCheckRunner { testRetryStrategy: RetryStrategy | null constructor ( + logger: Logger, accountId: string, timeout: number, verbose: boolean, @@ -28,7 +30,7 @@ export default class TriggerRunner extends AbstractCheckRunner { testSessionName: string | undefined, testRetryStrategy: RetryStrategy | null, ) { - super(accountId, timeout, verbose) + super(logger, accountId, timeout, verbose) this.shouldRecord = shouldRecord this.location = location this.targetTags = targetTags