More flexible verbosity, improve verbose test (#501)

* More flexible verbosity, improve verbose test

* Tweak reporting format

* Add evaluation reporting at trace level

src/colors.rs

@@ -1,5 +1,5 @@
 use rgb::{RGB16, RGBA8};
-use std::fmt;
+use std::{fmt, fmt::Display};
 
 use crate::PngError;
 
@@ -27,20 +27,18 @@ pub enum ColorType {
     RGBA,
 }
 
-impl fmt::Display for ColorType {
+impl Display for ColorType {
     #[inline]
     fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
-        write!(
+        match self {
-            f,
+            ColorType::Grayscale { .. } => Display::fmt("Grayscale", f),
-            "{}",
+            ColorType::RGB { .. } => Display::fmt("RGB", f),
-            match *self {
+            ColorType::Indexed { palette } => {
-                ColorType::Grayscale { .. } => "Grayscale",
+                Display::fmt(&format!("Indexed ({} colors)", palette.len()), f)
-                ColorType::RGB { .. } => "RGB",
-                ColorType::Indexed { .. } => "Indexed",
-                ColorType::GrayscaleAlpha => "Grayscale + Alpha",
-                ColorType::RGBA => "RGB + Alpha",
             }
-        )
+            ColorType::GrayscaleAlpha => Display::fmt("Grayscale + Alpha", f),
+            ColorType::RGBA => Display::fmt("RGB + Alpha", f),
+        }
     }
 }
 
@@ -109,9 +107,9 @@ impl TryFrom<u8> for BitDepth {
     }
 }
 
-impl fmt::Display for BitDepth {
+impl Display for BitDepth {
     #[inline]
     fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
-        write!(f, "{}", *self as u8)
+        Display::fmt(&(*self as u8).to_string(), f)
     }
 }

src/evaluate.rs

@@ -9,9 +9,11 @@ use crate::png::PngImage;
 #[cfg(not(feature = "parallel"))]
 use crate::rayon;
 use crate::Deadline;
+use crate::PngError;
 #[cfg(feature = "parallel")]
 use crossbeam_channel::{unbounded, Receiver, Sender};
 use indexmap::IndexSet;
+use log::trace;
 use rayon::prelude::*;
 #[cfg(not(feature = "parallel"))]
 use std::cell::RefCell;
@@ -131,9 +133,8 @@ impl Evaluator {
                     return;
                 }
                 let filtered = image.filter_image(filter, optimize_alpha);
-                if let Ok(idat_data) =
+                let idat_data = deflate::deflate(&filtered, compression, &best_candidate_size);
-                    deflate::deflate(&filtered, compression, &best_candidate_size)
+                if let Ok(idat_data) = idat_data {
-                {
                     let new = Candidate {
                         image: PngData {
                             idat_data,
@@ -144,7 +145,15 @@ impl Evaluator {
                         is_reduction,
                         nth,
                     };
-                    best_candidate_size.set_min(new.image.estimated_output_size());
+                    let size = new.image.estimated_output_size();
+                    best_candidate_size.set_min(size);
+                    trace!(
+                        "Eval: {}-bit {:20}  {:8}   {} bytes",
+                        image.ihdr.bit_depth,
+                        image.ihdr.color_type,
+                        filter,
+                        size
+                    );
 
                     #[cfg(feature = "parallel")]
                     {
@@ -158,6 +167,14 @@ impl Evaluator {
                             best => *best = Some(new),
                         }
                     }
+                } else if let Err(PngError::DeflatedDataTooLong(size)) = idat_data {
+                    trace!(
+                        "Eval: {}-bit {:20}  {:8}  >{} bytes",
+                        image.ihdr.bit_depth,
+                        image.ihdr.color_type,
+                        filter,
+                        size
+                    );
                 }
             });
         });

src/filters.rs

@@ -1,4 +1,5 @@
-use std::{fmt::Display, mem::transmute};
+use std::mem::transmute;
+use std::{fmt, fmt::Display};
 
 use crate::error::PngError;
 
