Merge pull request #1000 from TheDeanLab/logging-updates

Attempt to come up with a more scalable approach to logging.

Author: AdvancedImagingUTSW

src/navigate/controller/controller.py

@@ -40,6 +40,7 @@
 import os
 import time
 import platform
+import reprlib
 
 # Third Party Imports
 
@@ -82,7 +83,7 @@
     verify_configuration,
     get_navigate_path,
 )
-from navigate.tools.file_functions import create_save_path, save_yaml_file
+from navigate.tools.file_functions import create_save_path, save_yaml_file, get_ram_info
 from navigate.tools.common_dict_tools import update_stage_dict
 from navigate.tools.multipos_table_tools import update_table
 from navigate.tools.common_functions import combine_funcs
@@ -96,7 +97,6 @@
 
 class Controller:
     """Navigate Controller"""
-
     def __init__(
         self,
         root,
@@ -139,7 +139,6 @@ def __init__(
             Command line input arguments for non-default
             file paths or using synthetic hardware modes.
         """
-
         #: Tk top-level widget: Tk.tk GUI instance.
         self.root = root
 
@@ -148,24 +147,31 @@ def __init__(
 
         #: string: Path to the configuration yaml file.
         self.configuration_path = configuration_path
+        logger.info(f"Configuration Path: {self.configuration_path}")
 
         #: string: Path to the experiment yaml file.
         self.experiment_path = experiment_path
+        logger.info(f"Experiment Path: {self.experiment_path}")
 
         #: string: Path to the waveform constants yaml file.
         self.waveform_constants_path = waveform_constants_path
+        logger.info(f"Waveform Constants Path: {self.waveform_constants_path}")
 
         #: string: Path to the REST API yaml file.
         self.rest_api_path = rest_api_path
+        logger.info(f"REST API Path: {self.rest_api_path}")
 
         #: string: Path to the waveform templates yaml file.
         self.waveform_templates_path = waveform_templates_path
+        logger.info(f"Waveform Templates Path: {self.waveform_templates_path}")
 
         #: string: Path to the GUI configuration yaml file.
         self.gui_configuration_path = gui_configuration_path
+        logger.info(f"GUI Configuration Path: {self.gui_configuration_path}")
 
         #: iterable: Non-default command line input arguments for
         self.args = args
+        logger.info(f"Variable Input Arguments: {self.args}")
 
         #: Object: Thread pool for the controller.
         self.threads_pool = SynchronizedThreadPool()
@@ -191,6 +197,10 @@ def __init__(
         verify_experiment_config(self.manager, self.configuration)
         verify_waveform_constants(self.manager, self.configuration)
 
+        total_ram, available_ram = get_ram_info()
+        logger.info(f"Total RAM: {total_ram / 1024**3:.2f} GB. "
+                    f"Available RAM: {available_ram / 1024**3:.2f} GB.")
+
         #: ObjectInSubprocess: Model object in MVC architecture.
         self.model = ObjectInSubprocess(
             Model, args, self.configuration, event_queue=self.event_queue
@@ -269,9 +279,6 @@ def __init__(
         t = threading.Thread(target=self.update_event)
         t.start()
 
-        # self.microscope = self.configuration['configuration']
-        # ['microscopes'].keys()[0]  # Default to the first microscope
-
         #: MenuController: Menu Sub-Controller.
         self.menu_controller = MenuController(view=self.view, parent_controller=self)
         self.menu_controller.initialize_menus()
@@ -321,17 +328,6 @@ def __init__(
         if platform.system() == "Windows":
             self.view.root.bind("<Configure>", self.resize)
 
-        logger.info(self.__repr__())
-
-    def __repr__(self):
-        return (
-            f'Controller("{self.root}", "{self.splash_screen}", '
-            f'"{self.configuration_path}", "{self.experiment_path}", '
-            f'"{self.waveform_constants_path}", "{self.rest_api_path}", '
-            f'"{self.waveform_templates_path}", "{self.gui_configuration_path}", '
-            f'"{self.args}")'
-        )
-
     def update_buffer(self):
         """Update the buffer size according to the camera
         dimensions listed in the experimental parameters.

src/navigate/controller/sub_controllers/acquire_bar.py

@@ -44,7 +44,6 @@
 p = __name__.split(".")[1]
 logger = logging.getLogger(p)
 
-
 class AcquireBarController(GUIController):
     """Acquire Bar Controller."""
 

src/navigate/controller/sub_controllers/camera_view.py

@@ -38,6 +38,7 @@
 from typing import Dict
 import tempfile
 import os
+import time
 
 # Third Party Imports
 import cv2
@@ -58,7 +59,6 @@
 p = __name__.split(".")[1]
 logger = logging.getLogger(p)
 
-
 class ABaseViewController(metaclass=abc.ABCMeta):
     """Abstract Base View Controller Class."""
 
@@ -429,6 +429,16 @@ def try_to_display_image(self, image):
         display_thread = threading.Thread(target=self.display_image, args=(image,))
         display_thread.start()
 
+    def display_image(self, image):
+        """Display an image.
+
+        Parameters
+        ----------
+        image : numpy.ndarray
+            Image data.
+        """
+        pass
+
     def apply_lut(self, image):
         """Applies a LUT to an image.
 
@@ -978,7 +988,7 @@ def update_min_max_counts(self, display=False):
             self.max_counts = float(self.image_palette["Max"].get())
         if display and self.image is not None:
             self.process_image()
-        logger.debug(
+        logger.info(
             f"Min and Max counts scaled to, {self.min_counts}, {self.max_counts}"
         )
 
@@ -1321,6 +1331,7 @@ def display_image(self, image):
         image : numpy.ndarray
             Image data.
         """
+        start_time = time.time()
         self.image = self.flip_image(image)
         self.max_intensity_history.append(np.max(image))
         if self._snr_selected:
@@ -1331,6 +1342,7 @@ def display_image(self, image):
         self.update_max_counts()
         with self.is_displaying_image as is_displaying_image:
             is_displaying_image.value = False
+        logger.info(f"Displaying image took {time.time() - start_time:.4f} seconds")
 
     def set_mask_color_table(self, colors):
         """Set up segmentation mask color table
@@ -1677,22 +1689,12 @@ def __init__(self, channels: int, size_y: int, size_x: int):
                 dir=default_directory,
             )
 
-        logger.info(self.__repr__())
-
     def __del__(self):
         """Delete the temporary files."""
         if self.temp_files is not None:
             for temp_file in self.temp_files.values():
                 temp_file.close()
 
-    def __repr__(self):
-        """Return the string representation of the SpooledImageLoader."""
-        return (
-            f"SpooledImageLoader(channels={len(self.temp_files)}, "
-            f"size_y={self.size_y}, "
-            f"size_x={self.size_x})"
-        )
-
     @staticmethod
     def get_default_max_size() -> int:
         """Get the default max_size based on the total RAM.

src/navigate/controller/sub_controllers/plugins.py

@@ -46,7 +46,6 @@
 from navigate.tools.decorators import AcquisitionMode
 from navigate.controller.sub_controllers.gui import GUIController
 from navigate.view.popups.plugins_popup import PluginsPopup
-
 from navigate.plugins.plugin_manager import PluginFileManager, PluginPackageManager
 
 

src/navigate/controller/sub_controllers/stages.py

@@ -39,12 +39,13 @@
 
 # Local Imports
 from navigate.controller.sub_controllers.gui import GUIController
+from navigate.model.devices import log_initialization
 
 # Logger Setup
 p = __name__.split(".")[1]
 logger = logging.getLogger(p)
 
-
+@log_initialization
 class StageController(GUIController):
     """StageController
 
@@ -261,27 +262,22 @@ def disable_synthetic_stages(self, config):
                 if axis == "x":
                     self.view.xy_frame.up_x_btn.config(state=state)
                     self.view.xy_frame.down_x_btn.config(state=state)
-                    logger.info(f"X axis buttons set to {state}")
 
                 elif axis == "y":
                     self.view.xy_frame.up_y_btn.config(state=state)
                     self.view.xy_frame.down_y_btn.config(state=state)
-                    logger.info(f"Y axis buttons set to {state}")
 
                 elif axis == "z":
                     self.view.z_frame.down_btn.config(state=state)
                     self.view.z_frame.up_btn.config(state=state)
-                    logger.info(f"Z axis buttons set to {state}")
 
                 elif axis == "theta":
                     self.view.theta_frame.down_btn.config(state=state)
                     self.view.theta_frame.up_btn.config(state=state)
-                    logger.info(f"Theta axis buttons set to {state}")
 
                 elif axis == "f":
                     self.view.f_frame.down_btn.config(state=state)
                     self.view.f_frame.up_btn.config(state=state)
-                    logger.info(f"Focus axis buttons set to {state}")
             else:
                 pass
 

src/navigate/log_files/filters.py

@@ -97,3 +97,10 @@ def filter(self, record):
         if record.getMessage().startswith("Spec"):
             return False
         return True
+
+class DebugFilter(logging.Filter):
+    """
+    A custom logging filter to include only DEBUG level messages.
+    """
+    def filter(self, record):
+        return record.levelno == logging.DEBUG

src/navigate/log_files/log_functions.py

@@ -62,10 +62,6 @@ def find_filename(k, v):
     -------
     bool
         True if k == 'filename', False otherwise
-
-    Examples
-    --------
-    >>> find_filename('filename', 'test')
     """
     if k == "filename":
         return True

src/navigate/log_files/logging.yml

@@ -9,6 +9,8 @@ filters:
     (): ext://navigate.log_files.filters.PerformanceFilter
   not_performance:
     (): ext://navigate.log_files.filters.NonPerfFilter
+  only_debug:
+    (): ext://navigate.log_files.filters.DebugFilter
 handlers:
   console:
     class: logging.StreamHandler
@@ -28,27 +30,30 @@ handlers:
     level: DEBUG
     formatter: base
     filename: view_controller_debug.log
-    filters: [not_performance]
-    mode: a
-  performance:
-    class: logging.handlers.RotatingFileHandler
-    level: DEBUG
-    formatter: base
-    filename: performance.log
-    filters: [performance_specs]
+    filters: [not_performance, only_debug]
     mode: a
+#  performance:
+#    class: logging.handlers.RotatingFileHandler
+#    level: DEBUG
+#    formatter: base
+#    filename: view_controller_performance.log
+#    filters: [performance_specs]
+#    mode: a
 loggers:
   view:
     level: DEBUG
-    handlers: [console, vc_info, vc_debug, performance]
+#    handlers: [console, vc_info, vc_debug, performance]
+    handlers: [console, vc_info, vc_debug]
     propagate: no
   controller:
     level: DEBUG
-    handlers: [console, vc_info, vc_debug, performance]
+#    handlers: [console, vc_info, vc_debug, performance]
+    handlers: [console, vc_info, vc_debug]
     propagate: no
   config:
     level: DEBUG
-    handlers: [console, vc_info, vc_debug, performance]
+#    handlers: [console, vc_info, vc_debug, performance]
+    handlers: [console, vc_info, vc_debug]
     propagate: no
 
 

src/navigate/log_files/model_logging.yml

@@ -9,6 +9,8 @@ filters:
     (): ext://navigate.log_files.filters.PerformanceFilter
   not_performance:
     (): ext://navigate.log_files.filters.NonPerfFilter
+  only_debug:
+    (): ext://navigate.log_files.filters.DebugFilter
 handlers:
   console:
     class: logging.StreamHandler
@@ -28,7 +30,7 @@ handlers:
     level: DEBUG
     formatter: base
     filename: model_debug.log
-    filters: [not_performance]
+    filters: [not_performance, only_debug]
     mode: a
   model_error:
     class: logging.handlers.RotatingFileHandler
@@ -37,15 +39,16 @@ handlers:
     filename: model_error.log
     filters: [not_performance]
     mode: a
-  model_performance:
-    class: logging.handlers.RotatingFileHandler
-    level: DEBUG
-    formatter: base
-    filename: model_performance.log
-    filters: [performance_specs]
-    mode: a
+#  model_performance:
+#    class: logging.handlers.RotatingFileHandler
+#    level: DEBUG
+#    formatter: base
+#    filename: model_performance.log
+#    filters: [performance_specs]
+#    mode: a
 loggers:
   model:
     level: DEBUG
-    handlers: [console, model_info, model_debug, model_performance]
+    handlers: [console, model_info, model_debug]
+#    handlers: [console, model_info, model_debug, model_performance]
     propagate: no

src/navigate/model/device_startup_functions.py

@@ -92,7 +92,7 @@ def auto_redial(func, args, n_tries=10, exception=Exception, **kwargs):
                     val = None
                 time.sleep(0.5)  # TODO: 0.5 reached by trial and error. Better value?
             else:
-                logger.error(f"Device startup error: {e}")
+                logger.error(f"Device startup failed: {e}")
                 raise exception
         else:
             break