Repository: shssoichiro/oxipng
Pull request #501 (2023-04-26 03:21:15)

More flexible verbosity, improve verbose test
I started this after noticing that #495 is failing the verbose test. It turned out the reason is #489 inadvertently ended up making the test more fragile than it was before by including the file size in the expected output.
I've partially reverted some of the code in that test so it should be more robust. But I also thought it might be helpful to make the logging more flexible in general by making use of the `trace` level and allowing the `-v` option to be specified multiple times.

"Info", default verbosity (since #489):
(See also #419 - is this terse enough @folknor?)
```
Processing: tests/files/rgba_8_should_be_palette_8.png
    file size = 12030 bytes (13332 bytes = 52.57% decrease)
Output: tests/files/rgba_8_should_be_palette_8.out.png
```

"Debug", with `-v` (same as info prior to #489):
```
Processing: tests/files/rgba_8_should_be_palette_8.png
    500x400 pixels, PNG format
    8-bit RGB + Alpha, non-interlaced
    IDAT size = 25269 bytes
    File size = 25362 bytes
Reducing image to 8-bit Indexed (35 colors), non-interlaced
Trying: 10 filters
Found better combination:
    zc = 12  f = Sub       11856 bytes
    IDAT size = 11856 bytes (13413 bytes decrease)
    file size = 12030 bytes (13332 bytes = 52.57% decrease)
Output: tests/files/rgba_8_should_be_palette_8.out.png
```

"Trace", with `-vv` (like debug previously but with extra eval lines):
```
Processing: tests/files/rgba_8_should_be_palette_8.png
preserving metadata: Some(Metadata { file_type: FileType(FileType { mode: 33188 }), is_dir: false, is_file: true, permissions: Permissions(FilePermissions { mode: 33188 }), modified: Ok(SystemTime { tv_sec: 1666382601, tv_nsec: 376109094 }), accessed: Ok(SystemTime { tv_sec: 1681707679, tv_nsec: 992982008 }), created: Ok(SystemTime { tv_sec: 1666382601, tv_nsec: 375899395 }), .. })
    500x400 pixels, PNG format
    8-bit RGB + Alpha, non-interlaced
    IDAT size = 25269 bytes
    File size = 25362 bytes
Eval: 8-bit Indexed (35 colors)   None       15245 bytes
Eval: 8-bit RGB + Alpha           None      >15245 bytes
Eval: 8-bit Indexed (35 colors)   Bigrams   >15254 bytes
Eval: 8-bit RGB + Alpha           Bigrams   >15254 bytes
Reducing image to 8-bit Indexed (35 colors), non-interlaced
Trying: 10 filters
    zc = 12  f = None      11928 bytes
    zc = 12  f = MinSum   >11928 bytes
    zc = 12  f = Entropy  >11928 bytes
    zc = 12  f = Paeth    >11928 bytes
    zc = 12  f = Average  >11928 bytes
    zc = 12  f = Sub       11856 bytes
    zc = 12  f = BigEnt   >11928 bytes
    zc = 12  f = Bigrams  >11856 bytes
    zc = 12  f = Up       >11937 bytes
    zc = 12  f = Brute    >11865 bytes
Found better combination:
    zc = 12  f = Sub       11856 bytes
    IDAT size = 11856 bytes (13413 bytes decrease)
    file size = 12030 bytes (13332 bytes = 52.57% decrease)
attempting to set file times: atime: FileTime { seconds: 1681707679, nanos: 992982008 }, mtime: FileTime { seconds: 1666382601, nanos: 376109094 }
Output: tests/files/rgba_8_should_be_palette_8.out.png
```

andrews05: @shssoichiro What should the verbose test actually be testing anyway? I figure it probably doesn't need to be checking all 8 of those lines, but I'm not sure what would be appropriate.
andrews05: I've added some additional logging at trace level for the evaluator. Minor changes to the reporting format were required to make this work nicely.

Patch:
diff --git a/src/colors.rs b/src/colors.rs
index 32999849..77ee9818 100644
--- a/src/colors.rs
+++ b/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!(
-            f,
-            "{}",
-            match *self {
-                ColorType::Grayscale { .. } => "Grayscale",
-                ColorType::RGB { .. } => "RGB",
-                ColorType::Indexed { .. } => "Indexed",
-                ColorType::GrayscaleAlpha => "Grayscale + Alpha",
-                ColorType::RGBA => "RGB + Alpha",
+        match self {
+            ColorType::Grayscale { .. } => Display::fmt("Grayscale", f),
+            ColorType::RGB { .. } => Display::fmt("RGB", f),
+            ColorType::Indexed { palette } => {
+                Display::fmt(&format!("Indexed ({} colors)", palette.len()), f)
             }
-        )
+            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)
     }
 }
diff --git a/src/evaluate.rs b/src/evaluate.rs
index ee92b17a..833f41c6 100644
--- a/src/evaluate.rs
+++ b/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) =
-                    deflate::deflate(&filtered, compression, &best_candidate_size)
-                {
+                let idat_data = 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
+                    );
                 }
             });
         });
