[v2,07/25] libtuning: Migrate prints to python logging framework

20466 diff mbox series

In ctt_ccm.py the logging functionality of the Cam object was used. As
we don't want to port over that class, it needs to be replaced anyways.
While at it, also replace the eprint function as it doesn't add any
value over the logging framework and misses the ability for easy log
formatting.

For nice output formatting add the coloredlogs library.

Signed-off-by: Stefan Klug <stefan.klug@ideasonboard.com>
---
 utils/tuning/libtuning/ctt_ccm.py             | 27 ++++++++++---------
 .../libtuning/generators/yaml_output.py       |  5 ++--
 utils/tuning/libtuning/image.py               |  7 +++--
 utils/tuning/libtuning/libtuning.py           | 21 ++++++++-------
 utils/tuning/libtuning/macbeth.py             | 13 +++++----
 .../libtuning/modules/lsc/raspberrypi.py      | 12 +++++----
 utils/tuning/libtuning/utils.py               | 17 ++++++------
 utils/tuning/requirements.txt                 |  2 ++
 utils/tuning/rkisp1.py                        |  5 ++++
 9 files changed, 63 insertions(+), 46 deletions(-)

Hi Stefan,

Thank you for the patch.

On Fri, Jun 28, 2024 at 12:47:00PM +0200, Stefan Klug wrote:
> In ctt_ccm.py the logging functionality of the Cam object was used. As
> we don't want to port over that class, it needs to be replaced anyways.
> While at it, also replace the eprint function as it doesn't add any
> value over the logging framework and misses the ability for easy log
> formatting.
> 
> For nice output formatting add the coloredlogs library.
> 
> Signed-off-by: Stefan Klug <stefan.klug@ideasonboard.com>
> ---
>  utils/tuning/libtuning/ctt_ccm.py             | 27 ++++++++++---------
>  .../libtuning/generators/yaml_output.py       |  5 ++--
>  utils/tuning/libtuning/image.py               |  7 +++--
>  utils/tuning/libtuning/libtuning.py           | 21 ++++++++-------
>  utils/tuning/libtuning/macbeth.py             | 13 +++++----
>  .../libtuning/modules/lsc/raspberrypi.py      | 12 +++++----
>  utils/tuning/libtuning/utils.py               | 17 ++++++------
>  utils/tuning/requirements.txt                 |  2 ++
>  utils/tuning/rkisp1.py                        |  5 ++++
>  9 files changed, 63 insertions(+), 46 deletions(-)
> 
> diff --git a/utils/tuning/libtuning/ctt_ccm.py b/utils/tuning/libtuning/ctt_ccm.py
> index f37adaf45538..c4362756c3c0 100644
> --- a/utils/tuning/libtuning/ctt_ccm.py
> +++ b/utils/tuning/libtuning/ctt_ccm.py
> @@ -4,6 +4,8 @@
>  #
>  # camera tuning tool for CCM (colour correction matrix)
>  
> +import logging
> +
>  import numpy as np
>  from scipy.optimize import minimize
>  
> @@ -12,6 +14,8 @@ from .image import Image
>  from .ctt_awb import get_alsc_patches
>  from .utils import visualise_macbeth_chart
>  
> +logger = logging.getLogger(__name__)
> +
>  """
>  takes 8-bit macbeth chart values, degammas and returns 16 bit
>  """
> @@ -129,7 +133,7 @@ def ccm(Cam, cal_cr_list, cal_cb_list):
>      """
>      ccm_tab = {}
>      for Img in imgs:
> -        Cam.log += '\nProcessing image: ' + Img.name
> +        logger.info('Processing image: ' + Img.name)
>          """
>          get macbeth patches with alsc applied if alsc enabled.
>          Note: if alsc is disabled then colour_cals will be set to None and no
> @@ -154,7 +158,7 @@ def ccm(Cam, cal_cr_list, cal_cb_list):
>          each channel for each patch
>          """
>          gain = np.mean(m_srgb) / np.mean((r, g, b))
> -        Cam.log += '\nGain with respect to standard colours: {:.3f}'.format(gain)
> +        logger.info(f'Gain with respect to standard colours: {gain:.3f}')
>          r = np.mean(gain * r, axis=1)
>          b = np.mean(gain * b, axis=1)
>          g = np.mean(gain * g, axis=1)
> @@ -192,15 +196,13 @@ def ccm(Cam, cal_cr_list, cal_cb_list):
>          zero since the input data is imperfect
>          '''
>  
> -        Cam.log += ("\n \n Optimised Matrix Below: \n \n")
>          [r1, r2, g1, g2, b1, b2] = result.x
>          # The new, optimised color correction matrix values
> +        # This is the optimised Color Matrix (preserving greys by summing rows up to 1)
>          optimised_ccm = [r1, r2, (1 - r1 - r2), g1, g2, (1 - g1 - g2), b1, b2, (1 - b1 - b2)]
>  
> -        # This is the optimised Color Matrix (preserving greys by summing rows up to 1)
> -        Cam.log += str(optimised_ccm)
> -        Cam.log += "\n Old Color Correction Matrix Below \n"
> -        Cam.log += str(ccm)
> +        logger.info(f'Optimized Matrix: {np.round(optimised_ccm, 4)}')
> +        logger.info(f'Old Matrix:       {np.round(ccm, 4)}')
>  
>          formatted_ccm = np.array(original_ccm).reshape((3, 3))
>  
> @@ -229,7 +231,7 @@ def ccm(Cam, cal_cr_list, cal_cb_list):
>          We now want to spit out some data that shows
>          how the optimisation has improved the color matrices
>          '''
> -        Cam.log += "Here are the Improvements"
> +        logger.info("Here are the Improvements")
>  
>          # CALCULATE WORST CASE delta e
>          old_worst_delta_e = 0
> @@ -244,8 +246,8 @@ def ccm(Cam, cal_cr_list, cal_cb_list):
>              if new_delta_e > new_worst_delta_e:
>                  new_worst_delta_e = new_delta_e
>  
> -        Cam.log += "Before color correction matrix was optimised, we got an average delta E of " + str(before_average) + " and a maximum delta E of " + str(old_worst_delta_e)
> -        Cam.log += "After color correction matrix was optimised, we got an average delta E of " + str(after_average) + " and a maximum delta E of " + str(new_worst_delta_e)
> +        logger.info(f'delta E optimized: average: {after_average:.2f}  max:{new_worst_delta_e:.2f}')
> +        logger.info(f'delta E old:       average: {before_average:.2f}  max:{old_worst_delta_e:.2f}')
>  
>          visualise_macbeth_chart(m_rgb, optimised_ccm_rgb, after_gamma_rgb, str(Img.col) + str(matrix_selection_types[typenum]))
>          '''
> @@ -262,9 +264,8 @@ def ccm(Cam, cal_cr_list, cal_cb_list):
>              ccm_tab[Img.col].append(optimised_ccm)
>          else:
>              ccm_tab[Img.col] = [optimised_ccm]
> -        Cam.log += '\n'
>  
> -    Cam.log += '\nFinished processing images'
> +    logger.info('Finished processing images')
>      """
>      average any ccms that share a colour temperature
>      """
> @@ -273,7 +274,7 @@ def ccm(Cam, cal_cr_list, cal_cb_list):
>          tab = np.where((10000 * tab) % 1 <= 0.05, tab + 0.00001, tab)
>          tab = np.where((10000 * tab) % 1 >= 0.95, tab - 0.00001, tab)
>          ccm_tab[k] = list(np.round(tab, 5))
> -        Cam.log += '\nMatrix calculated for colour temperature of {} K'.format(k)
> +        logger.info(f'Matrix calculated for colour temperature of {k} K')
>  
>      """
>      return all ccms with respective colour temperature in the correct format,
> diff --git a/utils/tuning/libtuning/generators/yaml_output.py b/utils/tuning/libtuning/generators/yaml_output.py
> index 8f22d386f1b3..31e265df4ea7 100644
> --- a/utils/tuning/libtuning/generators/yaml_output.py
> +++ b/utils/tuning/libtuning/generators/yaml_output.py
> @@ -9,8 +9,9 @@ from .generator import Generator
>  from numbers import Number
>  from pathlib import Path
>  
> -import libtuning.utils as utils
> +import logging
>  
> +logger = logging.getLogger(__name__)
>  
>  class YamlOutput(Generator):
>      def __init__(self):
> @@ -112,7 +113,7 @@ class YamlOutput(Generator):
>                  continue
>  
>              if not isinstance(output_dict[module], dict):
> -                utils.eprint(f'Error: Output of {module.type} is not a dictionary')
> +                logger.error(f'Error: Output of {module.type} is not a dictionary')
>                  continue
>  
>              lines = self._stringify_dict(output_dict[module])
> diff --git a/utils/tuning/libtuning/image.py b/utils/tuning/libtuning/image.py
> index 6ff60ec17ec4..2c4d774f11e2 100644
> --- a/utils/tuning/libtuning/image.py
> +++ b/utils/tuning/libtuning/image.py
> @@ -13,6 +13,9 @@ import re
>  
>  import libtuning as lt
>  import libtuning.utils as utils
> +import logging
> +
> +logger = logging.getLogger(__name__)
>  
>  
>  class Image:
> @@ -25,13 +28,13 @@ class Image:
>          try:
>              self._load_metadata_exif()
>          except Exception as e:
> -            utils.eprint(f'Failed to load metadata from {self.path}: {e}')
> +            logger.error(f'Failed to load metadata from {self.path}: {e}')
>              raise e
>  
>          try:
>              self._read_image_dng()
>          except Exception as e:
> -            utils.eprint(f'Failed to load image data from {self.path}: {e}')
> +            logger.error(f'Failed to load image data from {self.path}: {e}')
>              raise e
>  
>      @property
> diff --git a/utils/tuning/libtuning/libtuning.py b/utils/tuning/libtuning/libtuning.py
> index 5e22288df49b..5342e5d6daaa 100644
> --- a/utils/tuning/libtuning/libtuning.py
> +++ b/utils/tuning/libtuning/libtuning.py
> @@ -5,13 +5,14 @@
>  # An infrastructure for camera tuning tools
>  
>  import argparse
> +import logging
>  
>  import libtuning as lt
>  import libtuning.utils as utils
> -from libtuning.utils import eprint
>  
>  from enum import Enum, IntEnum
>  
> +logger = logging.getLogger(__name__)
>  
>  class Color(IntEnum):
>      R = 0
> @@ -112,10 +113,10 @@ class Tuner(object):
>          for module_type in output_order:
>              modules = [module for module in self.modules if module.type == module_type.type]
>              if len(modules) > 1:
> -                eprint(f'Multiple modules found for module type "{module_type.type}"')
> +                logger.error(f'Multiple modules found for module type "{module_type.type}"')
>                  return False
>              if len(modules) < 1:
> -                eprint(f'No module found for module type "{module_type.type}"')
> +                logger.error(f'No module found for module type "{module_type.type}"')
>                  return False
>              self.output_order.append(modules[0])
>  
> @@ -124,19 +125,19 @@ class Tuner(object):
>      # \todo Validate parser and generator at Tuner construction time?
>      def _validate_settings(self):
>          if self.parser is None:
> -            eprint('Missing parser')
> +            logger.error('Missing parser')
>              return False
>  
>          if self.generator is None:
> -            eprint('Missing generator')
> +            logger.error('Missing generator')
>              return False
>  
>          if len(self.modules) == 0:
> -            eprint('No modules added')
> +            logger.error('No modules added')
>              return False
>  
>          if len(self.output_order) != len(self.modules):
> -            eprint('Number of outputs does not match number of modules')
> +            logger.error('Number of outputs does not match number of modules')
>              return False
>  
>          return True
> @@ -183,7 +184,7 @@ class Tuner(object):
>  
>          for module in self.modules:
>              if not module.validate_config(self.config):
> -                eprint(f'Config is invalid for module {module.type}')
> +                logger.error(f'Config is invalid for module {module.type}')
>                  return -1
>  
>          has_lsc = any(isinstance(m, lt.modules.lsc.LSC) for m in self.modules)
> @@ -192,14 +193,14 @@ class Tuner(object):
>  
>          images = utils.load_images(args.input, self.config, not has_only_lsc, has_lsc)
>          if images is None or len(images) == 0:
> -            eprint(f'No images were found, or able to load')
> +            logger.error(f'No images were found, or able to load')
>              return -1
>  
>          # Do the tuning
>          for module in self.modules:
>              out = module.process(self.config, images, self.output)
>              if out is None:
> -                eprint(f'Module {module.name} failed to process, aborting')
> +                logger.error(f'Module {module.hr_name} failed to process...')
>                  break
>              self.output[module] = out
>  
> diff --git a/utils/tuning/libtuning/macbeth.py b/utils/tuning/libtuning/macbeth.py
> index 265a33d68378..28051de8155c 100644
> --- a/utils/tuning/libtuning/macbeth.py
> +++ b/utils/tuning/libtuning/macbeth.py
> @@ -13,12 +13,15 @@ import os
>  from pathlib import Path
>  import numpy as np
>  import warnings
> +import logging
>  from sklearn import cluster as cluster
>  
>  from .ctt_ransac import get_square_verts, get_square_centres
>  
>  from libtuning.image import Image
>  
> +logger = logging.getLogger(__name__)
> +
>  
>  # Reshape image to fixed width without distorting returns image and scale
>  # factor
> @@ -374,7 +377,7 @@ def get_macbeth_chart(img, ref_data):
>  
>      # Catch macbeth errors and continue with code
>      except MacbethError as error:
> -        eprint(error)
> +        logger.warning(error)
>          return (0, None, None, False)
>  
>  
> @@ -497,7 +500,7 @@ def find_macbeth(img, mac_config):
>  
>      coords_fit = coords
>      if cor < 0.75:
> -        eprint(f'Warning: Low confidence {cor:.3f} for macbeth chart in {img.path.name}')
> +        logger.warning(f'Low confidence {cor:.3f} for macbeth chart')
>  
>      if show:
>          draw_macbeth_results(img, coords_fit)
> @@ -510,18 +513,18 @@ def locate_macbeth(image: Image, config: dict):
>      av_chan = (np.mean(np.array(image.channels), axis=0) / (2**16))
>      av_val = np.mean(av_chan)
>      if av_val < image.blacklevel_16 / (2**16) + 1 / 64:
> -        eprint(f'Image {image.path.name} too dark')
> +        logger.warning(f'Image {image.path.name} too dark')
>          return None
>  
>      macbeth = find_macbeth(av_chan, config['general']['macbeth'])
>  
>      if macbeth is None:
> -        eprint(f'No macbeth chart found in {image.path.name}')
> +        logger.warning(f'No macbeth chart found in {image.path.name}')
>          return None
>  
>      mac_cen_coords = macbeth[1]
>      if not image.get_patches(mac_cen_coords):
> -        eprint(f'Macbeth patches have saturated in {image.path.name}')
> +        logger.warning(f'Macbeth patches have saturated in {image.path.name}')
>          return None
>  
>      return macbeth
> diff --git a/utils/tuning/libtuning/modules/lsc/raspberrypi.py b/utils/tuning/libtuning/modules/lsc/raspberrypi.py
> index f19c71637b89..99bc4fe6e07f 100644
> --- a/utils/tuning/libtuning/modules/lsc/raspberrypi.py
> +++ b/utils/tuning/libtuning/modules/lsc/raspberrypi.py
> @@ -12,7 +12,9 @@ import libtuning.utils as utils
>  
>  from numbers import Number
>  import numpy as np
> +import logging
>  
> +logger = logging.getLogger(__name__)
>  
>  class ALSCRaspberryPi(LSC):
>      # Override the type name so that the parser can match the entry in the
> @@ -35,7 +37,7 @@ class ALSCRaspberryPi(LSC):
>  
>      def validate_config(self, config: dict) -> bool:
>          if self not in config:
> -            utils.eprint(f'{self.type} not in config')
> +            logger.error(f'{self.type} not in config')
>              return False
>  
>          valid = True
> @@ -46,14 +48,14 @@ class ALSCRaspberryPi(LSC):
>          color_key = self.do_color.name
>  
>          if lum_key not in conf and self.luminance_strength.required:
> -            utils.eprint(f'{lum_key} is not in config')
> +            logger.error(f'{lum_key} is not in config')
>              valid = False
>  
>          if lum_key in conf and (conf[lum_key] < 0 or conf[lum_key] > 1):
> -            utils.eprint(f'Warning: {lum_key} is not in range [0, 1]; defaulting to 0.5')
> +            logger.warning(f'{lum_key} is not in range [0, 1]; defaulting to 0.5')
>  
>          if color_key not in conf and self.do_color.required:
> -            utils.eprint(f'{color_key} is not in config')
> +            logger.error(f'{color_key} is not in config')
>              valid = False
>  
>          return valid
> @@ -235,7 +237,7 @@ class ALSCRaspberryPi(LSC):
>          if count == 1:
>              output['sigma'] = 0.005
>              output['sigma_Cb'] = 0.005
> -            utils.eprint('Warning: Only one alsc calibration found; standard sigmas used for adaptive algorithm.')
> +            logger.warning('Only one alsc calibration found; standard sigmas used for adaptive algorithm.')
>              return output
>  
>          # Obtain worst-case scenario residual sigmas
> diff --git a/utils/tuning/libtuning/utils.py b/utils/tuning/libtuning/utils.py
> index f099c0ed685c..872341407b7b 100644
> --- a/utils/tuning/libtuning/utils.py
> +++ b/utils/tuning/libtuning/utils.py
> @@ -12,16 +12,15 @@ import os
>  from pathlib import Path
>  import re
>  import sys
> +import logging
>  
>  import libtuning as lt
>  from libtuning.image import Image
>  from libtuning.macbeth import locate_macbeth
>  
> -# Utility functions
> -
> +logger = logging.getLogger(__name__)
>  
> -def eprint(*args, **kwargs):
> -    print(*args, file=sys.stderr, **kwargs)
> +# Utility functions
>  
>  
>  def get_module_by_type_name(modules, name):
> @@ -45,7 +44,7 @@ def _list_image_files(directory):
>  def _parse_image_filename(fn: Path):
>      result = re.search(r'^(alsc_)?(\d+)[kK]_(\d+)?[lLuU]?.\w{3,4}$', fn.name)
>      if result is None:
> -        eprint(f'The file name of {fn.name} is incorrectly formatted')
> +        logger.error(f'The file name of {fn.name} is incorrectly formatted')
>          return None, None, None
>  
>      color = int(result.group(2))
> @@ -72,7 +71,7 @@ def _validate_images(images):
>  def load_images(input_dir: str, config: dict, load_nonlsc: bool, load_lsc: bool) -> list:
>      files = _list_image_files(input_dir)
>      if len(files) == 0:
> -        eprint(f'No images found in {input_dir}')
> +        logger.error(f'No images found in {input_dir}')
>          return None
>  
>      images = []
> @@ -83,19 +82,19 @@ def load_images(input_dir: str, config: dict, load_nonlsc: bool, load_lsc: bool)
>  
>          # Skip lsc image if we don't need it
>          if lsc_only and not load_lsc:
> -            eprint(f'Skipping {f.name} as this tuner has no LSC module')
> +            logger.warning(f'Skipping {f.name} as this tuner has no LSC module')
>              continue
>  
>          # Skip non-lsc image if we don't need it
>          if not lsc_only and not load_nonlsc:
> -            eprint(f'Skipping {f.name} as this tuner only has an LSC module')
> +            logger.warning(f'Skipping {f.name} as this tuner only has an LSC module')
>              continue
>  
>          # Load image
>          try:
>              image = Image(f)
>          except Exception as e:
> -            eprint(f'Failed to load image {f.name}: {e}')
> +            logger.error(f'Failed to load image {f.name}: {e}')
>              continue
>  
>          # Populate simple fields
> diff --git a/utils/tuning/requirements.txt b/utils/tuning/requirements.txt
> index d1dc589d0329..2b6ed45c1cc0 100644
> --- a/utils/tuning/requirements.txt
> +++ b/utils/tuning/requirements.txt
> @@ -1,5 +1,7 @@
> +coloredlogs
>  numpy
>  opencv-python
>  py3exiv2
>  pyyaml
>  rawpy
> +

You can drop the empty line.

> diff --git a/utils/tuning/rkisp1.py b/utils/tuning/rkisp1.py
> index d0ce15d5ed7a..2606e07a93f7 100755
> --- a/utils/tuning/rkisp1.py
> +++ b/utils/tuning/rkisp1.py
> @@ -5,6 +5,8 @@
>  #
>  # Tuning script for rkisp1
>  
> +import coloredlogs
> +import logging
>  import sys
>  
>  import libtuning as lt
> @@ -13,6 +15,9 @@ from libtuning.generators import YamlOutput
>  from libtuning.modules.lsc import LSCRkISP1
>  from libtuning.modules.agc import AGCRkISP1
>  
> +
> +coloredlogs.install(level=logging.INFO, fmt='%(name)s %(levelname)s %(message)s')
> +

Should this go go libtuning/__init__.py, or do you envision different
tuning scripts configuring logging differently ?

>  tuner = lt.Tuner('RkISP1')
>  tuner.add(LSCRkISP1(
>            debug=[lt.Debug.Plot],