Support logging via RUST_LOG (#209)

* Support logging via RUST_LOG

* Add crf successful log

* Add encoding/vmaf + progress logs

* Enable info logging when stderr is not a terminal

CHANGELOG.md

@@ -2,6 +2,11 @@
 * Show full ffmpeg command after errors.
 * For *_vaapi encoders map `--crf` to ffmpeg `-q` (instead of `-qp`).
 * Set av1_vaapi default `--max-crf` to 255.
+* Fix sample-encode printing output to non-terminals.
+* Omit "Encode with: ..." stderr hint for non-terminals.
+* Support logging enabled when stderr is not a terminal or by setting env var `RUST_LOG`. E.g:
+  - `RUST_LOG=ab_av1=info` "info" level logs various progress results like sample encode info
+  - `RUST_LOG=ab_av1=debug` "debug" level logs include ffmpeg calls
 
 # v0.7.14
 * Fix bash completions of some filenames.

Cargo.toml

@@ -16,12 +16,14 @@ clap = { version = "4", features = ["derive", "env", "wrap_help"] }
 clap_complete = "4.4.10"
 console = "0.15.4"
 dirs = "5"
+env_logger = { version = "0.11.3", default-features = false, features = ["auto-color", "humantime"] }
 fastrand = "2"
 ffprobe = "0.4"
 futures = "0.3.19"
 humantime = "2.1"
 indicatif = "0.17"
 infer = { version = "0.16", default-features = false }
+log = "0.4.21"
 serde = { version = "1.0.185", features = ["derive"] }
 serde_json = "1.0.105"
 shell-escape = "0.1.5"

src/command/crf_search.rs

@@ -13,6 +13,7 @@ use clap::{ArgAction, Parser};
 use console::style;
 use err::ensure_other;
 use indicatif::{HumanBytes, HumanDuration, ProgressBar, ProgressStyle};
+use log::info;
 use std::{
     io::{self, IsTerminal},
     sync::Arc,
@@ -102,19 +103,31 @@ pub async fn crf_search(mut args: Args) -> anyhow::Result<()> {
     bar.finish();
     let best = best?;
 
-    // encode how-to hint + predictions
-    eprintln!(
-        "\n{} {}\n",
-        style("Encode with:").dim(),
-        style(args.args.encode_hint(best.crf())).dim().italic(),
-    );
+    if std::io::stderr().is_terminal() {
+        // encode how-to hint
+        eprintln!(
+            "\n{} {}\n",
+            style("Encode with:").dim(),
+            style(args.args.encode_hint(best.crf())).dim().italic(),
+        );
+    }
 
     StdoutFormat::Human.print_result(&best, input_is_image);
 
     Ok(())
 }
 
 pub async fn run(
+    args: &Args,
+    input_probe: Arc<Ffprobe>,
+    bar: ProgressBar,
+) -> Result<Sample, Error> {
+    _run(args, input_probe, bar)
+        .await
+        .inspect(|s| info!("crf {} successful", s.crf()))
+}
+
+async fn _run(
     Args {
         args,
         min_vmaf,
@@ -169,6 +182,7 @@ pub async fn run(
             args.clone(),
             input_probe.clone(),
             sample_bar.clone(),
+            false,
         ));
 
         let sample_task = loop {

src/command/encode.rs

@@ -6,16 +6,18 @@ use crate::{
     console_ext::style,
     ffmpeg,
     ffprobe::{self, Ffprobe},
+    log::ProgressLogger,
     process::FfmpegOut,
     temporary::{self, TempKind},
 };
 use clap::Parser;
 use console::style;
 use indicatif::{HumanBytes, ProgressBar, ProgressStyle};
+use log::info;
 use std::{
     path::{Path, PathBuf},
     sync::Arc,
-    time::Duration,
+    time::{Duration, Instant},
 };
 use tokio::fs;
 use tokio_stream::StreamExt;
@@ -89,17 +91,23 @@ pub async fn run(
         anyhow::bail!("--stereo-downmix cannot be used with --acodec copy");
     }
 
-    let mut enc = ffmpeg::encode(enc_args, &output, has_audio, audio_codec, stereo_downmix)?;
+    info!(
+        "encoding {}",
+        output.file_name().and_then(|n| n.to_str()).unwrap_or("")
+    );
 
+    let mut enc = ffmpeg::encode(enc_args, &output, has_audio, audio_codec, stereo_downmix)?;
+    let mut logger = ProgressLogger::new(module_path!(), Instant::now());
     let mut stream_sizes = None;
     while let Some(progress) = enc.next().await {
         match progress? {
             FfmpegOut::Progress { fps, time, .. } => {
                 if fps > 0.0 {
                     bar.set_message(format!("{fps} fps, "));
                 }
-                if probe.duration.is_ok() {
+                if let Ok(d) = &probe.duration {
                     bar.set_position(time.as_micros_u64());
+                    logger.update(*d, time, fps);
                 }
             }
             FfmpegOut::StreamSizes {

src/command/sample_encode.rs

@@ -8,16 +8,19 @@ use crate::{
     console_ext::style,
     ffmpeg::{self, FfmpegEncodeArgs},
     ffprobe::{self, Ffprobe},
+    log::ProgressLogger,
     process::FfmpegOut,
-    sample, temporary, vmaf,
-    vmaf::VmafOut,
+    sample, temporary,
+    vmaf::{self, VmafOut},
     SAMPLE_SIZE, SAMPLE_SIZE_S,
 };
 use anyhow::ensure;
 use clap::{ArgAction, Parser};
 use console::style;
 use indicatif::{HumanBytes, HumanDuration, ProgressBar, ProgressStyle};
+use log::info;
 use std::{
+    io::IsTerminal,
     path::{Path, PathBuf},
     sync::Arc,
     time::{Duration, Instant},
@@ -74,7 +77,7 @@ pub async fn sample_encode(mut args: Args) -> anyhow::Result<()> {
     let probe = ffprobe::probe(&args.args.input);
     args.sample
         .set_extension_from_input(&args.args.input, &probe);
-    run(args, probe.into(), bar).await?;
+    run(args, probe.into(), bar, true).await?;
     Ok(())
 }
 
@@ -89,6 +92,7 @@ pub async fn run(
     }: Args,
     input_probe: Arc<Ffprobe>,
     bar: ProgressBar,
+    print_output: bool,
 ) -> anyhow::Result<Output> {
     let input = Arc::new(args.input.clone());
     let input_pixel_format = input_probe.pixel_format();
@@ -155,6 +159,8 @@ pub async fn run(
 
         let (sample, sample_size) = sample?;
 
+        info!("encoding sample {sample_n}/{samples} crf {crf}",);
+
         // encode sample
         let result = match cache::cached_encode(
             cache,
@@ -179,11 +185,19 @@ pub async fn run(
                     .dim()
                     .to_string(),
                 );
+                if samples > 1 {
+                    info!(
+                        "sample {sample_n}/{samples} crf {crf} VMAF {:.2} ({:.0}%) (cache)",
+                        result.vmaf_score,
+                        100.0 * result.encoded_size as f32 / sample_size as f32,
+                    );
+                }
                 result
             }
             (None, key) => {
                 bar.set_message("encoding,");
                 let b = Instant::now();
+                let mut logger = ProgressLogger::new(module_path!(), b);
                 let (encoded_sample, mut output) = ffmpeg::encode_sample(
                     FfmpegEncodeArgs {
                         input: &sample,
@@ -200,6 +214,7 @@ pub async fn run(
                         if fps > 0.0 {
                             bar.set_message(format!("enc {fps} fps,"));
                         }
+                        logger.update(SAMPLE_SIZE, time, fps);
                     }
                 }
                 let encode_time = b.elapsed();
@@ -219,6 +234,7 @@ pub async fn run(
                         args.vfilter.as_deref(),
                     ),
                 )?;
+                let mut logger = ProgressLogger::new("ab_av1::vmaf", Instant::now());
                 let mut vmaf_score = -1.0;
                 while let Some(vmaf) = vmaf.next().await {
                     match vmaf {
@@ -236,6 +252,7 @@ pub async fn run(
                             if fps > 0.0 {
                                 bar.set_message(format!("vmaf {fps} fps,"));
                             }
+                            logger.update(SAMPLE_SIZE, time, fps);
                         }
                         VmafOut::Progress(_) => {}
                         VmafOut::Err(e) => return Err(e),
@@ -250,6 +267,12 @@ pub async fn run(
                     .dim()
                     .to_string(),
                 );
+                if samples > 1 {
+                    info!(
+                        "sample {sample_n}/{samples} crf {crf} VMAF {vmaf_score:.2} ({:.0}%)",
+                        100.0 * encoded_size as f32 / sample_size as f32,
+                    );
+                }
 
                 let result = EncodeResult {
                     vmaf_score,
@@ -293,14 +316,24 @@ pub async fn run(
         predicted_encode_time: results.estimate_encode_time(duration, full_pass),
         from_cache: results.iter().all(|r| r.from_cache),
     };
+    info!(
+        "crf {crf} VMAF {:.2} predicted video stream size {} ({:.0}%) taking {}{}",
+        output.vmaf,
+        HumanBytes(output.predicted_encode_size),
+        output.encode_percent,
+        HumanDuration(output.predicted_encode_time),
+        if output.from_cache { " (cache)" } else { "" }
+    );
 
-    if !bar.is_hidden() {
-        // encode how-to hint + predictions
-        eprintln!(
-            "\n{} {}\n",
-            style("Encode with:").dim(),
-            style(args.encode_hint(crf)).dim().italic(),
-        );
+    if print_output {
+        if std::io::stderr().is_terminal() {
+            // encode how-to hint
+            eprintln!(
+                "\n{} {}\n",
+                style("Encode with:").dim(),
+                style(args.encode_hint(crf)).dim().italic(),
+            );
+        }
         // stdout result
         stdout_format.print_result(
             output.vmaf,

src/command/vmaf.rs

@@ -4,13 +4,16 @@ use crate::{
         PROGRESS_CHARS,
     },
     ffprobe,
+    log::ProgressLogger,
     process::FfmpegOut,
-    vmaf,
-    vmaf::VmafOut,
+    vmaf::{self, VmafOut},
 };
 use clap::Parser;
 use indicatif::{ProgressBar, ProgressStyle};
-use std::{path::PathBuf, time::Duration};
+use std::{
+    path::PathBuf,
+    time::{Duration, Instant},
+};
 use tokio_stream::StreamExt;
 
 /// Full VMAF score calculation, distorted file vs reference file.
@@ -62,6 +65,7 @@ pub async fn vmaf(
     let rprobe = ffprobe::probe(&reference);
     let rpix_fmt = rprobe.pixel_format().unwrap_or(PixelFormat::Yuv444p10le);
     let nframes = dprobe.nframes().or_else(|_| rprobe.nframes());
+    let duration = dprobe.duration.as_ref().or(rprobe.duration.as_ref());
     if let Ok(nframes) = nframes {
         bar.set_length(nframes);
     }
@@ -75,20 +79,26 @@ pub async fn vmaf(
             reference_vfilter.as_deref(),
         ),
     )?;
+    let mut logger = ProgressLogger::new(module_path!(), Instant::now());
     let mut vmaf_score = -1.0;
     while let Some(vmaf) = vmaf.next().await {
         match vmaf {
             VmafOut::Done(score) => {
                 vmaf_score = score;
                 break;
             }
-            VmafOut::Progress(FfmpegOut::Progress { frame, fps, .. }) => {
+            VmafOut::Progress(FfmpegOut::Progress {
+                frame, fps, time, ..
+            }) => {
                 if fps > 0.0 {
                     bar.set_message(format!("vmaf {fps} fps, "));
                 }
                 if nframes.is_ok() {
                     bar.set_position(frame);
                 }
+                if let Ok(total) = duration {
+                    logger.update(*total, time, fps);
+                }
             }
             VmafOut::Progress(FfmpegOut::StreamSizes { .. }) => {}
             VmafOut::Err(e) => return Err(e),

src/ffmpeg.rs

@@ -6,6 +6,7 @@ use crate::{
     temporary::{self, TempKind},
 };
 use anyhow::Context;
+use log::debug;
 use std::{
     collections::HashSet,
     hash::{Hash, Hasher},
@@ -102,6 +103,7 @@ pub fn encode_sample(
         .stdout(Stdio::null())
         .stderr(Stdio::piped());
     let cmd_str = cmd.to_cmd_str();
+    debug!("cmd `{cmd_str}`");
 
     let enc = cmd.spawn().context("ffmpeg encode_sample")?;
 
@@ -171,6 +173,7 @@ pub fn encode(
         .stdout(Stdio::null())
         .stderr(Stdio::piped());
     let cmd_str = cmd.to_cmd_str();
+    debug!("cmd `{cmd_str}`");
 
     let enc = cmd.spawn().context("ffmpeg encode")?;