From 4a553040d3d536a4a532bf8e6d99e1f42991250f Mon Sep 17 00:00:00 2001 From: Joel Collins Date: Wed, 20 May 2020 17:46:44 +0100 Subject: [PATCH] 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"):