libtuning: Migrate prints to python logging framework

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>
Reviewed-by: Paul Elder <paul.elder@ideasonboard.com>
Reviewed-by: Daniel Scally <dan.scally@ideasonboard.com>

9 files changed, 62 insertions, 46 deletions

diff --git a/utils/tuning/libtuning/ctt_ccm.py b/utils/tuning/libtuning/ctt_ccm.py
index f37adaf4..c4362756 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 8f22d386..31e265df 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 6ff60ec1..2c4d774f 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 5e22288d..5342e5d6 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 265a33d6..28051de8 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 f19c7163..99bc4fe6 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 f099c0ed..87234140 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 b2875524..3705769b 100644
--- a/utils/tuning/requirements.txt
+++ b/utils/tuning/requirements.txt
@@ -1,3 +1,4 @@
+coloredlogs
 matplotlib
 numpy
 opencv-python
diff --git a/utils/tuning/rkisp1.py b/utils/tuning/rkisp1.py
index d0ce15d5..2606e07a 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')
+
 tuner = lt.Tuner('RkISP1')
 tuner.add(LSCRkISP1(
           debug=[lt.Debug.Plot],