diff --git a/pyproject.toml b/pyproject.toml index fb072b44..ef0c8af2 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -114,8 +114,8 @@ select = [ "C", # Flake8 comprehensions "FIX", #TODO/FIXME's in code. These should be added during development for ongoing tasks. # If they are not fixed before merge they should be converted to GitLab issues -# "LOG", # Flake8 logging issues (pedantic logger formatting issues can be added with "G") -# "T20", # Warns for print statements, production code should log + "LOG", # Flake8 logging issues (pedantic logger formatting issues can be added with "G") + "T20", # Warns for print statements, production code should log # "PT", # pytest linting "RET", # Consistent clear return statements "RSE", # Raise parentheses @@ -140,10 +140,17 @@ ignore = [ ] [tool.ruff.lint.per-file-ignores] +# All testing dirs "{tests,integration-tests,hardware-specific-tests}/**" = [ "B018", # Complaining about useless attribute access in tests, but we need them to check errors are raised "ANN", # Tests are not typehinted for fixtures etc "S101", # Allow asserts in tests + "T20", # Allow prints in tests + "LOG015",# Allow tests to use the root logger. +] +# Developer CLI scripts +"{pull_webapp,picamera_tests,change_log_helper}.py" = [ + "T20", # Printing is normal in small CLI scripts ] [tool.ruff.lint.pydocstyle] diff --git a/src/openflexure_microscope_server/logging.py b/src/openflexure_microscope_server/logging.py index 0dd3ee12..5e09b054 100644 --- a/src/openflexure_microscope_server/logging.py +++ b/src/openflexure_microscope_server/logging.py @@ -18,6 +18,7 @@ import os from fastapi.responses import PlainTextResponse from fastapi import HTTPException +LOGGER = logging.getLogger(__name__) OFM_LOG_FILE = None @@ -58,12 +59,9 @@ def configure_logging(log_folder: str) -> None: root_logger.addHandler(handler) except PermissionError as e: - logging.error(f"Cannot create log file at {OFM_LOG_FILE}: {e}") + LOGGER.error(f"Cannot create log file at {OFM_LOG_FILE}: {e}") - logging.info("") - logging.info("****************************************************") - logging.info("OFM server root logger has been set up at INFO level") - logging.info("****************************************************") + LOGGER.info("OFM server root logger has been set up at INFO level") def retrieve_log() -> PlainTextResponse: diff --git a/src/openflexure_microscope_server/server/__init__.py b/src/openflexure_microscope_server/server/__init__.py index 3dfbb721..1f14fbd3 100644 --- a/src/openflexure_microscope_server/server/__init__.py +++ b/src/openflexure_microscope_server/server/__init__.py @@ -14,6 +14,8 @@ from .serve_static_files import add_static_files from .legacy_api import add_v2_endpoints from ..logging import configure_logging, retrieve_log, retrieve_log_from_file +LOGGER = logging.getLogger(__name__) + def set_shutdown_function(shutdown_function: Callable[[], None]) -> None: """Ensure a function is called before the shutdown. @@ -93,7 +95,7 @@ def serve_from_cli(argv: Optional[list[str]] = None) -> None: # Catch anything and log as it is essential that this # function cannot raise an unhandled exception or Uvicorn # will never get a shutdown signal. - logging.error(e, exc_info=True) + LOGGER.error(e, exc_info=True) # Monkey patch uvicorn's exit handling to stop the MJPEG Streams # before waiting for background tasks to complete. @@ -109,9 +111,11 @@ def serve_from_cli(argv: Optional[list[str]] = None) -> None: except BaseException as e: if args.fallback: - print(f"Error: {e}") + # Allow printing to the terminal for fallback errors so they are not + # presented in the fallback logs. + print(f"Error: {e}") # noqa: T201 fallback_server = "labthings_fastapi.server.fallback:app" - print(f"Starting fallback server {fallback_server}.") + print(f"Starting fallback server {fallback_server}.") # noqa: T201 app = lt.cli.object_reference_to_object(fallback_server) app.labthings_config = config app.labthings_server = server diff --git a/src/openflexure_microscope_server/things/autofocus.py b/src/openflexure_microscope_server/things/autofocus.py index e0b956f1..5c5e01dc 100644 --- a/src/openflexure_microscope_server/things/autofocus.py +++ b/src/openflexure_microscope_server/things/autofocus.py @@ -25,6 +25,8 @@ from .camera import RawCameraDependency as RawCamera from .camera import CameraDependency as CameraClient from .stage import StageDependency as Stage +LOGGER = logging.getLogger(__name__) + class NotStreamingError(RuntimeError): """No images captured from stream. The camera is almost certainly not streaming.""" @@ -228,7 +230,7 @@ class JPEGSharpnessMonitor: self.camera = camera self.stage = stage self.portal = portal - print(f"Created sharpness monitor with {stage}, {camera}, {portal}") + LOGGER.debug(f"Created sharpness monitor with {stage}, {camera}, {portal}") self.stage_positions: list[Mapping[str, int]] = [] self.stage_times: list[float] = [] self.jpeg_times: list[float] = [] @@ -307,7 +309,7 @@ class JPEGSharpnessMonitor: raise e if stop < 1: stop = len(jpeg_times) - logging.debug("changing stop to %s", (stop)) + LOGGER.debug("changing stop to %s", (stop)) jpeg_times = jpeg_times[start:stop] jpeg_heights: np.ndarray = np.interp(jpeg_times, stage_times, stage_heights) return jpeg_times, jpeg_heights, jpeg_sizes[start:stop] diff --git a/src/openflexure_microscope_server/things/camera/opencv.py b/src/openflexure_microscope_server/things/camera/opencv.py index c159ce41..a4e5f81a 100644 --- a/src/openflexure_microscope_server/things/camera/opencv.py +++ b/src/openflexure_microscope_server/things/camera/opencv.py @@ -21,6 +21,8 @@ from labthings_fastapi.types.numpy import NDArray from . import BaseCamera +LOGGER = logging.getLogger(__name__) + class OpenCVCamera(BaseCamera): """A Thing that provides and interface to an OpenCV Camera.""" @@ -70,9 +72,7 @@ class OpenCVCamera(BaseCamera): while self._capture_enabled: ret, frame = self.cap.read() if not ret: - logging.error( - f"Failed to capture frame from camera {self.camera_index}" - ) + LOGGER.error(f"Failed to capture frame from camera {self.camera_index}") break jpeg = cv2.imencode(".jpg", frame)[1].tobytes() self.mjpeg_stream.add_frame(jpeg, portal) @@ -99,8 +99,8 @@ class OpenCVCamera(BaseCamera): binary image formats will be added in due course. """ if wait is not None: - logging.warning("OpenCV camera has no wait option. Use None.") - logging.warning(f"OpenCV camera doesn't respect {stream_name=}") + LOGGER.warning("OpenCV camera has no wait option. Use None.") + LOGGER.warning(f"OpenCV camera doesn't respect {stream_name=}") ret, frame = self.cap.read() if not ret: raise RuntimeError( @@ -118,6 +118,6 @@ class OpenCVCamera(BaseCamera): This function will produce a JPEG image. """ if wait is not None: - logging.warning("OpenCV camera has no wait option. Use None.") - logging.warning(f"OpenCV camera doesn't respect {stream_name=}") + LOGGER.warning("OpenCV camera has no wait option. Use None.") + LOGGER.warning(f"OpenCV camera doesn't respect {stream_name=}") return Image.fromarray(self.capture_array()) diff --git a/src/openflexure_microscope_server/things/camera/picamera.py b/src/openflexure_microscope_server/things/camera/picamera.py index be01b337..0158c56e 100644 --- a/src/openflexure_microscope_server/things/camera/picamera.py +++ b/src/openflexure_microscope_server/things/camera/picamera.py @@ -47,6 +47,8 @@ from . import picamera_tuning_file_utils as tf_utils from . import BaseCamera, ArrayModel +LOGGER = logging.getLogger(__name__) + SUPPORTED_CAMS_SENSOR_INFO = { "picamera_v2": recalibrate_utils.IMX219_SENSOR_INFO, "picamera_hq": recalibrate_utils.IMX477_SENSOR_INFO, @@ -397,16 +399,16 @@ class StreamingPiCamera2(BaseCamera): os.environ["LIBCAMERA_RPI_TUNING_FILE"] = tuning_file.name if self._picamera is not None: - logging.info("Closing picamera object for reinitialisation") - logging.info( + LOGGER.info("Closing picamera object for reinitialisation") + LOGGER.info( "Camera object already exists, closing for reinitialisation" ) self._picamera.close() - logging.info("Picamera closed, deleting picamera") + LOGGER.info("Picamera closed, deleting picamera") del self._picamera recalibrate_utils.recreate_camera_manager() - logging.info("Creating new Picamera2 object") + LOGGER.info("Creating new Picamera2 object") # Specify tuning file otherwise it will be overwritten with None. self._picamera = Picamera2( camera_num=self._camera_num, @@ -519,7 +521,7 @@ class StreamingPiCamera2(BaseCamera): ) stream_config["buffer_count"] = buffer_count picam.configure(stream_config) - logging.info("Starting picamera MJPEG stream...") + LOGGER.info("Starting picamera MJPEG stream...") stream_name = "lores" if main_resolution[0] > 1280 else "main" picam.start_recording( MJPEGEncoder(self.mjpeg_bitrate), @@ -538,11 +540,11 @@ class StreamingPiCamera2(BaseCamera): name="lores", ) except Exception as e: - logging.exception("Error while starting preview: {e}") - logging.exception(e) + LOGGER.exception("Error while starting preview: {e}") + LOGGER.exception(e) else: self.stream_active = True - logging.debug( + LOGGER.debug( "Started MJPEG stream at %s on port %s", self.stream_resolution, 1 ) @@ -553,15 +555,15 @@ class StreamingPiCamera2(BaseCamera): try: picam.stop_recording() # This should also stop the extra lores encoder except Exception as e: - logging.info("Stopping recording failed") - logging.exception(e) + LOGGER.info("Stopping recording failed") + LOGGER.exception(e) else: self.stream_active = False if stop_web_stream: portal = lt.get_blocking_portal(self) self.mjpeg_stream.stop(portal) self.lores_mjpeg_stream.stop(portal) - logging.info("Stopped MJPEG stream.") + LOGGER.info("Stopped MJPEG stream.") # Adding a sleep to prevent camera getting confused by rapid commands time.sleep(self._sensor_info.short_pause) @@ -579,7 +581,7 @@ class StreamingPiCamera2(BaseCamera): Restarts stream when complete. """ with self._streaming_picamera(pause_stream=True) as cam: - logging.debug("Reconfiguring camera for full resolution capture") + LOGGER.debug("Reconfiguring camera for full resolution capture") cam.configure(cam.create_still_configuration(sensor=self._sensor_mode)) cam.start() time.sleep(self._sensor_info.short_pause) diff --git a/src/openflexure_microscope_server/things/camera/picamera_recalibrate_utils.py b/src/openflexure_microscope_server/things/camera/picamera_recalibrate_utils.py index 5f38ee6e..b88976b6 100644 --- a/src/openflexure_microscope_server/things/camera/picamera_recalibrate_utils.py +++ b/src/openflexure_microscope_server/things/camera/picamera_recalibrate_utils.py @@ -52,6 +52,8 @@ from scipy.ndimage import zoom from picamera2 import Picamera2 import picamera2 +LOGGER = logging.getLogger(__name__) + class SensorInfo(BaseModel): """Information about the sensor used for calibration and property setting.""" @@ -167,7 +169,7 @@ def adjust_shutter_and_gain_from_raw( # Check whether the shutter speed is still going up - if not, we've hit a maximum if camera.capture_metadata()["ExposureTime"] == test.exposure_time: - logging.info(f"Shutter speed has maxed out at {test.exposure_time}") + LOGGER.info(f"Shutter speed has maxed out at {test.exposure_time}") break # Now, if we've not converged, increase gain until we converge or run out of options. @@ -185,13 +187,13 @@ def adjust_shutter_and_gain_from_raw( # Check the gain is still changing - if not, we have probably hit the maximum if camera.capture_metadata()["AnalogueGain"] == test.analog_gain: - logging.info(f"Gain has maxed out at {test.analog_gain}") + LOGGER.info(f"Gain has maxed out at {test.analog_gain}") break if _check_convergence(test, target_white_level, tolerance): - logging.info(f"Brightness has converged to within {tolerance * 100:.0f}%.") + LOGGER.info(f"Brightness has converged to within {tolerance * 100:.0f}%.") else: - logging.warning( + LOGGER.warning( f"Failed to reach target brightness of {target_white_level}." f"Brightness reached {test.level} after {iterations} iterations." ) @@ -230,11 +232,9 @@ def adjust_white_balance_from_raw( channel_gains = 1 / grids if channel_gains.shape[1:] != channels.shape[1:]: channel_gains = _upsample_channels(channel_gains, channels.shape[1:]) - logging.info( - f"Before gains, channel maxima are {np.max(channels, axis=(1, 2))}" - ) + LOGGER.info(f"Before gains, channel maxima are {np.max(channels, axis=(1, 2))}") channels = channels * channel_gains - logging.info(f"After gains, channel maxima are {np.max(channels, axis=(1, 2))}") + LOGGER.info(f"After gains, channel maxima are {np.max(channels, axis=(1, 2))}") if method == "centre": _, height, width = channels.shape # Cut out the central 10% from 9/20 to 11/20... @@ -261,7 +261,7 @@ def adjust_white_balance_from_raw( # Here, we decrease the gains by the minimum value of Cr and Cb. new_awb_gains = (green / red * np.min(Cr), green / blue * np.min(Cb)) - logging.info( + LOGGER.info( f"Raw white point is R: {red} G: {green} B: {blue}, " f"setting AWB gains to ({new_awb_gains[0]:.2f}, " f"{new_awb_gains[1]:.2f})." @@ -270,7 +270,7 @@ def adjust_white_balance_from_raw( camera.controls.ColourGains = new_awb_gains time.sleep(sensor_info.long_pause) m = camera.capture_metadata() - print(f"Camera confirms gains are now {m['ColourGains']}") + LOGGER.debug(f"Camera confirms gains are now {m['ColourGains']}") return new_awb_gains @@ -334,7 +334,7 @@ def _test_exposure_settings(camera: Picamera2, percentile: float) -> _ExposureTe # because of black level compensation. The line below forces a # minimum value of 1 which will keep things well-behaved! if max_brightness < 1: - logging.warning( + LOGGER.warning( f"Measured brightness of {max_brightness}. " "This should normally be >= 1, and may indicate the " "camera's black level compensation has gone wrong." @@ -346,7 +346,7 @@ def _test_exposure_settings(camera: Picamera2, percentile: float) -> _ExposureTe exposure_time=int(metadata["ExposureTime"]), analog_gain=float(metadata["AnalogueGain"]), ) - logging.info(f"{result.model_dump()}") + LOGGER.info(f"{result.model_dump()}") return result @@ -490,5 +490,5 @@ def _raw_channels_from_camera( # de-mosaicing has been done, so 2/3 of the values are zero (3/4 for R and B # channels, 1/2 for green because there's twice as many green pixels). raw_format = camera.camera_configuration()["raw"]["format"] - print(f"Acquired a raw image in format {raw_format}") + LOGGER.debug(f"Acquired a raw image in format {raw_format}") return _channels_from_bayer_array(raw_image) diff --git a/src/openflexure_microscope_server/things/camera/simulation.py b/src/openflexure_microscope_server/things/camera/simulation.py index 80dadb55..37df5d1c 100644 --- a/src/openflexure_microscope_server/things/camera/simulation.py +++ b/src/openflexure_microscope_server/things/camera/simulation.py @@ -30,6 +30,8 @@ from openflexure_microscope_server.ui import ( from . import BaseCamera, ArrayModel from ..stage import BaseStage +LOGGER = logging.getLogger(__name__) + # The ratio between "motor" steps and pixels # higher related to a faster movement RATIO = 0.2 @@ -204,7 +206,7 @@ class SimulatedCamera(BaseCamera): try: pos = self.get_stage_position() except Exception as e: - print(f"Failed to get stage position: {e}") + LOGGER.debug(f"Failed to get stage position: {e}") pos = {"x": 0, "y": 0, "z": 0} return self.generate_image((pos["y"], pos["x"], pos["z"])) @@ -238,7 +240,7 @@ class SimulatedCamera(BaseCamera): If called while already streaming, the warning will be emitted and no other action will be taken. """ - logging.warning( + LOGGER.warning( f"Simulation camera doesn't respect {main_resolution=} or {buffer_count=} " "arguments." ) @@ -271,7 +273,7 @@ class SimulatedCamera(BaseCamera): jpeg_lores = cv2.imencode(".jpg", ds_frame)[1].tobytes() self.lores_mjpeg_stream.add_frame(jpeg_lores, portal) except Exception as e: - logging.exception(f"Failed to capture frame: {e}, retrying...") + LOGGER.exception(f"Failed to capture frame: {e}, retrying...") @lt.thing_action def discard_frames(self) -> None: @@ -293,8 +295,8 @@ class SimulatedCamera(BaseCamera): binary image formats will be added in due course. """ if wait is not None: - logging.warning("Simulation camera has no wait option. Use None.") - logging.warning(f"Simulation camera camera doesn't respect {stream_name=}") + LOGGER.warning("Simulation camera has no wait option. Use None.") + LOGGER.warning(f"Simulation camera camera doesn't respect {stream_name=}") return self.generate_frame() def capture_image( @@ -307,8 +309,8 @@ class SimulatedCamera(BaseCamera): It is used for capture to memory. """ if wait is not None: - logging.warning("Simulation camera has no wait option. Use None.") - logging.warning(f"Simulation camera camera doesn't respect {stream_name=}") + LOGGER.warning("Simulation camera has no wait option. Use None.") + LOGGER.warning(f"Simulation camera camera doesn't respect {stream_name=}") return Image.fromarray(self.generate_frame()) @lt.thing_action diff --git a/src/openflexure_microscope_server/things/stage/sangaboard.py b/src/openflexure_microscope_server/things/stage/sangaboard.py index 932fa373..733d4099 100644 --- a/src/openflexure_microscope_server/things/stage/sangaboard.py +++ b/src/openflexure_microscope_server/things/stage/sangaboard.py @@ -15,6 +15,8 @@ import labthings_fastapi as lt from . import BaseStage +LOGGER = logging.getLogger(__name__) + class SangaboardThing(BaseStage): """A Thing to manage a Sangaboard motor controller. @@ -168,7 +170,7 @@ class SangaboardThing(BaseStage): # cannot be used. intended_brightness = float(return_value[7:]) on_brightness = 0.32 - logging.warning( + LOGGER.warning( "Brightness control is not yet implemented. Desired brightness: " f"{intended_brightness}. Set brightness: {on_brightness}" )