rahix/openflexure-microscope-server
1
0
Fork 0
Code Issues Pull requests Projects Releases Packages Wiki Activity Actions

Stop using print statments or root level loggers

Browse source
This commit is contained in:
Julian Stirling 2025-09-18 14:30:44 +01:00
parent 338d49f9e6
commit 65f172d650
9 changed files with 69 additions and 52 deletions
Download patch file Download diff file Expand all files Collapse all files

11
pyproject.toml
View file

@ -114,8 +114,8 @@ select = [
"C", # Flake8 comprehensions "C", # Flake8 comprehensions
"FIX", #TODO/FIXME's in code. These should be added during development for ongoing tasks. "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 # 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") "LOG", # Flake8 logging issues (pedantic logger formatting issues can be added with "G")
# "T20", # Warns for print statements, production code should log "T20", # Warns for print statements, production code should log
# "PT", # pytest linting # "PT", # pytest linting
"RET", # Consistent clear return statements "RET", # Consistent clear return statements
"RSE", # Raise parentheses "RSE", # Raise parentheses
@ -140,10 +140,17 @@ ignore = [
] ]
[tool.ruff.lint.per-file-ignores] [tool.ruff.lint.per-file-ignores]
# All testing dirs
"{tests,integration-tests,hardware-specific-tests}/**" = [ "{tests,integration-tests,hardware-specific-tests}/**" = [
"B018", # Complaining about useless attribute access in tests, but we need them to check errors are raised "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 "ANN", # Tests are not typehinted for fixtures etc
"S101", # Allow asserts in tests "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] [tool.ruff.lint.pydocstyle]

8
src/openflexure_microscope_server/logging.py
View file

@ -18,6 +18,7 @@ import os
from fastapi.responses import PlainTextResponse from fastapi.responses import PlainTextResponse
from fastapi import HTTPException from fastapi import HTTPException
LOGGER = logging.getLogger(__name__)
OFM_LOG_FILE = None OFM_LOG_FILE = None
@ -58,12 +59,9 @@ def configure_logging(log_folder: str) -> None:
root_logger.addHandler(handler) root_logger.addHandler(handler)
except PermissionError as e: 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("") LOGGER.info("OFM server root logger has been set up at INFO level")
logging.info("****************************************************")
logging.info("OFM server root logger has been set up at INFO level")
logging.info("****************************************************")
def retrieve_log() -> PlainTextResponse: def retrieve_log() -> PlainTextResponse:

10
src/openflexure_microscope_server/server/__init__.py
View file

@ -14,6 +14,8 @@ from .serve_static_files import add_static_files
from .legacy_api import add_v2_endpoints from .legacy_api import add_v2_endpoints
from ..logging import configure_logging, retrieve_log, retrieve_log_from_file from ..logging import configure_logging, retrieve_log, retrieve_log_from_file
LOGGER = logging.getLogger(__name__)
def set_shutdown_function(shutdown_function: Callable[[], None]) -> None: def set_shutdown_function(shutdown_function: Callable[[], None]) -> None:
"""Ensure a function is called before the shutdown. """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 # Catch anything and log as it is essential that this
# function cannot raise an unhandled exception or Uvicorn # function cannot raise an unhandled exception or Uvicorn
# will never get a shutdown signal. # 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 # Monkey patch uvicorn's exit handling to stop the MJPEG Streams
# before waiting for background tasks to complete. # 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: except BaseException as e:
if args.fallback: 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" 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 = lt.cli.object_reference_to_object(fallback_server)
app.labthings_config = config app.labthings_config = config
app.labthings_server = server app.labthings_server = server

6
src/openflexure_microscope_server/things/autofocus.py
View file

@ -25,6 +25,8 @@ from .camera import RawCameraDependency as RawCamera
from .camera import CameraDependency as CameraClient from .camera import CameraDependency as CameraClient
from .stage import StageDependency as Stage from .stage import StageDependency as Stage
LOGGER = logging.getLogger(__name__)
class NotStreamingError(RuntimeError): class NotStreamingError(RuntimeError):
"""No images captured from stream. The camera is almost certainly not streaming.""" """No images captured from stream. The camera is almost certainly not streaming."""
@ -228,7 +230,7 @@ class JPEGSharpnessMonitor:
self.camera = camera self.camera = camera
self.stage = stage self.stage = stage
self.portal = portal 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_positions: list[Mapping[str, int]] = []
self.stage_times: list[float] = [] self.stage_times: list[float] = []
self.jpeg_times: list[float] = [] self.jpeg_times: list[float] = []
@ -307,7 +309,7 @@ class JPEGSharpnessMonitor:
raise e raise e
if stop < 1: if stop < 1:
stop = len(jpeg_times) 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_times = jpeg_times[start:stop]
jpeg_heights: np.ndarray = np.interp(jpeg_times, stage_times, stage_heights) jpeg_heights: np.ndarray = np.interp(jpeg_times, stage_times, stage_heights)
return jpeg_times, jpeg_heights, jpeg_sizes[start:stop] return jpeg_times, jpeg_heights, jpeg_sizes[start:stop]

14
src/openflexure_microscope_server/things/camera/opencv.py
View file

@ -21,6 +21,8 @@ from labthings_fastapi.types.numpy import NDArray
from . import BaseCamera from . import BaseCamera
LOGGER = logging.getLogger(__name__)
class OpenCVCamera(BaseCamera): class OpenCVCamera(BaseCamera):
"""A Thing that provides and interface to an OpenCV Camera.""" """A Thing that provides and interface to an OpenCV Camera."""
@ -70,9 +72,7 @@ class OpenCVCamera(BaseCamera):
while self._capture_enabled: while self._capture_enabled:
ret, frame = self.cap.read() ret, frame = self.cap.read()
if not ret: if not ret:
logging.error( LOGGER.error(f"Failed to capture frame from camera {self.camera_index}")
f"Failed to capture frame from camera {self.camera_index}"
)
break break
jpeg = cv2.imencode(".jpg", frame)[1].tobytes() jpeg = cv2.imencode(".jpg", frame)[1].tobytes()
self.mjpeg_stream.add_frame(jpeg, portal) self.mjpeg_stream.add_frame(jpeg, portal)
@ -99,8 +99,8 @@ class OpenCVCamera(BaseCamera):
binary image formats will be added in due course. binary image formats will be added in due course.
""" """
if wait is not None: if wait is not None:
logging.warning("OpenCV camera has no wait option. Use None.") LOGGER.warning("OpenCV camera has no wait option. Use None.")
logging.warning(f"OpenCV camera doesn't respect {stream_name=}") LOGGER.warning(f"OpenCV camera doesn't respect {stream_name=}")
ret, frame = self.cap.read() ret, frame = self.cap.read()
if not ret: if not ret:
raise RuntimeError( raise RuntimeError(
@ -118,6 +118,6 @@ class OpenCVCamera(BaseCamera):
This function will produce a JPEG image. This function will produce a JPEG image.
""" """
if wait is not None: if wait is not None:
logging.warning("OpenCV camera has no wait option. Use None.") LOGGER.warning("OpenCV camera has no wait option. Use None.")
logging.warning(f"OpenCV camera doesn't respect {stream_name=}") LOGGER.warning(f"OpenCV camera doesn't respect {stream_name=}")
return Image.fromarray(self.capture_array()) return Image.fromarray(self.capture_array())

26
src/openflexure_microscope_server/things/camera/picamera.py
View file

@ -47,6 +47,8 @@ from . import picamera_tuning_file_utils as tf_utils
from . import BaseCamera, ArrayModel from . import BaseCamera, ArrayModel
LOGGER = logging.getLogger(__name__)
SUPPORTED_CAMS_SENSOR_INFO = { SUPPORTED_CAMS_SENSOR_INFO = {
"picamera_v2": recalibrate_utils.IMX219_SENSOR_INFO, "picamera_v2": recalibrate_utils.IMX219_SENSOR_INFO,
"picamera_hq": recalibrate_utils.IMX477_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 os.environ["LIBCAMERA_RPI_TUNING_FILE"] = tuning_file.name
if self._picamera is not None: if self._picamera is not None:
logging.info("Closing picamera object for reinitialisation") LOGGER.info("Closing picamera object for reinitialisation")
logging.info( LOGGER.info(
"Camera object already exists, closing for reinitialisation" "Camera object already exists, closing for reinitialisation"
) )
self._picamera.close() self._picamera.close()
logging.info("Picamera closed, deleting picamera") LOGGER.info("Picamera closed, deleting picamera")
del self._picamera del self._picamera
recalibrate_utils.recreate_camera_manager() 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. # Specify tuning file otherwise it will be overwritten with None.
self._picamera = Picamera2( self._picamera = Picamera2(
camera_num=self._camera_num, camera_num=self._camera_num,
@ -519,7 +521,7 @@ class StreamingPiCamera2(BaseCamera):
) )
stream_config["buffer_count"] = buffer_count stream_config["buffer_count"] = buffer_count
picam.configure(stream_config) 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" stream_name = "lores" if main_resolution[0] > 1280 else "main"
picam.start_recording( picam.start_recording(
MJPEGEncoder(self.mjpeg_bitrate), MJPEGEncoder(self.mjpeg_bitrate),
@ -538,11 +540,11 @@ class StreamingPiCamera2(BaseCamera):
name="lores", name="lores",
) )
except Exception as e: except Exception as e:
logging.exception("Error while starting preview: {e}") LOGGER.exception("Error while starting preview: {e}")
logging.exception(e) LOGGER.exception(e)
else: else:
self.stream_active = True self.stream_active = True
logging.debug( LOGGER.debug(
"Started MJPEG stream at %s on port %s", self.stream_resolution, 1 "Started MJPEG stream at %s on port %s", self.stream_resolution, 1
) )
@ -553,15 +555,15 @@ class StreamingPiCamera2(BaseCamera):
try: try:
picam.stop_recording() # This should also stop the extra lores encoder picam.stop_recording() # This should also stop the extra lores encoder
except Exception as e: except Exception as e:
logging.info("Stopping recording failed") LOGGER.info("Stopping recording failed")
logging.exception(e) LOGGER.exception(e)
else: else:
self.stream_active = False self.stream_active = False
if stop_web_stream: if stop_web_stream:
portal = lt.get_blocking_portal(self) portal = lt.get_blocking_portal(self)
self.mjpeg_stream.stop(portal) self.mjpeg_stream.stop(portal)
self.lores_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 # Adding a sleep to prevent camera getting confused by rapid commands
time.sleep(self._sensor_info.short_pause) time.sleep(self._sensor_info.short_pause)
@ -579,7 +581,7 @@ class StreamingPiCamera2(BaseCamera):
Restarts stream when complete. Restarts stream when complete.
""" """
with self._streaming_picamera(pause_stream=True) as cam: 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.configure(cam.create_still_configuration(sensor=self._sensor_mode))
cam.start() cam.start()
time.sleep(self._sensor_info.short_pause) time.sleep(self._sensor_info.short_pause)

26
src/openflexure_microscope_server/things/camera/picamera_recalibrate_utils.py
View file

@ -52,6 +52,8 @@ from scipy.ndimage import zoom
from picamera2 import Picamera2 from picamera2 import Picamera2
import picamera2 import picamera2
LOGGER = logging.getLogger(__name__)
class SensorInfo(BaseModel): class SensorInfo(BaseModel):
"""Information about the sensor used for calibration and property setting.""" """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 # Check whether the shutter speed is still going up - if not, we've hit a maximum
if camera.capture_metadata()["ExposureTime"] == test.exposure_time: 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 break
# Now, if we've not converged, increase gain until we converge or run out of options. # 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 # Check the gain is still changing - if not, we have probably hit the maximum
if camera.capture_metadata()["AnalogueGain"] == test.analog_gain: 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 break
if _check_convergence(test, target_white_level, tolerance): 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: else:
logging.warning( LOGGER.warning(
f"Failed to reach target brightness of {target_white_level}." f"Failed to reach target brightness of {target_white_level}."
f"Brightness reached {test.level} after {iterations} iterations." f"Brightness reached {test.level} after {iterations} iterations."
) )
@ -230,11 +232,9 @@ def adjust_white_balance_from_raw(
channel_gains = 1 / grids channel_gains = 1 / grids
if channel_gains.shape[1:] != channels.shape[1:]: if channel_gains.shape[1:] != channels.shape[1:]:
channel_gains = _upsample_channels(channel_gains, channels.shape[1:]) channel_gains = _upsample_channels(channel_gains, channels.shape[1:])
logging.info( LOGGER.info(f"Before gains, channel maxima are {np.max(channels, axis=(1, 2))}")
f"Before gains, channel maxima are {np.max(channels, axis=(1, 2))}"
)
channels = channels * channel_gains 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": if method == "centre":
_, height, width = channels.shape _, height, width = channels.shape
# Cut out the central 10% from 9/20 to 11/20... # 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. # 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)) 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"Raw white point is R: {red} G: {green} B: {blue}, "
f"setting AWB gains to ({new_awb_gains[0]:.2f}, " f"setting AWB gains to ({new_awb_gains[0]:.2f}, "
f"{new_awb_gains[1]:.2f})." f"{new_awb_gains[1]:.2f})."
@ -270,7 +270,7 @@ def adjust_white_balance_from_raw(
camera.controls.ColourGains = new_awb_gains camera.controls.ColourGains = new_awb_gains
time.sleep(sensor_info.long_pause) time.sleep(sensor_info.long_pause)
m = camera.capture_metadata() 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 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 # because of black level compensation. The line below forces a
# minimum value of 1 which will keep things well-behaved! # minimum value of 1 which will keep things well-behaved!
if max_brightness < 1: if max_brightness < 1:
logging.warning( LOGGER.warning(
f"Measured brightness of {max_brightness}. " f"Measured brightness of {max_brightness}. "
"This should normally be >= 1, and may indicate the " "This should normally be >= 1, and may indicate the "
"camera's black level compensation has gone wrong." "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"]), exposure_time=int(metadata["ExposureTime"]),
analog_gain=float(metadata["AnalogueGain"]), analog_gain=float(metadata["AnalogueGain"]),
) )
logging.info(f"{result.model_dump()}") LOGGER.info(f"{result.model_dump()}")
return result 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 # 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). # channels, 1/2 for green because there's twice as many green pixels).
raw_format = camera.camera_configuration()["raw"]["format"] 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) return _channels_from_bayer_array(raw_image)

16
src/openflexure_microscope_server/things/camera/simulation.py
View file

@ -30,6 +30,8 @@ from openflexure_microscope_server.ui import (
from . import BaseCamera, ArrayModel from . import BaseCamera, ArrayModel
from ..stage import BaseStage from ..stage import BaseStage
LOGGER = logging.getLogger(__name__)
# The ratio between "motor" steps and pixels # The ratio between "motor" steps and pixels
# higher related to a faster movement # higher related to a faster movement
RATIO = 0.2 RATIO = 0.2
@ -204,7 +206,7 @@ class SimulatedCamera(BaseCamera):
try: try:
pos = self.get_stage_position() pos = self.get_stage_position()
except Exception as e: 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} pos = {"x": 0, "y": 0, "z": 0}
return self.generate_image((pos["y"], pos["x"], pos["z"])) 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 If called while already streaming, the warning will be emitted and no other
action will be taken. action will be taken.
""" """
logging.warning( LOGGER.warning(
f"Simulation camera doesn't respect {main_resolution=} or {buffer_count=} " f"Simulation camera doesn't respect {main_resolution=} or {buffer_count=} "
"arguments." "arguments."
) )
@ -271,7 +273,7 @@ class SimulatedCamera(BaseCamera):
jpeg_lores = cv2.imencode(".jpg", ds_frame)[1].tobytes() jpeg_lores = cv2.imencode(".jpg", ds_frame)[1].tobytes()
self.lores_mjpeg_stream.add_frame(jpeg_lores, portal) self.lores_mjpeg_stream.add_frame(jpeg_lores, portal)
except Exception as e: 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 @lt.thing_action
def discard_frames(self) -> None: def discard_frames(self) -> None:
@ -293,8 +295,8 @@ class SimulatedCamera(BaseCamera):
binary image formats will be added in due course. binary image formats will be added in due course.
""" """
if wait is not None: if wait is not None:
logging.warning("Simulation camera has no wait option. Use None.") LOGGER.warning("Simulation camera has no wait option. Use None.")
logging.warning(f"Simulation camera camera doesn't respect {stream_name=}") LOGGER.warning(f"Simulation camera camera doesn't respect {stream_name=}")
return self.generate_frame() return self.generate_frame()
def capture_image( def capture_image(
@ -307,8 +309,8 @@ class SimulatedCamera(BaseCamera):
It is used for capture to memory. It is used for capture to memory.
""" """
if wait is not None: if wait is not None:
logging.warning("Simulation camera has no wait option. Use None.") LOGGER.warning("Simulation camera has no wait option. Use None.")
logging.warning(f"Simulation camera camera doesn't respect {stream_name=}") LOGGER.warning(f"Simulation camera camera doesn't respect {stream_name=}")
return Image.fromarray(self.generate_frame()) return Image.fromarray(self.generate_frame())
@lt.thing_action @lt.thing_action

4
src/openflexure_microscope_server/things/stage/sangaboard.py
View file

@ -15,6 +15,8 @@ import labthings_fastapi as lt
from . import BaseStage from . import BaseStage
LOGGER = logging.getLogger(__name__)
class SangaboardThing(BaseStage): class SangaboardThing(BaseStage):
"""A Thing to manage a Sangaboard motor controller. """A Thing to manage a Sangaboard motor controller.
@ -168,7 +170,7 @@ class SangaboardThing(BaseStage):
# cannot be used. # cannot be used.
intended_brightness = float(return_value[7:]) intended_brightness = float(return_value[7:])
on_brightness = 0.32 on_brightness = 0.32
logging.warning( LOGGER.warning(
"Brightness control is not yet implemented. Desired brightness: " "Brightness control is not yet implemented. Desired brightness: "
f"{intended_brightness}. Set brightness: {on_brightness}" f"{intended_brightness}. Set brightness: {on_brightness}"
) )