@@ -31,11 +32,9 @@ impl TryFrom<u8> for RowFilter {
 }
 
 impl Display for RowFilter {
-    fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
+    fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
-        write!(
+        Display::fmt(
-            f,
+            match self {
-            "{:8}",
-            match *self {
                 Self::None => "None",
                 Self::Sub => "Sub",
                 Self::Up => "Up",
@@ -46,7 +45,8 @@ impl Display for RowFilter {
                 Self::Bigrams => "Bigrams",
                 Self::BigEnt => "BigEnt",
                 Self::Brute => "Brute",
-            }
+            },
+            f,
         )
     }
 }

src/interlace.rs

@@ -1,4 +1,4 @@
-use std::fmt::Display;
+use std::{fmt, fmt::Display};
 
 use crate::headers::IhdrData;
 use crate::png::PngImage;
@@ -25,14 +25,13 @@ impl TryFrom<u8> for Interlacing {
 }
 
 impl Display for Interlacing {
-    fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
+    fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
-        write!(
+        Display::fmt(
-            f,
+            match self {
-            "{}",
-            match *self {
                 Self::None => "non-interlaced",
                 Self::Adam7 => "interlaced",
-            }
+            },
+            f,
         )
     }
 }

src/lib.rs

@@ -25,13 +25,13 @@ extern crate rayon;
 mod rayon;
 
 use crate::atomicmin::AtomicMin;
-use crate::colors::{BitDepth, ColorType};
+use crate::colors::BitDepth;
 use crate::deflate::{crc32, inflate};
 use crate::evaluate::Evaluator;
 use crate::png::PngData;
 use crate::png::PngImage;
 use crate::reduction::*;
-use log::{debug, info, warn};
+use log::{debug, info, trace, warn};
 use rayon::prelude::*;
 use std::fmt;
 use std::fs::{copy, File, Metadata};
@@ -330,7 +330,7 @@ pub fn optimize(input: &InFile, output: &OutFile, opts: &Options) -> PngResult<(
                         ))
                     })
                     .map(Some)?;
-                debug!("preserving metadata: {:?}", opt_metadata_preserved);
+                trace!("preserving metadata: {:?}", opt_metadata_preserved);
             } else {
                 opt_metadata_preserved = None;
             }
