Fixed logging and split access and root file handlers

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)

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():

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."
     )
 

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 <setpoint>."""
-    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)

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):