From 1d7661c560239673b5833b587b13fbff34439588 Mon Sep 17 00:00:00 2001 From: Inrixia Date: Wed, 30 Oct 2024 17:37:45 +1300 Subject: [PATCH] Video - Always check artwork/nfo for recovery & improve error logging --- package.json | 2 +- src/float.ts | 2 +- src/lib/Video.ts | 184 +++++++++++++---------------- src/lib/logging/ProgressBars.ts | 26 ++-- src/lib/logging/ProgressConsole.ts | 4 +- src/lib/logging/ProgressLogger.ts | 10 +- 6 files changed, 109 insertions(+), 119 deletions(-) diff --git a/package.json b/package.json index 378281e..8260403 100644 --- a/package.json +++ b/package.json @@ -8,7 +8,7 @@ "start": "pnpm run tsc && node ./dist/float.js", "startHeadless": "pnpm run tsc && node ./dist/float.js --headless", "checkLint": "eslint ./src", - "sanity": "pnpm run checkLint && pnpm run test-esm && pnpm run build-windows-latest && pnpm run test-windows-latest", + "sanity": "pnpm run checkLint && pnpm run test-esm && pnpm run build && pnpm run test", "test-esm": "pnpm run tsc && node ./dist/float.js --sanityCheck", "test": "./build/float --sanityCheck", "makeBlob": "node --experimental-sea-config ./sea-config.json", diff --git a/src/float.ts b/src/float.ts index 3fe96cd..d4783c8 100644 --- a/src/float.ts +++ b/src/float.ts @@ -22,7 +22,7 @@ const downloadNewVideos = async () => { const inProgress = []; // Fetch content posts from seek and destroy guids - let contentPosts: Promise[] = []; + const contentPosts: Promise[] = []; while (settings.floatplane.seekAndDestroy.length > 0) { const guid = settings.floatplane.seekAndDestroy.pop(); if (guid === undefined) continue; diff --git a/src/lib/Video.ts b/src/lib/Video.ts index af755fe..fa5e7c0 100644 --- a/src/lib/Video.ts +++ b/src/lib/Video.ts @@ -23,6 +23,7 @@ import { updatePlex } from "./helpers/updatePlex.js"; import { ProgressHeadless } from "./logging/ProgressConsole.js"; import { ProgressBars } from "./logging/ProgressBars.js"; +import { withContext } from "./logging/ProgressLogger.js"; const exec = promisify(execCallback); const sleep = promisify(setTimeout); @@ -67,7 +68,7 @@ export class Video extends Attachment { public static State = VideoState; - private static readonly MaxRetries = 5; + private static readonly MaxRetries = 1; private static readonly DownloadThreads = 8; private static readonly DownloadSemaphore = new Semaphore(this.DownloadThreads); @@ -76,6 +77,7 @@ export class Video extends Attachment { private static readonly ThrottleGroup = settings.maxDownloadSpeed > -1 ? new ThrottleGroup(Video.ThrottleOptions) : undefined; private static readonly ProgressLogger: typeof ProgressHeadless | typeof ProgressBars = args.headless ? ProgressHeadless : ProgressBars; + private readonly logger = new Video.ProgressLogger(this.videoTitle); // Static cache of instances public static readonly Videos: Record = {}; @@ -92,118 +94,98 @@ export class Video extends Attachment { } public async download() { - if ((await this.getState()) === Video.State.Muxed) return; - const logger = new Video.ProgressLogger(this.videoTitle); - promQueued.inc(); await Video.DownloadSemaphore.obtain(); - logger.start(); - for (let retries = 1; retries < Video.MaxRetries + 1; retries++) { - try { - switch (await this.getState()) { - case Video.State.Missing: { - logger.log("Waiting on delivery cdn..."); - const downloadRequest = await this.getVideoStream(settings.floatplane.videoResolution); - - // Pipe the download to the file once response starts - const writeStream = createWriteStream(this.partialPath); - - // Throttle if enabled - if (Video.ThrottleGroup) { - // @ts-expect-error Type is wrong, this needs to be called with no arguments - const throttle = Video.ThrottleGroup.throttle(); - downloadRequest.pipe(throttle).pipe(writeStream); - } else downloadRequest.pipe(writeStream); - - let downloadedBytes = 0; - const onDownloadProgress = (progress: Progress) => { - const bytesSinceLast = progress.transferred - downloadedBytes; - downloadedBytes = progress.transferred; - promDownloadedBytes.inc(bytesSinceLast); - logger.onDownloadProgress(downloadRequest.downloadProgress, bytesSinceLast); - }; - - let downloadInterval: NodeJS.Timeout; - downloadRequest.once("downloadProgress", (downloadProgress: Progress) => { - logger.log("Download started!"); - downloadInterval = setInterval(() => onDownloadProgress(downloadRequest.downloadProgress), 250); - onDownloadProgress(downloadProgress); - }); - - await new Promise((res, rej) => { - downloadRequest.once("end", res); - downloadRequest.once("error", rej); - }).finally(() => { - clearInterval(downloadInterval); - onDownloadProgress(downloadRequest.downloadProgress); - }); - - logger.log("Download complete!"); - if (settings.extras.saveNfo) { - logger.log("Saving .nfo"); - try { - await this.saveNfo(); - } catch (error) { - // non-critical error - const message = this.parseErrorMessage(error); - logger.error(`Failed to save .nfo file! ${message} - Skipping`); - } + try { + if (settings.extras.saveNfo) { + this.logger.log("Saving .nfo"); + await this.saveNfo().catch(withContext(`Saving .nfo file!`)).catch(this.onError); + } + if (settings.extras.downloadArtwork) { + this.logger.log("Saving artwork"); + await this.downloadArtwork().catch(withContext(`Saving artwork!`)).catch(this.onError); + } + if ((await this.getState()) === Video.State.Muxed) return; + promQueued.inc(); + for (let retries = 0; retries < Video.MaxRetries; retries++) { + try { + switch (await this.getState()) { + case Video.State.Missing: { + await this.onMissing().catch(withContext(`Downloading missing video!`)); } - if (settings.extras.downloadArtwork) { - logger.log("Saving artwork"); - try { - await this.downloadArtwork(); - } catch (error) { - // non-critical error - const message = this.parseErrorMessage(error); - logger.error(`Failed to save artwork! ${message} - Skipping`); + // eslint-disable-next-line no-fallthrough + case Video.State.Partial: { + this.logger.log("Muxing ffmpeg metadata..."); + await this.muxffmpegMetadata().catch(withContext(`Muxing ffmpeg metadata`)); + + if (settings.postProcessingCommand !== "") { + this.logger.log(`Running settings.postProcessingCommand...`); + await this.postProcessingCommand().catch(withContext(`postProcessingCommand`)); } - } - } - // eslint-disable-next-line no-fallthrough - case Video.State.Partial: { - logger.log("Muxing ffmpeg metadata..."); - await this.muxffmpegMetadata(); - - if (settings.postProcessingCommand !== "") { - logger.log(`Running post download command "${settings.postProcessingCommand}"...`); - await this.postProcessingCommand().catch((err) => logger.log(`postProcessingCommand failed! ${err.message}\n`)); - } - if (settings.plex.enabled) { - await updatePlex().catch((err) => { - throw new Error(`Updating plex failed! ${err.message}`); - }); + if (settings.plex.enabled) { + await updatePlex().catch(withContext(`Updating plex`)); + } } } - } - logger.done(chalk`{cyan Download & Muxing complete!}`); - promDownloadedTotal.inc(); - break; - } catch (error) { - const message = this.parseErrorMessage(error); - promErrors.labels({ message, attachmentId: this.attachmentId }).inc(); - - if (retries < Video.MaxRetries) { - logger.error(`${message} - Retrying in ${retries}s [${retries}/${Video.MaxRetries}]`); - await sleep(1000 * retries); - } else { - logger.error(`${message} - Failed`); + this.logger.done(chalk`{cyan Download & Muxing complete!}`); + promDownloadedTotal.inc(); + break; + } catch (err: any) { + this.onError(err); + if (retries < Video.MaxRetries) await sleep(5000); } } + } finally { + await Video.DownloadSemaphore.release(); } - await Video.DownloadSemaphore.release(); promQueued.dec(); } - private parseErrorMessage(error: unknown): string { - let message = error instanceof Error ? error.message : `Something weird happened, whatever was thrown was not a error! ${error}`; - if (message.includes("ffmpeg")) { - const lastIndex = message.lastIndexOf(Video.Extensions.Partial); - if (lastIndex !== -1) { - message = `ffmpeg${message.substring(lastIndex + 9).replace(/\n|\r/g, "")}`; - } - } - return message; + private onError(err: any, throwAfterLog = false) { + const errStatement = this.logger.error(err); + console.error(`[${this.videoTitle}]`, errStatement); + promErrors.labels({ message: err?.message ?? err?.toString(), attachmentId: this.attachmentId }).inc(); + if (throwAfterLog) throw err; + } + + private async onMissing() { + this.logger.log("Waiting on delivery cdn..."); + const downloadRequest = await this.getVideoStream(settings.floatplane.videoResolution); + + // Pipe the download to the file once response starts + const writeStream = createWriteStream(this.partialPath); + + // Throttle if enabled + if (Video.ThrottleGroup) { + // @ts-expect-error Type is wrong, this needs to be called with no arguments + const throttle = Video.ThrottleGroup.throttle(); + downloadRequest.pipe(throttle).pipe(writeStream); + } else downloadRequest.pipe(writeStream); + + let downloadedBytes = 0; + const onDownloadProgress = (progress: Progress) => { + const bytesSinceLast = progress.transferred - downloadedBytes; + downloadedBytes = progress.transferred; + promDownloadedBytes.inc(bytesSinceLast); + this.logger.onDownloadProgress(downloadRequest.downloadProgress, bytesSinceLast); + }; + + let downloadInterval: NodeJS.Timeout; + downloadRequest.once("downloadProgress", (downloadProgress: Progress) => { + this.logger.log("Download started!"); + downloadInterval = setInterval(() => onDownloadProgress(downloadRequest.downloadProgress), 250); + onDownloadProgress(downloadProgress); + }); + + await new Promise((res, rej) => { + downloadRequest.once("end", res); + downloadRequest.once("error", rej); + }).finally(() => { + clearInterval(downloadInterval); + onDownloadProgress(downloadRequest.downloadProgress); + }); + + this.logger.log("Download complete!"); } private static async pathBytes(path: string) { diff --git a/src/lib/logging/ProgressBars.ts b/src/lib/logging/ProgressBars.ts index f091fd5..81a3baf 100644 --- a/src/lib/logging/ProgressBars.ts +++ b/src/lib/logging/ProgressBars.ts @@ -1,4 +1,4 @@ -import { MultiProgressBars } from "multi-progress-bars"; +import { MultiProgressBars, type UpdateOptions } from "multi-progress-bars"; import { ProgressLogger, type IProgressLogger } from "./ProgressLogger.js"; import type { Progress } from "got"; import chalk from "chalk-template"; @@ -23,22 +23,19 @@ export class ProgressBars extends ProgressLogger implements IProgressLogger { super(title); this.title = title.slice(0, 32).trim(); + let i = 1; + while (ProgressBars._Bars.getIndex(this.title) !== undefined) this.title = `${this.title} [${++i}]`; ProgressBars.Total++; } - private updateTask(...args: Parameters) { + private updateTask(updateOptions?: UpdateOptions) { if (ProgressBars._Bars.getIndex(this.title) === undefined) { ProgressBars._Bars.addTask(this.title, { type: "percentage" }); } - ProgressBars._Bars.updateTask(...args); + ProgressBars._Bars.updateTask(this.title, updateOptions); } - public start() { - let i = 1; - while (ProgressBars._Bars.getIndex(this.title) !== undefined) this.title = `${this.title} [${++i}]`; - this.updateTask(this.title, { percentage: 0 }); - } public log(message: string) { - this.updateTask(this.title, { message }); + this.updateTask({ message }); } private reset() { ProgressBars.DownloadSpeed -= this._downloadSpeed; @@ -46,13 +43,16 @@ export class ProgressBars extends ProgressLogger implements IProgressLogger { this._downloadSpeed = 0; this.updateSummaryBar(); } - public error(message: string) { + public error(err: any) { ProgressBars.Errors++; - this.log(chalk`{red ERR}: ${message}`); - this.reset(); + const errMsg = this.sanitizeError(err); + const errStatement = chalk`{red ERR}: ${errMsg}`; + this.log(errStatement); + return errStatement; } public done(message: string) { ProgressBars.Done += 1; + this.updateTask(); // Ensure the bar exists ProgressBars._Bars.done(this.title, { message }); this.reset(); setTimeout(() => ProgressBars._Bars.removeTask(this.title), 5000); @@ -83,7 +83,7 @@ export class ProgressBars extends ProgressLogger implements IProgressLogger { const speed = chalk`{green ${(this._downloadSpeed / 125000).toFixed(2)} mb/s}`; const eta = chalk`ETA: {blue ${Math.floor(downloadETA / 60)}m ${Math.floor(downloadETA) % 60}s}`; - this.updateTask(this.title, { + this.updateTask({ percentage: progress.percent, message: `${downloaded} ${speed} ${eta}`, }); diff --git a/src/lib/logging/ProgressConsole.ts b/src/lib/logging/ProgressConsole.ts index b299c94..046a27a 100644 --- a/src/lib/logging/ProgressConsole.ts +++ b/src/lib/logging/ProgressConsole.ts @@ -4,8 +4,8 @@ export class ProgressHeadless extends ProgressLogger implements IProgressLogger public log(message: string) { console.log(`${this.title} - ${message}`); } - public error(message: string) { - this.log(`An error occoured: ${message}`); + public error(err: any) { + this.log(`An error occoured: ${this.sanitizeError(err)}`); } public done = this.log; public onDownloadProgress() {} diff --git a/src/lib/logging/ProgressLogger.ts b/src/lib/logging/ProgressLogger.ts index 8935af0..087604d 100644 --- a/src/lib/logging/ProgressLogger.ts +++ b/src/lib/logging/ProgressLogger.ts @@ -3,7 +3,7 @@ import type { Progress } from "got"; export interface IProgressLogger { readonly title: string; log(message: string): void; - error(message: string): void; + error(err: any, context: string): void; onDownloadProgress(progress: Progress, bytesSinceLast: number): void; done(message: string): void; } @@ -13,4 +13,12 @@ export class ProgressLogger { constructor(title: string) { this.title = title.trim(); } + protected sanitizeError(err: any): string { + return err instanceof Error ? err.message : `Something weird happened, whatever was thrown was not a error! ${err}`; + } } + +export const withContext = (context: string) => (err: any) => { + if (err instanceof Error) throw new Error(`${context} - ${err.message}`); + throw err; +};