feat(server): better transcoding logs (#13000)

* better transcoding logs

* pr feedback

server/src/interfaces/logger.interface.ts

@@ -6,6 +6,7 @@ export interface ILoggerRepository {
   setAppName(name: string): void;
   setContext(message: string): void;
   setLogLevel(level: LogLevel): void;
+  isLevelEnabled(level: LogLevel): boolean;
 
   verbose(message: any, ...args: any): void;
   debug(message: any, ...args: any): void;

server/src/interfaces/media.interface.ts

@@ -62,6 +62,10 @@ export interface TranscodeCommand {
   inputOptions: string[];
   outputOptions: string[];
   twoPass: boolean;
+  progress: {
+    frameCount: number;
+    percentInterval: number;
+  };
 }
 
 export interface BitrateDistribution {
@@ -79,6 +83,10 @@ export interface VideoCodecHWConfig extends VideoCodecSWConfig {
   getSupportedCodecs(): Array<VideoCodec>;
 }
 
+export interface ProbeOptions {
+  countFrames: boolean;
+}
+
 export interface IMediaRepository {
   // image
   extract(input: string, output: string): Promise<boolean>;
@@ -87,6 +95,6 @@ export interface IMediaRepository {
   getImageDimensions(input: string): Promise<ImageDimensions>;
 
   // video
-  probe(input: string): Promise<VideoInfo>;
+  probe(input: string, options?: ProbeOptions): Promise<VideoInfo>;
   transcode(input: string, output: string | Writable, command: TranscodeCommand): Promise<void>;
 }

server/src/repositories/media.repository.ts

@@ -1,15 +1,16 @@
 import { Inject, Injectable } from '@nestjs/common';
 import { exiftool } from 'exiftool-vendored';
 import ffmpeg, { FfprobeData } from 'fluent-ffmpeg';
+import { Duration } from 'luxon';
 import fs from 'node:fs/promises';
 import { Writable } from 'node:stream';
-import { promisify } from 'node:util';
 import sharp from 'sharp';
-import { Colorspace } from 'src/enum';
+import { Colorspace, LogLevel } from 'src/enum';
 import { ILoggerRepository } from 'src/interfaces/logger.interface';
 import {
   IMediaRepository,
   ImageDimensions,
+  ProbeOptions,
   ThumbnailOptions,
   TranscodeCommand,
   VideoInfo,
@@ -17,10 +18,22 @@ import {
 import { Instrumentation } from 'src/utils/instrumentation';
 import { handlePromiseError } from 'src/utils/misc';
 
-const probe = promisify<string, FfprobeData>(ffmpeg.ffprobe);
+const probe = (input: string, options: string[]): Promise<FfprobeData> =>
+  new Promise((resolve, reject) =>
+    ffmpeg.ffprobe(input, options, (error, data) => (error ? reject(error) : resolve(data))),
+  );
 sharp.concurrency(0);
 sharp.cache({ files: 0 });
 
+type ProgressEvent = {
+  frames: number;
+  currentFps: number;
+  currentKbps: number;
+  targetSize: number;
+  timemark: string;
+  percent?: number;
+};
+
 @Instrumentation()
 @Injectable()
 export class MediaRepository implements IMediaRepository {
@@ -65,8 +78,8 @@ export class MediaRepository implements IMediaRepository {
       .toFile(output);
   }
 
-  async probe(input: string): Promise<VideoInfo> {
-    const results = await probe(input);
+  async probe(input: string, options?: ProbeOptions): Promise<VideoInfo> {
+    const results = await probe(input, options?.countFrames ? ['-count_packets'] : []); // gets frame count quickly: https://stackoverflow.com/a/28376817
     return {
       format: {
         formatName: results.format.format_name,
@@ -83,10 +96,10 @@ export class MediaRepository implements IMediaRepository {
           width: stream.width || 0,
           codecName: stream.codec_name === 'h265' ? 'hevc' : stream.codec_name,
           codecType: stream.codec_type,
-          frameCount: Number.parseInt(stream.nb_frames ?? '0'),
-          rotation: Number.parseInt(`${stream.rotation ?? 0}`),
+          frameCount: this.parseInt(options?.countFrames ? stream.nb_read_packets : stream.nb_frames),
+          rotation: this.parseInt(stream.rotation),
           isHDR: stream.color_transfer === 'smpte2084' || stream.color_transfer === 'arib-std-b67',
-          bitrate: Number.parseInt(stream.bit_rate ?? '0'),
+          bitrate: this.parseInt(stream.bit_rate),
         })),
       audioStreams: results.streams
         .filter((stream) => stream.codec_type === 'audio')
@@ -94,7 +107,7 @@ export class MediaRepository implements IMediaRepository {
           index: stream.index,
           codecType: stream.codec_type,
           codecName: stream.codec_name,
-          frameCount: Number.parseInt(stream.nb_frames ?? '0'),
+          frameCount: this.parseInt(options?.countFrames ? stream.nb_read_packets : stream.nb_frames),
         })),
     };
   }
@@ -156,10 +169,37 @@ export class MediaRepository implements IMediaRepository {
   }
 
   private configureFfmpegCall(input: string, output: string | Writable, options: TranscodeCommand) {
-    return ffmpeg(input, { niceness: 10 })
+    const ffmpegCall = ffmpeg(input, { niceness: 10 })
       .inputOptions(options.inputOptions)
       .outputOptions(options.outputOptions)
       .output(output)
-      .on('error', (error, stdout, stderr) => this.logger.error(stderr || error));
+      .on('start', (command: string) => this.logger.debug(command))
+      .on('error', (error, _, stderr) => this.logger.error(stderr || error));
+
+    const { frameCount, percentInterval } = options.progress;
+    const frameInterval = Math.ceil(frameCount / (100 / percentInterval));
+    if (this.logger.isLevelEnabled(LogLevel.DEBUG) && frameCount && frameInterval) {
+      let lastProgressFrame: number = 0;
+      ffmpegCall.on('progress', (progress: ProgressEvent) => {
+        if (progress.frames - lastProgressFrame < frameInterval) {
+          return;
+        }
+
+        lastProgressFrame = progress.frames;
+        const percent = ((progress.frames / frameCount) * 100).toFixed(2);
+        const ms = Math.floor((frameCount - progress.frames) / progress.currentFps) * 1000;
+        const duration = ms ? Duration.fromMillis(ms).rescale().toHuman({ unitDisplay: 'narrow' }) : '';
+        const outputText = output instanceof Writable ? 'stream' : output.split('/').pop();
+        this.logger.debug(
+          `Transcoding ${percent}% done${duration ? `, estimated ${duration} remaining` : ''} for output ${outputText}`,
+        );
+      });
+    }
+
+    return ffmpegCall;
+  }
+
+  private parseInt(value: string | number | undefined): number {
+    return Number.parseInt(value as string) || 0;
   }
 }

server/src/services/media.service.ts

@@ -11,6 +11,7 @@ import {
   AudioCodec,
   Colorspace,
   ImageFormat,
+  LogLevel,
   StorageFolder,
   TranscodeHWAccel,
   TranscodePolicy,
@@ -31,7 +32,13 @@ import {
   QueueName,
 } from 'src/interfaces/job.interface';
 import { ILoggerRepository } from 'src/interfaces/logger.interface';
-import { AudioStreamInfo, IMediaRepository, VideoFormat, VideoStreamInfo } from 'src/interfaces/media.interface';
+import {
+  AudioStreamInfo,
+  IMediaRepository,
+  TranscodeCommand,
+  VideoFormat,
+  VideoStreamInfo,
+} from 'src/interfaces/media.interface';
 import { IMoveRepository } from 'src/interfaces/move.interface';
 import { IPersonRepository } from 'src/interfaces/person.interface';
 import { IStorageRepository } from 'src/interfaces/storage.interface';
@@ -346,7 +353,9 @@ export class MediaService {
     const output = StorageCore.getEncodedVideoPath(asset);
     this.storageCore.ensureFolders(output);
 
-    const { videoStreams, audioStreams, format } = await this.mediaRepository.probe(input);
+    const { videoStreams, audioStreams, format } = await this.mediaRepository.probe(input, {
+      countFrames: this.logger.isLevelEnabled(LogLevel.DEBUG), // makes frame count more reliable for progress logs
+    });
     const mainVideoStream = this.getMainStream(videoStreams);
     const mainAudioStream = this.getMainStream(audioStreams);
     if (!mainVideoStream || !format.formatName) {
@@ -365,12 +374,14 @@ export class MediaService {
         this.logger.log(`Transcoded video exists for asset ${asset.id}, but is no longer required. Deleting...`);
         await this.jobRepository.queue({ name: JobName.DELETE_FILES, data: { files: [asset.encodedVideoPath] } });
         await this.assetRepository.update({ id: asset.id, encodedVideoPath: null });
+      } else {
+        this.logger.verbose(`Asset ${asset.id} does not require transcoding based on current policy, skipping`);
       }
 
       return JobStatus.SKIPPED;
     }
 
-    let command;
+    let command: TranscodeCommand;
     try {
       const config = BaseConfig.create(ffmpeg, await this.getDevices(), await this.hasMaliOpenCL());
       command = config.getCommand(target, mainVideoStream, mainAudioStream);
@@ -379,16 +390,20 @@ export class MediaService {
       return JobStatus.FAILED;
     }
 
-    this.logger.log(`Started encoding video ${asset.id} ${JSON.stringify(command)}`);
+    if (ffmpeg.accel === TranscodeHWAccel.DISABLED) {
+      this.logger.log(`Encoding video ${asset.id} without hardware acceleration`);
+    } else {
+      this.logger.log(`Encoding video ${asset.id} with ${ffmpeg.accel.toUpperCase()} acceleration`);
+    }
+
     try {
       await this.mediaRepository.transcode(input, output, command);
-    } catch (error) {
-      this.logger.error(error);
-      if (ffmpeg.accel !== TranscodeHWAccel.DISABLED) {
-        this.logger.error(
-          `Error occurred during transcoding. Retrying with ${ffmpeg.accel.toUpperCase()} acceleration disabled.`,
-        );
+    } catch (error: any) {
+      this.logger.error(`Error occurred during transcoding: ${error.message}`);
+      if (ffmpeg.accel === TranscodeHWAccel.DISABLED) {
+        return JobStatus.FAILED;
       }
+      this.logger.error(`Retrying with ${ffmpeg.accel.toUpperCase()} acceleration disabled`);
       const config = BaseConfig.create({ ...ffmpeg, accel: TranscodeHWAccel.DISABLED });
       command = config.getCommand(target, mainVideoStream, mainAudioStream);
       await this.mediaRepository.transcode(input, output, command);
@@ -555,7 +570,7 @@ export class MediaService {
         const maliDeviceStat = await this.storageRepository.stat('/dev/mali0');
         this.maliOpenCL = maliIcdStat.isFile() && maliDeviceStat.isCharacterDevice();
       } catch {
-        this.logger.debug('OpenCL not available for transcoding, using CPU decoding instead.');
+        this.logger.debug('OpenCL not available for transcoding, so RKMPP acceleration will use CPU decoding');
         this.maliOpenCL = false;
       }
     }

server/src/utils/media.ts

@@ -80,6 +80,7 @@ export class BaseConfig implements VideoCodecSWConfig {
       inputOptions: this.getBaseInputOptions(videoStream),
       outputOptions: [...this.getBaseOutputOptions(target, videoStream, audioStream), '-v verbose'],
       twoPass: this.eligibleForTwoPass(),
+      progress: { frameCount: videoStream.frameCount, percentInterval: 5 },
     } as TranscodeCommand;
     if ([TranscodeTarget.ALL, TranscodeTarget.VIDEO].includes(target)) {
       const filters = this.getFilterOptions(videoStream);

server/test/repositories/logger.repository.mock.ts

@@ -6,7 +6,7 @@ export const newLoggerRepositoryMock = (): Mocked<ILoggerRepository> => {
     setLogLevel: vitest.fn(),
     setContext: vitest.fn(),
     setAppName: vitest.fn(),
-
+    isLevelEnabled: vitest.fn(),
     verbose: vitest.fn(),
     debug: vitest.fn(),
     log: vitest.fn(),