logging: add logging mechanism, hooks to log uncaught crashes, and an example use of the logging tools

software/control/_def.py

@@ -1,12 +1,16 @@
 import os
 import sys
 import glob
-import numpy as np
 from pathlib import Path
 from configparser import ConfigParser
 import json
 import csv
 
+import squid.logging
+
+log = squid.logging.get_logger(__name__)
+
+
 def conf_attribute_reader(string_value):
     """
     :brief: standardized way for reading config entries
@@ -180,13 +184,13 @@ class LIMIT_SWITCH_POLARITY:
 
 
 class ILLUMINATION_CODE:
-    ILLUMINATION_SOURCE_LED_ARRAY_FULL = 0;
+    ILLUMINATION_SOURCE_LED_ARRAY_FULL = 0
     ILLUMINATION_SOURCE_LED_ARRAY_LEFT_HALF = 1
     ILLUMINATION_SOURCE_LED_ARRAY_RIGHT_HALF = 2
     ILLUMINATION_SOURCE_LED_ARRAY_LEFTB_RIGHTR = 3
-    ILLUMINATION_SOURCE_LED_ARRAY_LOW_NA = 4;
-    ILLUMINATION_SOURCE_LED_ARRAY_LEFT_DOT = 5;
-    ILLUMINATION_SOURCE_LED_ARRAY_RIGHT_DOT = 6;
+    ILLUMINATION_SOURCE_LED_ARRAY_LOW_NA = 4
+    ILLUMINATION_SOURCE_LED_ARRAY_LEFT_DOT = 5
+    ILLUMINATION_SOURCE_LED_ARRAY_RIGHT_DOT = 6
     ILLUMINATION_SOURCE_LED_EXTERNAL_FET = 20
     ILLUMINATION_SOURCE_405NM = 11
     ILLUMINATION_SOURCE_488NM = 12
@@ -493,8 +497,6 @@ class SOFTWARE_POS_LIMIT:
 
 DO_FLUORESCENCE_RTP = False
 
-ENABLE_SPINNING_DISK_CONFOCAL = False
-
 INVERTED_OBJECTIVE = False
 
 ILLUMINATION_INTENSITY_FACTOR = 0.6
@@ -598,7 +600,6 @@ def read_objectives_csv(file_path):
                 'NA': float(row['NA']),
                 'tube_lens_f_mm': float(row['tube_lens_f_mm'])
             }
-            #print(f"{row['name']}: {objectives[row['name']]}")
     return objectives
 
 def read_sample_formats_csv(file_path):
@@ -618,7 +619,6 @@ def read_sample_formats_csv(file_path):
                 'rows': int(row['rows']),
                 'cols': int(row['cols'])
             }
-            #print(format_key, "well plate settings:", sample_formats[format_key])
     return sample_formats
 
 OBJECTIVES_CSV_PATH = 'objectives.csv'
@@ -668,12 +668,12 @@ def read_sample_formats_csv(file_path):
 if config_files:
     if len(config_files) > 1:
         if CACHED_CONFIG_FILE_PATH in config_files:
-            print('defaulting to last cached config file at '+CACHED_CONFIG_FILE_PATH)
+            log.info(f'defaulting to last cached config file at \'{CACHED_CONFIG_FILE_PATH}\'')
             config_files = [CACHED_CONFIG_FILE_PATH]
         else:
-            print('multiple machine configuration files found, the program will exit')
+            log.error('multiple machine configuration files found, the program will exit')
             sys.exit(1)
-    print('load machine-specific configuration')
+    log.info('load machine-specific configuration')
     #exec(open(config_files[0]).read())
     cfp = ConfigParser()
     cfp.read(config_files[0])
@@ -704,16 +704,16 @@ def read_sample_formats_csv(file_path):
         file.write(config_files[0])
     CACHED_CONFIG_FILE_PATH = config_files[0]
 else:
-    print('configuration*.ini file not found, defaulting to legacy configuration')
+    log.warning('configuration*.ini file not found, defaulting to legacy configuration')
     config_files = glob.glob('.' + '/' + 'configuration*.txt')
     if config_files:
         if len(config_files) > 1:
-            print('multiple machine configuration files found, the program will exit')
+            log.error('multiple machine configuration files found, the program will exit')
             sys.exit(1)
-        print('load machine-specific configuration')
+        log.info('load machine-specific configuration')
         exec(open(config_files[0]).read())
     else:
-        print('machine-specific configuration not present, the program will exit')
+        log.error('machine-specific configuration not present, the program will exit')
         sys.exit(1)
 ##########################################################
 ##### end of loading machine specific configurations #####

software/main_hcs.py

@@ -1,48 +1,48 @@
 # set QT_API environment variable
-import os
-import glob
 import argparse
+import glob
+import os
 os.environ["QT_API"] = "pyqt5"
-import qtpy
-
 import sys
 
 # qt libraries
-from qtpy.QtCore import *
 from qtpy.QtWidgets import *
 from qtpy.QtGui import *
 
+import squid.logging
+squid.logging.setup_uncaught_exception_logging()
+
 # app specific libraries
 import control.gui_hcs as gui
-
 from configparser import ConfigParser
 from control.widgets import ConfigEditorBackwardsCompatible, ConfigEditorForAcquisitions
-
 from control._def import CACHED_CONFIG_FILE_PATH
 
-import glob
-
-parser = argparse.ArgumentParser()
-parser.add_argument("--simulation", help="Run the GUI with simulated hardware.", action = 'store_true')
-parser.add_argument("--performance", help="Run the GUI with minimal viewers.", action = 'store_true')
-args = parser.parse_args()
 
 def show_config(cfp, configpath, main_gui):
     config_widget = ConfigEditorBackwardsCompatible(cfp, configpath, main_gui)
     config_widget.exec_()
 
+
 def show_acq_config(cfm):
     acq_config_widget = ConfigEditorForAcquisitions(cfm)
     acq_config_widget.exec_()
 
 if __name__ == "__main__":
+    parser = argparse.ArgumentParser()
+    parser.add_argument("--simulation", help="Run the GUI with simulated hardware.", action='store_true')
+    parser.add_argument("--performance", help="Run the GUI with minimal viewers.", action='store_true')
+    args = parser.parse_args()
+
+    log = squid.logging.get_logger("main_hcs")
+
     legacy_config = False
     cf_editor_parser = ConfigParser()
     config_files = glob.glob('.' + '/' + 'configuration*.ini')
     if config_files:
         cf_editor_parser.read(CACHED_CONFIG_FILE_PATH)
     else:
-        print('configuration*.ini file not found, defaulting to legacy configuration')
+        log.error('configuration*.ini file not found, defaulting to legacy configuration')
         legacy_config = True
     app = QApplication([])
     app.setStyle('Fusion')

software/squid/logging.py

@@ -0,0 +1,141 @@
+import logging as py_logging
+import threading
+from typing import Optional, Type
+from types import TracebackType
+import sys
+
+_squid_root_logger_name= "squid"
+
+
+# The idea for this CustomFormatter is cribbed from https://stackoverflow.com/a/56944256
+class _CustomFormatter(py_logging.Formatter):
+    GRAY = "\x1b[38;20m"
+    YELLOW = "\x1b[33;20m"
+    RED = "\x1b[31;20m"
+    BOLD_RED = "\x1b[31;1m"
+    RESET = "\x1b[0m"
+    FORMAT = "%(asctime)s.%(msecs)03d - %(name)s - %(levelname)s - %(message)s (%(filename)s:%(lineno)d)"
+
+    FORMATS = {
+        py_logging.DEBUG: GRAY + FORMAT + RESET,
+        py_logging.INFO: GRAY + FORMAT + RESET,
+        py_logging.WARNING: YELLOW + FORMAT + RESET,
+        py_logging.ERROR: RED + FORMAT + RESET,
+        py_logging.CRITICAL: BOLD_RED + FORMAT + RESET
+    }
+
+    # NOTE(imo): The datetime hackery is so that we can have millisecond timestamps using a period instead
+    # of comma.  The default asctime + datefmt uses a comma.
+    FORMATTERS = {level: py_logging.Formatter(fmt, datefmt="%Y-%m-%d %H:%M:%S") for (level, fmt) in FORMATS.items()}
+
+    def format(self, record):
+        return self.FORMATTERS[record.levelno].format(record)
+
+_COLOR_STREAM_HANDLER = py_logging.StreamHandler()
+_COLOR_STREAM_HANDLER.setFormatter(_CustomFormatter())
+
+# Make sure the squid root logger has all the handlers we want setup.  We could move this into a helper so it
+# isn't done at the module level, but not needing to remember to call some helper to setup formatting is nice.
+py_logging.getLogger(_squid_root_logger_name).addHandler(_COLOR_STREAM_HANDLER)
+
+
+def get_logger(name: Optional[str] = None) -> py_logging.Logger:
+    """
+    Returns the top level squid logger instance by default, or a logger in the squid
+    logging hierarchy if a non-None name is given.
+    """
+    if name is None:
+        logger = py_logging.getLogger(_squid_root_logger_name)
+    else:
+        logger = py_logging.getLogger(_squid_root_logger_name).getChild(name)
+
+    return logger
+
+
+def set_log_level(level):
+    """
+    All squid code should use this set_log_level method, and the corresponding squid.logging.get_logger,
+    to control squid-only logging.
+
+    This does not modify the log level of loggers outside the squid logger hierarchy! If global logging control
+    is needed the normal logging package tools can be used instead.
+    """
+    squid_root_logger = get_logger()
+    squid_root_logger.setLevel(level)
+
+    # There's no `getAllChildren` method on the logger or its manager, so we just grab the manager
+    # for our root logger and then check all other loggers to see if they start with our root logger prefix
+    # to find all the squid specific logger.
+    for (name, logger) in squid_root_logger.manager.loggerDict.items():
+        # The logging module uses the PlaceHolder object for nodes in the hierarchy that
+        # have children, but no associated loggers.  EG if we create a logger at
+        # squid.control.gui_hcs but not at squid.control, then the logger for squid.control
+        # exists but is a PlaceHolder (until someone explicitly requests it).
+        if name.startswith(_squid_root_logger_name) and isinstance(logger, py_logging.Logger):
+            logger.setLevel(level)
+
+
+def register_crash_handler(handler, call_existing_too=True):
+    """
+    We want to make sure any uncaught exceptions are logged, so we have this mechanism for putting a hook into
+    the python system that does custom logging when an exception bubbles all the way to the top.
+
+    NOTE: We do our best below, but it is a really bad idea for your handler to raise an exception.
+    """
+    # The sys.excepthook docs are a good entry point for all of this
+    # (here: https://docs.python.org/3/library/sys.html#sys.excepthook), but essentially there are 3 different ways
+    # threads of execution can blow up.  We want to catch and log all 3 of them.
+    old_excepthook = sys.excepthook
+    old_thread_excepthook = threading.excepthook
+    # The unraisable hook doesn't have the same signature as the excepthooks, but we can sort of shoehorn the arguments
+    # into the same signature.  Also, this is an extremely rare (I'm not sure I've ever seen it?) failure mode, so
+    # it should be okay.
+    old_unraisable_hook = sys.unraisablehook
+
+    logger = get_logger()
+
+    def new_excepthook(exception_type: Type[BaseException], value: BaseException, tb: TracebackType):
+        try:
+            handler(exception_type, value, tb)
+        except BaseException as e:
+            logger.critical("Custom excepthook handler raised exception", e)
+        if call_existing_too:
+            old_excepthook(exception_type, value, tb)
+
+    def new_thread_excepthook(hook_args: threading.ExceptHookArgs):
+        exception_type = hook_args.exc_type
+        value = hook_args.exc_type
+        tb = hook_args.exc_traceback
+        try:
+            handler(exception_type, value, type(tb))
+        except BaseException as e:
+            logger.critical("Custom thread excepthook handler raised exception", e)
+        if call_existing_too:
+            old_thread_excepthook(exception_type, value, type(tb))
+
+    def new_unraisable_hook(info):
+        exception_type = info.exc_type
+        tb = info.exc_traceback
+        value = info.exc_value
+        try:
+            handler(exception_type, value, type(tb))
+        except BaseException as e:
+            logger.critical("Custom unraisable hook handler raised exception", e)
+        if call_existing_too:
+            old_unraisable_hook(info)
+
+    logger.info(f"Registering custom excepthook, threading excepthook, and unraisable hook using handler={handler.__name__}")
+    sys.excepthook = new_excepthook
+    threading.excepthook = new_thread_excepthook
+    sys.unraisablehook = new_unraisable_hook
+
+
+def setup_uncaught_exception_logging():
+    """
+    This will make sure uncaught exceptions are sent to the root squid logger as error messages.
+    """
+    logger = get_logger()
+    def uncaught_exception_logger(exception_type: Type[BaseException], value: BaseException, tb: TracebackType):
+        logger.exception("Uncaught Exception!", exc_info=value)
+
+    register_crash_handler(uncaught_exception_logger, call_existing_too=False)

software/tests/squid/test_logging.py

@@ -0,0 +1,15 @@
+import squid.logging
+
+def test_root_logger():
+    root_logger = squid.logging.get_logger()
+    assert root_logger.name == squid.logging._squid_root_logger_name
+
+def test_children_loggers():
+    child_a = "a"
+    child_b = "b"
+
+    child_a_logger = squid.logging.get_logger(child_a)
+    child_b_logger = child_a_logger.getChild(child_b)
+
+    assert child_a_logger.name == f"{squid.logging._squid_root_logger_name}.{child_a}"
+    assert child_b_logger.name == f"{squid.logging._squid_root_logger_name}.{child_a}.{child_b}"