From 4a553040d3d536a4a532bf8e6d99e1f42991250f Mon Sep 17 00:00:00 2001 From: Joel Collins Date: Wed, 20 May 2020 17:46:44 +0100 Subject: [PATCH 1/4] Fixed logging and split access and root file handlers --- openflexure_microscope/api/app.py | 46 ++++++++++++------- .../api/default_extensions/autofocus.py | 4 +- .../camera_stage_calibration_2d.py | 6 +-- .../recalibrate_utils.py | 26 +++++------ openflexure_microscope/api/utilities/gui.py | 5 +- openflexure_microscope/microscope.py | 8 ++-- 6 files changed, 54 insertions(+), 41 deletions(-) diff --git a/openflexure_microscope/api/app.py b/openflexure_microscope/api/app.py index fbd2b042..c5816708 100644 --- a/openflexure_microscope/api/app.py +++ b/openflexure_microscope/api/app.py @@ -33,31 +33,42 @@ from openflexure_microscope.api.microscope import default_microscope as api_micr from openflexure_microscope.api.v2 import views # Handle logging -DEFAULT_LOGFILE = logs_file_path("openflexure_microscope.log") +ROOT_LOGFILE = logs_file_path("openflexure_microscope.log") +ACCESS_LOGFILE = logs_file_path("openflexure_microscope.access.log") -logger = logging.getLogger() - -error_formatter = logging.Formatter( +# Basic log format +formatter = logging.Formatter( "[%(asctime)s] [%(threadName)s] [%(levelname)s] %(message)s" ) -rotating_logfile = logging.handlers.RotatingFileHandler( - DEFAULT_LOGFILE, maxBytes=1_000_000, backupCount=7 -) - -error_handlers = [rotating_logfile, logging.StreamHandler()] - -for handler in error_handlers: - handler.setFormatter(error_formatter) - logger.addHandler(handler) +# Get root logger +logger = logging.getLogger() logger.setLevel(logging.INFO) +# Create file handler +fh = logging.handlers.RotatingFileHandler( + ROOT_LOGFILE, maxBytes=1_000_000, backupCount=5 +) +fh.setFormatter(formatter) +fh.setLevel(logging.INFO) +fh.propagate = False + +# Create access log file handler +afh = logging.handlers.RotatingFileHandler( + ACCESS_LOGFILE, maxBytes=1_000_000, backupCount=5 +) +afh.setFormatter(formatter) +afh.setLevel(logging.INFO) +afh.propagate = False + +# Add file handler to root logger +logger.addHandler(fh) # Log server paths being used logging.info(f"Running with data path {OPENFLEXURE_VAR_PATH}") -print("Creating app") +logging.info("Creating app") # Create flask app app, labthing = create_app( __name__, @@ -176,6 +187,9 @@ atexit.register(cleanup) if __name__ == "__main__": from labthings.server.wsgi import Server - print("Starting OpenFlexure Microscope Server...") - server = Server(app, log=logger, error_log=logger) + # Block the access logs from propagating up to the root logger + logging.getLogger("labthings.server.wsgi.handler").propagate = False + + logging.info("Starting OpenFlexure Microscope Server...") + server = Server(app, log=afh, error_log=None) server.run(host="::", port=5000, debug=False, zeroconf=True) diff --git a/openflexure_microscope/api/default_extensions/autofocus.py b/openflexure_microscope/api/default_extensions/autofocus.py index ad9e17b5..8bc6ba7f 100644 --- a/openflexure_microscope/api/default_extensions/autofocus.py +++ b/openflexure_microscope/api/default_extensions/autofocus.py @@ -62,7 +62,7 @@ class JPEGSharpnessMonitor: def stop(self): "Stop the background thread" self.stop_event.set() - print("Joining JPEG thread") + logging.info("Joining JPEG thread") self.background_thread.join() def _measure_jpegs(self): @@ -75,7 +75,7 @@ class JPEGSharpnessMonitor: time_now = time.time() self.jpeg_sizes.append(size_now) self.jpeg_times.append(time_now) - print("Exited JPEG measure loop") + logging.info("Exited JPEG measure loop") if self.stop_event.is_set(): logging.debug("Cleanly stopped sharpness measurement in background thread") if self.should_stop(): diff --git a/openflexure_microscope/api/default_extensions/camera_stage_mapping/camera_stage_calibration_2d.py b/openflexure_microscope/api/default_extensions/camera_stage_mapping/camera_stage_calibration_2d.py index 9f090994..39ebd514 100644 --- a/openflexure_microscope/api/default_extensions/camera_stage_mapping/camera_stage_calibration_2d.py +++ b/openflexure_microscope/api/default_extensions/camera_stage_mapping/camera_stage_calibration_2d.py @@ -73,13 +73,13 @@ def calibrate_xy_grid(tracker, move, step=100, n_steps=4, backlash_compensation= transformed_image_positions = np.dot(image_positions, A) residuals = transformed_image_positions - stage_positions fractional_error = norm(residuals) / stage_positions.shape[0] - print(f"Ratio of residuals to displacement is {fractional_error})") + logging.debug(f"Ratio of residuals to displacement is {fractional_error})") if fractional_error > 0.05: # Check it was a reasonably good fit - print( + logging.warning( "Warning: the error fitting measured displacements was %.1f%%" % (fractional_error * 100) ) - print( + logging.info( f"Calibrated the pixel-location matrix.\nResiduals were {fractional_error*100:.1f}% of the shift." ) diff --git a/openflexure_microscope/api/default_extensions/picamera_autocalibrate/recalibrate_utils.py b/openflexure_microscope/api/default_extensions/picamera_autocalibrate/recalibrate_utils.py index 5dae166d..dbbd78ba 100644 --- a/openflexure_microscope/api/default_extensions/picamera_autocalibrate/recalibrate_utils.py +++ b/openflexure_microscope/api/default_extensions/picamera_autocalibrate/recalibrate_utils.py @@ -28,19 +28,19 @@ def flat_lens_shading_table(camera): def adjust_exposure_to_setpoint(camera, setpoint): """Adjust the camera's exposure time until the maximum pixel value is .""" - print("Adjusting shutter speed to hit setpoint {}".format(setpoint), end="") + logging.info("Adjusting shutter speed to hit setpoint {}".format(setpoint), end="") for i in range(3): print(".", end="") camera.shutter_speed = int( camera.shutter_speed * setpoint / np.max(rgb_image(camera)) ) time.sleep(1) - print("done") + logging.info("done") def auto_expose_and_freeze_settings(camera): """Freeze the settings after auto-exposing to white illumination""" - print("Allowing the camera to auto-expose") + logging.info("Allowing the camera to auto-expose") camera.awb_mode = "auto" camera.exposure_mode = "auto" camera.iso = ( @@ -49,18 +49,18 @@ def auto_expose_and_freeze_settings(camera): for i in range(6): print(".", end="") time.sleep(0.5) - print("done") + logging.info("done") - print("Freezing the camera settings...") + logging.info("Freezing the camera settings...") camera.shutter_speed = camera.exposure_speed - print("Shutter speed = {}".format(camera.shutter_speed)) + logging.info("Shutter speed = {}".format(camera.shutter_speed)) camera.exposure_mode = "off" - print("Auto exposure disabled") + logging.info("Auto exposure disabled") g = camera.awb_gains camera.awb_mode = "off" camera.awb_gains = g - print("Auto white balance disabled, gains are {}".format(g)) - print( + logging.info("Auto white balance disabled, gains are {}".format(g)) + logging.info( "Analogue gain: {}, Digital gain: {}".format( camera.analog_gain, camera.digital_gain ) @@ -90,7 +90,7 @@ def lst_from_channels(channels): # lst_resolution = list(np.ceil(full_resolution / 64.0).astype(int)) lst_resolution = [(r // 64) + 1 for r in full_resolution] # NB the size of the LST is 1/64th of the image, but rounded UP. - print("Generating a lens shading table at {}x{}".format(*lst_resolution)) + logging.info("Generating a lens shading table at {}x{}".format(*lst_resolution)) lens_shading = np.zeros([channels.shape[0]] + lst_resolution, dtype=np.float) for i in range(lens_shading.shape[0]): image_channel = channels[i, :, :] @@ -107,7 +107,7 @@ def lst_from_channels(channels): padded_image_channel = np.pad( image_channel, [(0, lw * 32 - iw), (0, lh * 32 - ih)], mode="edge" ) # Pad image to the right and bottom - print( + logging.info( "Channel shape: {}x{}, shading table shape: {}x{}, after padding {}".format( iw, ih, lw * 32, lh * 32, padded_image_channel.shape ) @@ -185,7 +185,7 @@ if __name__ == "__main__": with PiCamera() as camera: camera.start_preview() time.sleep(3) - print("Recalibrating...") + logging.info("Recalibrating...") recalibrate_camera(camera) - print("Done.") + logging.info("Done.") time.sleep(2) diff --git a/openflexure_microscope/api/utilities/gui.py b/openflexure_microscope/api/utilities/gui.py index f55611b4..6e00b04c 100644 --- a/openflexure_microscope/api/utilities/gui.py +++ b/openflexure_microscope/api/utilities/gui.py @@ -13,9 +13,8 @@ def build_gui_from_dict(gui_description, extension_object): # Make a working copy of GUI description api_gui = copy.deepcopy(gui_description) - print("") - print(extension_object) - print(extension_object._rules) + logging.debug(extension_object) + logging.debug(extension_object._rules) # Expand shorthand routes into full relative URLs if "forms" in gui_description and isinstance(api_gui["forms"], list): diff --git a/openflexure_microscope/microscope.py b/openflexure_microscope/microscope.py index 22cf6615..aab2fede 100644 --- a/openflexure_microscope/microscope.py +++ b/openflexure_microscope/microscope.py @@ -83,7 +83,7 @@ class Microscope: """ ### Detector - print("Creating camera") + logging.info("Creating camera") if configuration.get("camera"): camera_type = configuration["camera"].get("type") if camera_type in ("PiCamera", "PiCameraStreamer"): @@ -94,7 +94,7 @@ class Microscope: logging.warning("No compatible camera hardware found.") ### Stage - print("Creating stage") + logging.info("Creating stage") if configuration.get("stage"): stage_type = configuration["stage"].get("type") stage_port = configuration["stage"].get("port") @@ -105,7 +105,7 @@ class Microscope: logging.error(e) logging.warning("No compatible Sangaboard hardware found.") - print("Handling fallbacks") + logging.info("Handling fallbacks") ### Fallbacks if not self.camera: self.camera = MissingCamera() @@ -113,7 +113,7 @@ class Microscope: self.stage = MissingStage() ### Locks - print("Creating locks") + logging.info("Creating locks") if hasattr(self.camera, "lock"): self.lock.locks.append(self.camera.lock) if hasattr(self.stage, "lock"): From d9527685d6b60486f8defb018182688dc3af2591 Mon Sep 17 00:00:00 2001 From: Joel Collins Date: Wed, 20 May 2020 17:47:16 +0100 Subject: [PATCH 2/4] Updated to LabThings 0.6.3 --- poetry.lock | 27 +++++++-------------------- pyproject.toml | 2 +- 2 files changed, 8 insertions(+), 21 deletions(-) diff --git a/poetry.lock b/poetry.lock index 4c15fba4..83bad1bc 100644 --- a/poetry.lock +++ b/poetry.lock @@ -290,7 +290,7 @@ description = "Python implementation of LabThings, based on the Flask microframe name = "labthings" optional = false python-versions = ">=3.6,<4.0" -version = "0.6.2" +version = "0.6.3" [package.dependencies] Flask = ">=1.1.1,<2.0.0" @@ -379,7 +379,7 @@ description = "Core utilities for Python packages" name = "packaging" optional = false python-versions = ">=2.7, !=3.0.*, !=3.1.*, !=3.2.*, !=3.3.*" -version = "20.3" +version = "20.4" [package.dependencies] pyparsing = ">=2.0.2" @@ -466,19 +466,6 @@ all = ["Sphinx (>=1.5.1)", "check-manifest (>=0.25)", "coverage (>=4.0)", "isort docs = ["Sphinx (>=1.5.1)"] tests = ["check-manifest (>=0.25)", "coverage (>=4.0)", "isort (>=4.2.2)", "pydocstyle (>=1.0.0)", "pytest-cache (>=1.0)", "pytest-cov (>=1.8.0)", "pytest-pep8 (>=1.0.6)", "pytest (>=2.8.0)"] -[[package]] -category = "dev" -description = "Python interface to your NPM and package.json." -name = "pynpm" -optional = false -python-versions = "*" -version = "0.1.2" - -[package.extras] -all = ["Sphinx (>=1.5.1)", "check-manifest (>=0.25)", "coverage (>=4.0)", "isort (>=4.2.2)", "pydocstyle (>=1.0.0)", "pytest-cache (>=1.0)", "pytest-cov (>=1.8.0)", "pytest-pep8 (>=1.0.6)", "pytest (>=2.8.0)"] -docs = ["Sphinx (>=1.5.1)"] -tests = ["check-manifest (>=0.25)", "coverage (>=4.0)", "isort (>=4.2.2)", "pydocstyle (>=1.0.0)", "pytest-cache (>=1.0)", "pytest-cov (>=1.8.0)", "pytest-pep8 (>=1.0.6)", "pytest (>=2.8.0)"] - [[package]] category = "dev" description = "Python parsing module" @@ -773,7 +760,7 @@ ifaddr = "*" rpi = ["RPi.GPIO"] [metadata] -content-hash = "4fbf4240ac033cff8c0879b570792626e29a5aa2c5ffa2ec08b825ef8c2b700c" +content-hash = "1c923fc71ff343293798e1bd187df98791716e15e4d970fef1a8d77bf25de1e2" python-versions = "^3.6" [metadata.files] @@ -942,8 +929,8 @@ jinja2 = [ {file = "Jinja2-2.11.2.tar.gz", hash = "sha256:89aab215427ef59c34ad58735269eb58b1a5808103067f7bb9d5836c651b3bb0"}, ] labthings = [ - {file = "labthings-0.6.2-py3-none-any.whl", hash = "sha256:b83997a7dd115e0bfe20c2d5c52741c0b747fe8044e12db7bf82a433f8493d8e"}, - {file = "labthings-0.6.2.tar.gz", hash = "sha256:6373e2d0fdd731752a6fabd09708adeaf233b67f0cdcabee669642f647e9d95d"}, + {file = "labthings-0.6.3-py3-none-any.whl", hash = "sha256:63ef2a575d008b8e260dc5b64e7691b99d74a9dcdbea4263fb7975aeb50ce74b"}, + {file = "labthings-0.6.3.tar.gz", hash = "sha256:f5756ad4622210923511b690a8deb378bddc7d1e300ebd9e42cca8bc562ef032"}, ] lazy-object-proxy = [ {file = "lazy-object-proxy-1.4.3.tar.gz", hash = "sha256:f3900e8a5de27447acbf900b4750b0ddfd7ec1ea7fbaf11dfa911141bc522af0"}, @@ -1084,8 +1071,8 @@ opencv-python-headless = [ {file = "opencv_python_headless-4.2.0.34-cp38-cp38-win_amd64.whl", hash = "sha256:20c450943acebd9aa04566fdef4a658b94eec80a0c39a8f480c9aa1696034fcb"}, ] packaging = [ - {file = "packaging-20.3-py2.py3-none-any.whl", hash = "sha256:82f77b9bee21c1bafbf35a84905d604d5d1223801d639cf3ed140bd651c08752"}, - {file = "packaging-20.3.tar.gz", hash = "sha256:3c292b474fda1671ec57d46d739d072bfd495a4f51ad01a055121d81e952b7a3"}, + {file = "packaging-20.4-py2.py3-none-any.whl", hash = "sha256:998416ba6962ae7fbd6596850b80e17859a5753ba17c32284f67bfff33784181"}, + {file = "packaging-20.4.tar.gz", hash = "sha256:4357f74f47b9c12db93624a82154e9b120fa8293699949152b22065d556079f8"}, ] picamera = [] pillow = [ diff --git a/pyproject.toml b/pyproject.toml index 51e726a4..e288b50d 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -46,7 +46,7 @@ opencv-python-headless = [ {version = "4.1.0.25", python = "~3.7"}, # PiWheels build for RPi running Py37 {version = "4.2.0.34", python = "^3.8"} # Latest for Py38 systems ] -labthings = "0.6.2" +labthings = "0.6.3" pynpm = "^0.1.2" [tool.poetry.extras] From cf04fc36fceee0d37fd91c95dcb8619e72038eb4 Mon Sep 17 00:00:00 2001 From: Joel Collins Date: Fri, 22 May 2020 10:17:05 +0100 Subject: [PATCH 3/4] Added catch-all 410 response for API v1 routes --- openflexure_microscope/api/app.py | 6 +++++- 1 file changed, 5 insertions(+), 1 deletion(-) diff --git a/openflexure_microscope/api/app.py b/openflexure_microscope/api/app.py index c5816708..bc7e635d 100644 --- a/openflexure_microscope/api/app.py +++ b/openflexure_microscope/api/app.py @@ -9,7 +9,7 @@ import logging, logging.handlers import os import pkg_resources -from flask import Flask, send_file +from flask import Flask, send_file, abort from datetime import datetime @@ -157,6 +157,10 @@ def err_log(): attachment_filename="openflexure_microscope_{}.log".format(timestamp), ) +@app.route('/api/v1/', defaults={'path': ''}) +@app.route('/api/v1/') +def api_v1_catch_all(path): + abort(410, 'API v1 is no longer in use. Please upgrade your client.') # Automatically clean up microscope at exit def cleanup(): From b8a8160644006ca5c02f1270b31b198fa05bfe06 Mon Sep 17 00:00:00 2001 From: Joel Collins Date: Fri, 22 May 2020 10:23:13 +0100 Subject: [PATCH 4/4] Fixed log view file path --- openflexure_microscope/api/app.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/openflexure_microscope/api/app.py b/openflexure_microscope/api/app.py index bc7e635d..bb276986 100644 --- a/openflexure_microscope/api/app.py +++ b/openflexure_microscope/api/app.py @@ -152,7 +152,7 @@ def err_log(): """ timestamp = datetime.now().strftime("%Y-%m-%d_%H-%M-%S") return send_file( - DEFAULT_LOGFILE, + ROOT_LOGFILE, as_attachment=True, attachment_filename="openflexure_microscope_{}.log".format(timestamp), )