@@ -532,7 +532,7 @@ fn optimize_png(
             }
 
             if !filters.is_empty() {
-                debug!("Evaluating: {} filters", filters.len());
+                trace!("Evaluating: {} filters", filters.len());
                 let eval = Evaluator::new(deadline, filters, eval_compression, opts.optimize_alpha);
                 if eval_filter.is_some() {
                     eval.set_best_size(png.idat_data.len());
@@ -615,7 +615,7 @@ fn optimize_png(
             png.idat_data = idat_data;
             debug!("Found better combination:");
             debug!(
-                "    zc = {}  f = {}  {} bytes",
+                "    zc = {}  f = {:8}  {} bytes",
                 opts.compression,
                 opts.filter,
                 png.idat_data.len()
@@ -746,16 +746,20 @@ fn perform_trial(
     match new_idat {
         Ok(n) => {
             let bytes = n.len();
-            debug!(
+            trace!(
-                "    zc = {}  f = {}  {} bytes",
+                "    zc = {}  f = {:8}  {} bytes",
-                trial.compression, trial.filter, bytes
+                trial.compression,
+                trial.filter,
+                bytes
             );
             Some((trial, n))
         }
         Err(PngError::DeflatedDataTooLong(bytes)) => {
-            debug!(
+            trace!(
-                "    zc = {}  f = {} >{} bytes",
+                "    zc = {}  f = {:8} >{} bytes",
-                trial.compression, trial.filter, bytes,
+                trial.compression,
+                trial.filter,
+                bytes,
             );
             None
         }
@@ -814,24 +818,10 @@ impl Deadline {
 
 /// Display the format of the image data
 fn report_format(prefix: &str, png: &PngImage) {
-    if let ColorType::Indexed { palette } = &png.ihdr.color_type {
+    debug!(
-        debug!(
+        "{}{}-bit {}, {}",
-            "{}{} bits/pixel, {} colors in palette ({})",
+        prefix, png.ihdr.bit_depth, png.ihdr.color_type, png.ihdr.interlaced
-            prefix,
+    );
-            png.ihdr.bit_depth,
-            palette.len(),
-            png.ihdr.interlaced
-        );
-    } else {
-        debug!(
-            "{}{}x{} bits/pixel, {} ({})",
-            prefix,
-            png.channels_per_pixel(),
-            png.ihdr.bit_depth,
-            png.ihdr.color_type,
-            png.ihdr.interlaced
-        );
-    }
 }
 
 /// Strip headers from the `PngData` object, as requested by the passed `Options`
@@ -1032,9 +1022,10 @@ fn copy_times(_: &Metadata, _: &Path) -> PngResult<()> {
 fn copy_times(input_path_meta: &Metadata, out_path: &Path) -> PngResult<()> {
     let atime = filetime::FileTime::from_last_access_time(input_path_meta);
     let mtime = filetime::FileTime::from_last_modification_time(input_path_meta);
-    debug!(
+    trace!(
         "attempting to set file times: atime: {:?}, mtime: {:?}",
-        atime, mtime
+        atime,
+        mtime
     );
     filetime::set_file_times(out_path, atime, mtime).map_err(|err_io| {
         PngError::new(&format!(

src/main.rs

@@ -13,7 +13,7 @@
 #![warn(clippy::range_plus_one)]
 #![allow(clippy::cognitive_complexity)]
 
-use clap::{AppSettings, Arg, ArgMatches, Command};
+use clap::{AppSettings, Arg, ArgAction, ArgMatches, Command};
 use indexmap::IndexSet;
 use log::{error, warn};
 use oxipng::Deflaters;
@@ -154,9 +154,10 @@ fn main() {
         )
         .arg(
             Arg::new("verbose")
-                .help("Run in verbose mode")
+                .help("Run in verbose mode (use multiple times to increase verbosity)")
                 .short('v')
                 .long("verbose")
+                .action(ArgAction::Count)
                 .conflicts_with("quiet"),
         )
         .arg(
@@ -381,7 +382,7 @@ fn parse_opts_into_struct(
     stderrlog::new()
         .module(module_path!())
         .quiet(matches.is_present("quiet"))
-        .verbosity(if matches.is_present("verbose") { 3 } else { 2 })
+        .verbosity(matches.get_count("verbose") as usize + 2)
         .show_level(false)
         .init()
         .unwrap();

tests/flags.rs

@@ -180,34 +180,26 @@ fn verbose_mode() {
     });
 
     let logs: Vec<_> = receiver.into_iter().collect();
-    println!("logs={:?}", logs);
+    let expected_prefixes = [
-    assert_eq!(logs.len(), 9);
-    let expected_logs = [
         "    500x400 pixels, PNG format",
-        "    3x8 bits/pixel, RGB (non-interlaced)",
+        "    8-bit RGB, non-interlaced",
         "    IDAT size = 113794 bytes",
         "    File size = 114708 bytes",
         "Trying: 1 filters",
-        "    zc = 11  f = None      149409 bytes",
         "Found better combination:",
-        "    zc = 11  f = None      149409 bytes",
+        "    zc = 11  f = None ",
-        "    IDAT size = 149409 bytes",
+        "    IDAT size = ",
     ];
-    for (idx, expected_log) in expected_logs.into_iter().enumerate() {
+    assert_eq!(logs.len(), expected_prefixes.len());
-        if let Some(log) = logs.get(idx) {
+    for (i, log) in logs.into_iter().enumerate() {
-            if !log.starts_with(expected_log) {
+        let expected_prefix = expected_prefixes[i];
-                panic!(
+        assert!(
-                    "logs[{}] = {:?} doesn't start with {:?}",
+            log.starts_with(&expected_prefix),
-                    idx, log, expected_log
+            "logs[{}] = {:?} doesn't start with {:?}",
-                );
+            i,
-            }
+            log,
-        } else {
+            expected_prefix
-            panic!(
+        );
-                "Expected to find {} log entries, but got {}",
-                expected_logs.len(),
-                logs.len()
-            );
-        }
     }
 }