diff --git a/src/filters.rs b/src/filters.rs
index d43c2833..1fec39e6 100644
--- a/src/filters.rs
+++ b/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 {
-        write!(
-            f,
-            "{:8}",
-            match *self {
+    fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
+        Display::fmt(
+            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,
         )
     }
 }
diff --git a/src/interlace.rs b/src/interlace.rs
index 88c146ff..0fd63f21 100644
--- a/src/interlace.rs
+++ b/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 {
-        write!(
-            f,
-            "{}",
-            match *self {
+    fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
+        Display::fmt(
+            match self {
                 Self::None => "non-interlaced",
                 Self::Adam7 => "interlaced",
-            }
+            },
+            f,
         )
     }
 }
diff --git a/src/lib.rs b/src/lib.rs
index d88746b7..d331c6dc 100644
--- a/src/lib.rs
+++ b/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!(
-                "    zc = {}  f = {}  {} bytes",
-                trial.compression, trial.filter, bytes
+            trace!(
+                "    zc = {}  f = {:8}  {} bytes",
+                trial.compression,
+                trial.filter,
+                bytes
             );
             Some((trial, n))
         }
         Err(PngError::DeflatedDataTooLong(bytes)) => {
-            debug!(
-                "    zc = {}  f = {} >{} bytes",
-                trial.compression, trial.filter, bytes,
+            trace!(
+                "    zc = {}  f = {:8} >{} 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!(
-            "{}{} bits/pixel, {} colors in palette ({})",
-            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
-        );
-    }
+    debug!(
+        "{}{}-bit {}, {}",
+        prefix, 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!(
diff --git a/src/main.rs b/src/main.rs
index b484fac6..3676e85e 100644
--- a/src/main.rs
+++ b/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();


Test patch:
diff --git a/tests/flags.rs b/tests/flags.rs
index d31f70e2..3690f21a 100644
--- a/tests/flags.rs
+++ b/tests/flags.rs
@@ -180,34 +180,26 @@ fn verbose_mode() {
     });
 
     let logs: Vec<_> = receiver.into_iter().collect();
-    println!("logs={:?}", logs);
-    assert_eq!(logs.len(), 9);
-    let expected_logs = [
+    let expected_prefixes = [
         "    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",
-        "    IDAT size = 149409 bytes",
+        "    zc = 11  f = None ",
+        "    IDAT size = ",
     ];
-    for (idx, expected_log) in expected_logs.into_iter().enumerate() {
-        if let Some(log) = logs.get(idx) {
-            if !log.starts_with(expected_log) {
-                panic!(
-                    "logs[{}] = {:?} doesn't start with {:?}",
-                    idx, log, expected_log
-                );
-            }
-        } else {
-            panic!(
-                "Expected to find {} log entries, but got {}",
-                expected_logs.len(),
-                logs.len()
-            );
-        }
+    assert_eq!(logs.len(), expected_prefixes.len());
+    for (i, log) in logs.into_iter().enumerate() {
+        let expected_prefix = expected_prefixes[i];
+        assert!(
+            log.starts_with(&expected_prefix),
+            "logs[{}] = {:?} doesn't start with {:?}",
+            i,
+            log,
+            expected_prefix
+        );
     }
 }