Rework log levels to be more useful (#546)

- Update log levels so that the log file contains more verbose
  information by default, while leaving the stderr progress indicator
  relatively uncluttered
- Explicitly set the log level to `error` for all dependencies
- rav1e scenechange info has been moved to `--log-level trace`
- Avoid outputting colors if stderr is not a tty
- Fix a crash when using `--quiet`

Cargo.lock

@@ -156,6 +156,7 @@ version = "0.3.1"
 dependencies = [
  "ansi_term",
  "anyhow",
+ "atty",
  "av1an-core",
  "clap",
  "ffmpeg-next",
@@ -175,6 +176,7 @@ dependencies = [
  "ansi_term",
  "anyhow",
  "arrayvec",
+ "atty",
  "av-format",
  "av-ivf",
  "av-scenechange",

av1an-cli/Cargo.toml

@@ -12,6 +12,7 @@ license = "GPL-3.0"
 edition = "2018"
 
 [dependencies]
+atty = "0.2.14"
 clap = { version = "3.0.0", features = ["derive"] }
 shlex = "1.0.0"
 path_abs = "0.5.1"

av1an-cli/src/lib.rs

@@ -130,10 +130,10 @@ pub struct CliOpts {
   ///
   /// info: Designates useful information.
   ///
-  /// debug: Designates lower priority information. Includes rav1e scenechange decision info.
+  /// debug: Designates lower priority information.
   ///
-  /// trace: Designates very low priority, often extremely verbose, information.
-  #[clap(long, default_value_t = LevelFilter::Info, ignore_case = true, possible_values = &["error", "warn", "info", "debug", "trace"])]
+  /// trace: Designates very low priority, often extremely verbose, information. Includes rav1e scenechange decision info.
+  #[clap(long, default_value_t = LevelFilter::Debug, ignore_case = true, possible_values = &["error", "warn", "info", "debug", "trace"])]
   // "off" is also an allowed value for LevelFilter but we just disable the user from setting it
   pub log_level: LevelFilter,
 
@@ -616,11 +616,16 @@ impl LogWriter for StderrLogger {
       return Ok(());
     }
 
-    let style = match record.level() {
-      Level::Error => Style::default().fg(Color::Fixed(196)).bold(),
-      Level::Warn => Style::default().fg(Color::Fixed(208)).bold(),
-      Level::Info => Style::default().dimmed(),
-      _ => Style::default(),
+    let style = if atty::is(atty::Stream::Stderr) {
+      match record.level() {
+        Level::Error => Style::default().fg(Color::Fixed(196)).bold(),
+        Level::Warn => Style::default().fg(Color::Fixed(208)).bold(),
+        Level::Info => Style::default().bold(),
+        Level::Debug => Style::default().dimmed(),
+        _ => Style::default(),
+      }
+    } else {
+      Style::default()
     };
 
     let msg = style.paint(format!("{}", record.args()));
@@ -657,15 +662,33 @@ pub fn run() -> anyhow::Result<()> {
   let log_level = cli_args.log_level;
   let mut args = parse_cli(cli_args)?;
 
-  let log = LogSpecBuilder::new().default(log_level).build();
+  let log = LogSpecBuilder::new()
+    .default(LevelFilter::Error)
+    .module("av1an", log_level)
+    .module("av1an_cli", log_level)
+    .module("av1an_core", log_level)
+    .module(
+      "rav1e::scenechange",
+      match log_level {
+        LevelFilter::Trace => LevelFilter::Debug,
+        LevelFilter::Debug => LevelFilter::Info,
+        other => other,
+      },
+    )
+    .build();
 
-  Logger::with(log)
+  // Note that with all write modes except WriteMode::Direct (which is the default)
+  // you should keep the LoggerHandle alive up to the very end of your program,
+  // because it will, in its Drop implementation, flush all writers to ensure that
+  // all buffered log lines are flushed before the program terminates,
+  // and then it calls their shutdown method.
+  let _logger = Logger::with(log)
     .log_to_file_and_writer(
       FileSpec::try_from(PathAbs::new(&args.log_file)?)?,
       Box::new(StderrLogger {
         level: match args.verbosity {
-          Verbosity::Normal | Verbosity::Quiet => Level::Warn,
-          Verbosity::Verbose => Level::Info,
+          Verbosity::Quiet => Level::Warn,
+          Verbosity::Normal | Verbosity::Verbose => Level::Info,
         },
       }),
     )

av1an-core/Cargo.toml

@@ -16,6 +16,7 @@ license = "GPL-3.0"
 [dependencies]
 log = "0.4.14"
 arrayvec = "0.7.2"
+atty = "0.2.14"
 av-format = "0.3.1"
 av-ivf = "0.2.2"
 memchr = "2.4.1"

av1an-core/src/concat.rs

@@ -130,18 +130,18 @@ pub fn ivf(input: &Path, out: &Path) -> anyhow::Result<()> {
               *p += pos_offset;
             }
 
-            debug!("received packet with pos: {:?}", packet.pos);
+            trace!("received packet with pos: {:?}", packet.pos);
             muxer.write_packet(Arc::new(packet))?;
           }
           Event::Continue => continue,
           Event::Eof => {
-            debug!("EOF received.");
+            trace!("EOF received.");
             break;
           }
           _ => unimplemented!(),
         },
         Err(e) => {
-          debug!("error: {:?}", e);
+          error!("{:?}", e);
           break;
         }
       }

av1an-core/src/scene_detect.rs

@@ -20,15 +20,21 @@ pub fn av_scenechange_detect(
   sc_downscale_height: Option<usize>,
 ) -> anyhow::Result<(Vec<usize>, usize)> {
   if verbosity != Verbosity::Quiet {
-    eprintln!("{}", Style::default().bold().paint("Scene detection"));
+    if atty::is(atty::Stream::Stderr) {
+      eprintln!("{}", Style::default().bold().paint("Scene detection"));
+    } else {
+      eprintln!("Scene detection");
+    }
     progress_bar::init_progress_bar(total_frames as u64);
   }
 
   let input2 = input.clone();
   let frame_thread = thread::spawn(move || {
     let frames = input2.frames().unwrap();
-    progress_bar::convert_to_progress();
-    progress_bar::set_len(frames as u64);
+    if verbosity != Verbosity::Quiet {
+      progress_bar::convert_to_progress();
+      progress_bar::set_len(frames as u64);
+    }
     frames
   });
 

av1an-core/src/settings.rs

@@ -138,7 +138,7 @@ impl EncodeArgs {
     create_dir!(Path::new(&self.temp).join("split"))?;
     create_dir!(Path::new(&self.temp).join("encode"))?;
 
-    info!("temporary directory: {}", &self.temp);
+    debug!("temporary directory: {}", &self.temp);
 
     let done_path = Path::new(&self.temp).join("done.json");
     let done_json_exists = done_path.exists();
@@ -642,17 +642,11 @@ properly into a mkv file. Specify mkvmerge as the concatenation method by settin
         .iter()
         .any(|f| Self::check_aom_encoder_mode(f))
       {
-        eprintln!(
-          "{}",
-          Color::Yellow.paint("[WARN] --end-usage was not specified")
-        );
+        warn!("[WARN] --end-usage was not specified");
       }
 
       if !self.video_params.iter().any(|f| Self::check_aom_rate(f)) {
-        eprintln!(
-          "{}",
-          Color::Yellow.paint("[WARN] --cq-level or --target-bitrate was not specified")
-        );
+        warn!("[WARN] --cq-level or --target-bitrate was not specified");
       }
     }
   }
@@ -743,9 +737,12 @@ properly into a mkv file. Specify mkvmerge as the concatenation method by settin
       |path| Cow::Borrowed(path.as_path()),
     );
 
+    let used_existing_cuts;
     let (mut scenes, frames) = if (self.scenes.is_some() && scene_file.exists()) || self.resume {
+      used_existing_cuts = true;
       crate::split::read_scenes_from_file(scene_file.as_ref())?
     } else {
+      used_existing_cuts = false;
       self.calc_split_locations()?
     };
     self.frames = frames;
@@ -753,15 +750,17 @@ properly into a mkv file. Specify mkvmerge as the concatenation method by settin
       .frames
       .store(self.frames, atomic::Ordering::SeqCst);
     let scenes_before = scenes.len() + 1;
-    if let Some(split_len) = self.extra_splits_len {
-      scenes = extra_splits(&scenes, self.frames, split_len);
-      let scenes_after = scenes.len() + 1;
-      info!(
-        "scenecut: found {} scene(s) [with extra_splits({} frames): {}]",
-        scenes_before, split_len, scenes_after
-      );
-    } else {
-      info!("scenecut: found {} scene(s)", scenes_before);
+    if !used_existing_cuts {
+      if let Some(split_len) = self.extra_splits_len {
+        scenes = extra_splits(&scenes, self.frames, split_len);
+        let scenes_after = scenes.len() + 1;
+        info!(
+          "scenecut: found {} scene(s) [with extra_splits ({} frames): {} scene(s)]",
+          scenes_before, split_len, scenes_after
+        );
+      } else {
+        info!("scenecut: found {} scene(s)", scenes_before);
+      }
     }
 
     write_scenes_to_file(&scenes, self.frames, scene_file)?;
@@ -896,9 +895,9 @@ properly into a mkv file. Specify mkvmerge as the concatenation method by settin
   fn create_video_queue_segment(&self, splits: &[usize]) -> anyhow::Result<Vec<Chunk>> {
     let input = self.input.as_video_path();
 
-    info!("Split video");
+    debug!("Splitting video");
     segment(input, &self.temp, splits);
-    info!("Split done");
+    debug!("Splitting done");
 
     let source_path = Path::new(&self.temp).join("split");
     let queue_files = Self::read_queue_files(&source_path)?;
@@ -935,9 +934,9 @@ properly into a mkv file. Specify mkvmerge as the concatenation method by settin
       .copied()
       .collect();
 
-    info!("Segmenting video");
+    debug!("Segmenting video");
     segment(input, &self.temp, &to_split[1..]);
-    info!("Segment done");
+    debug!("Segment done");
 
     let source_path = Path::new(&self.temp).join("split");
     let queue_files = Self::read_queue_files(&source_path)?;
@@ -1136,20 +1135,30 @@ properly into a mkv file. Specify mkvmerge as the concatenation method by settin
       }
       self.workers = cmp::min(self.workers, chunk_queue.len());
 
-      eprintln!(
-        "{}{} {} {}{} {} {}{} {}\n{}: {}",
-        Color::Green.bold().paint("Q"),
-        Color::Green.paint("ueue"),
-        Color::Green.bold().paint(format!("{}", chunk_queue.len())),
-        Color::Blue.bold().paint("W"),
-        Color::Blue.paint("orkers"),
-        Color::Blue.bold().paint(format!("{}", self.workers)),
-        Color::Purple.bold().paint("P"),
-        Color::Purple.paint("asses"),
-        Color::Purple.bold().paint(format!("{}", self.passes)),
-        Style::default().bold().paint("Params"),
-        Style::default().dimmed().paint(self.video_params.join(" "))
-      );
+      if atty::is(atty::Stream::Stderr) {
+        eprintln!(
+          "{}{} {} {}{} {} {}{} {}\n{}: {}",
+          Color::Green.bold().paint("Q"),
+          Color::Green.paint("ueue"),
+          Color::Green.bold().paint(format!("{}", chunk_queue.len())),
+          Color::Blue.bold().paint("W"),
+          Color::Blue.paint("orkers"),
+          Color::Blue.bold().paint(format!("{}", self.workers)),
+          Color::Purple.bold().paint("P"),
+          Color::Purple.paint("asses"),
+          Color::Purple.bold().paint(format!("{}", self.passes)),
+          Style::default().bold().paint("Params"),
+          Style::default().dimmed().paint(self.video_params.join(" "))
+        );
+      } else {
+        eprintln!(
+          "Queue {} Workers {} Passes {}\nParams: {}",
+          chunk_queue.len(),
+          self.workers,
+          self.passes,
+          self.video_params.join(" ")
+        );
+      }
 
       if self.verbosity == Verbosity::Normal {
         init_progress_bar(self.frames as u64);
@@ -1204,7 +1213,7 @@ properly into a mkv file. Specify mkvmerge as the concatenation method by settin
       let _audio_output_exists =
         audio_thread.map_or(false, |audio_thread| audio_thread.join().unwrap());
 
-      info!("encoding finished, concatenating with {}", self.concat);
+      debug!("encoding finished, concatenating with {}", self.concat);
 
       match self.concat {
         ConcatMethod::Ivf => {
@@ -1239,8 +1248,7 @@ properly into a mkv file. Specify mkvmerge as the concatenation method by settin
           },
           self.vmaf_threads.unwrap_or_else(num_cpus::get),
         ) {
-          error!("{}", e);
-          error!("VMAF calculation failed, no plot generated.");
+          error!("VMAF calculation failed with error: {}", e);
         }
       }
 

av1an-core/src/target_quality.rs

@@ -358,11 +358,11 @@ pub fn log_probes(
   vmaf_cq_scores.sort_by_key(|(_score, q)| *q);
 
   // TODO: take chunk id as integer instead and format with {:05}
-  info!(
+  debug!(
     "chunk {}: P-Rate={}, {} frames",
     chunk_idx, probing_rate, frames
   );
-  info!(
+  debug!(
     "chunk {}: TQ-Probes: {:.2?}{}",
     chunk_idx,
     vmaf_cq_scores,
@@ -372,7 +372,7 @@ pub fn log_probes(
       Skip::None => "",
     }
   );
-  info!(
+  debug!(
     "chunk {}: Target Q={:.0}, VMAF={:.2}",
     chunk_idx, target_q, target_vmaf
   );