From af0ffb5f2173cef12a77699ad60c110753d8db36 Mon Sep 17 00:00:00 2001 From: Simo Kinnunen Date: Tue, 12 Nov 2024 02:30:10 +0900 Subject: [PATCH] feat: add a whole bunch of logging intended to shed light to 408 errors Although the logging is going to be fairly excessive especially for larger projects, this should hopefully be enough to give us at least some clue about the ongoing 408 issues with certain projects. --- packages/cli/src/commands/deploy.ts | 23 ++++++- packages/cli/src/commands/test.ts | 55 +++++++++++++-- packages/cli/src/commands/trigger.ts | 8 +++ packages/cli/src/rest/checkly-storage.ts | 24 +++++-- packages/cli/src/rest/projects.ts | 10 ++- packages/cli/src/rest/test-sessions.ts | 12 +++- .../cli/src/services/abstract-check-runner.ts | 67 ++++++++++++++++++- packages/cli/src/services/project-parser.ts | 1 + packages/cli/src/services/snapshot-service.ts | 19 +++++- packages/cli/src/services/socket-client.ts | 40 +++++++++-- packages/cli/src/services/test-runner.ts | 14 +++- packages/cli/src/services/trigger-runner.ts | 4 +- 12 files changed, 249 insertions(+), 28 deletions(-) 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