From 8a34a814166171aa1c7a13c8d41d6cb8d9362cbd Mon Sep 17 00:00:00 2001 From: "paul.lebel" Date: Fri, 14 Mar 2025 19:52:23 +0300 Subject: [PATCH 01/12] Updated severity levels of logs --- ulc_mm_package/QtGUI/acquisition.py | 2 +- ulc_mm_package/QtGUI/oracle.py | 4 ++-- ulc_mm_package/QtGUI/scope_op.py | 10 +++++----- ulc_mm_package/hardware/real/pneumatic_module.py | 8 ++++---- ulc_mm_package/hardware/scope_routines.py | 8 ++++---- ulc_mm_package/image_processing/data_storage.py | 4 ++-- ulc_mm_package/image_processing/flow_control.py | 1 - 7 files changed, 18 insertions(+), 19 deletions(-) diff --git a/ulc_mm_package/QtGUI/acquisition.py b/ulc_mm_package/QtGUI/acquisition.py index 2f26e148f..1f16ef5f7 100644 --- a/ulc_mm_package/QtGUI/acquisition.py +++ b/ulc_mm_package/QtGUI/acquisition.py @@ -89,7 +89,7 @@ def get_img(self): self.img, self.img_timestamp = next(self.img_gen) self.update_scopeop.emit(self.img, self.img_timestamp) except PyCamerasError as e: - self.logger.exception(e) + self.logger.error(f"Failed to grab image: {e}.") def send_img(self): self.update_liveview.emit(self.img) diff --git a/ulc_mm_package/QtGUI/oracle.py b/ulc_mm_package/QtGUI/oracle.py index 0dccb90f8..df882d192 100644 --- a/ulc_mm_package/QtGUI/oracle.py +++ b/ulc_mm_package/QtGUI/oracle.py @@ -656,7 +656,7 @@ def save_form(self): .strip() ) except subprocess.CalledProcessError: - self.logger.info("No Git branch or tag found.") + self.logger.error("No Git branch or tag found.") self.scopeop.mscope.data_storage.createNewExperiment( self.ext_dir, @@ -856,7 +856,7 @@ def main(): def shutoff_excepthook(type, value, tb): tb_string = "".join(traceback.format_exception(type, value, tb)) - oracle.logger.warning(f"Oracle shutoff due to exception - {tb_string}") + oracle.logger.error(f"Oracle shutoff due to exception - {tb_string}") try: app.shutoff.emit() # Pause before shutting off hardware to ensure there are no calls to camera post-shutoff diff --git a/ulc_mm_package/QtGUI/scope_op.py b/ulc_mm_package/QtGUI/scope_op.py index 9b909a77f..899fddd71 100644 --- a/ulc_mm_package/QtGUI/scope_op.py +++ b/ulc_mm_package/QtGUI/scope_op.py @@ -424,7 +424,7 @@ def _check_pressure_seal(self, *args): QR.NONE.value, ) except PressureLeak as e: - self.logger.error(str(e)) + self.logger.error(f"Pressure leak detected: {e}") self.default_error.emit( "Calibration failed", str(e), @@ -578,7 +578,7 @@ def run_autobrightness(self, img, _timestamp): try: self.img_signal.disconnect(self.run_autobrightness) except TypeError: - self.logger.info( + self.logger.warning( "run_autobrightness: img_signal already disconnected, no signal/slot changes were made." ) @@ -966,7 +966,7 @@ def run_experiment(self, img, timestamp) -> None: try: self.flowrate, _ = self.flowcontrol_routine.send((img_ds_10x, timestamp)) except Exception as e: - self.logger.warning(f"Unexpected flow control exception - {e}") + self.logger.error(f"Unexpected flow control exception - {e}") self.flowrate = -1 self.flowcontrol_routine = self.routines.flow_control_routine( self.mscope, self.target_flowrate @@ -993,7 +993,7 @@ def run_experiment(self, img, timestamp) -> None: ) = (pressure, status) except PressureSensorStaleValue as e: ## TODO??? - self.logger.info(f"Stale pressure sensor value - {e}") + self.logger.error(f"Stale pressure sensor value - {e}") self.img_metadata["led_pwm_val"] = self.mscope.led.pwm_duty_cycle self.img_metadata[ @@ -1020,7 +1020,7 @@ def run_experiment(self, img, timestamp) -> None: except Exception as e: # some error has occurred, but the TH sensor isn't critical, so just warn # and move on - self.logger.warning( + self.logger.error( f"exception occurred while retrieving temperature and humidity: {e}" ) self.img_metadata["humidity"] = None diff --git a/ulc_mm_package/hardware/real/pneumatic_module.py b/ulc_mm_package/hardware/real/pneumatic_module.py index 36fe8bb2d..8f66b26a1 100644 --- a/ulc_mm_package/hardware/real/pneumatic_module.py +++ b/ulc_mm_package/hardware/real/pneumatic_module.py @@ -135,7 +135,7 @@ def get_config_params(self) -> Tuple[float, float, float]: ) return min_duty_cycle, max_duty_cycle, step_size except Exception as e: - self.logger.exception( + self.logger.error( f"Error encountered while reading syringe min/max from the config file, {CONFIGURATION_FILE}. Setting defaults instead.\nException: {e}" ) return ( @@ -144,7 +144,7 @@ def get_config_params(self) -> Tuple[float, float, float]: DEFAULT_STEP, ) else: - self.logger.info( + self.logger.warning( f"{CONFIGURATION_FILE} was not found, using default values instead for syringe min/max duty cycle." ) return ( @@ -319,7 +319,7 @@ def getPressure(self) -> Tuple[float, PressureSensorRead]: raise PressureSensorStaleValue( f"{perf_counter() - self.prev_poll_time_s}s elapsed since last read (last value was: {self.prev_pressure} w/ status {self.prev_status.value})." ) - self.logger.info("Returning previous pressure value.") + self.logger.warning("Returning previous pressure value.") return self.prev_pressure, self.prev_status def getPressureImmediately(self) -> Tuple[float, PressureSensorRead]: @@ -351,7 +351,7 @@ def getPressureImmediately(self) -> Tuple[float, PressureSensorRead]: self.prev_poll_time_s = perf_counter() return (pressure, status) except PressureSensorBusy as e: - self.logger.info(f"Attempted read but pressure sensor is busy: {e}.") + self.logger.warning(f"Attempted read but pressure sensor is busy: {e}.") raise PressureSensorBusy() else: raise PressureSensorNotInstantiated(self.mpr_err_msg) diff --git a/ulc_mm_package/hardware/scope_routines.py b/ulc_mm_package/hardware/scope_routines.py index bf366606d..26b5c8d46 100644 --- a/ulc_mm_package/hardware/scope_routines.py +++ b/ulc_mm_package/hardware/scope_routines.py @@ -271,7 +271,7 @@ def flow_control_routine( flow_controller.pneumatic_module.default_min_step_size ) - self.logger.error( + self.logger.warning( "Can't reach target flowrate. Syringe at end of travel." ) @@ -540,7 +540,7 @@ def find_cells_routine( try: flow_controller.adjustSyringe(flow_error=1.0) except (CantReachTargetFlowrate, SyringeEndOfTravel): - self.logger.info( + self.logger.error( f"Syringe reached end of travel but current pressure: ({curr_pressure_gauge:.2f} mBar) is less than max allowable ({processing_constants.MAX_VACUUM_PRESSURE:.2f} mBar).\nContinuing with cell finder anyway..." ) break @@ -558,12 +558,12 @@ def find_cells_routine( while perf_counter() - start < pull_time: # Wait the desired time yield - logging.info("Resetting pressure...") + self.logger.info("Resetting pressure...") mscope.pneumatic_module.setDutyCycle( mscope.pneumatic_module.getMaxDutyCycle() ) - logging.info("Looking for cells...") + self.logger.info("Looking for cells...") # Perform a full focal stack and get the cross-correlation value for each image # If we're currently at the bottom, do the bottom-up sweep. Otherwise, do the top-down sweep. if mscope.motor.pos == 0: diff --git a/ulc_mm_package/image_processing/data_storage.py b/ulc_mm_package/image_processing/data_storage.py index 942c7e3f3..b57760abc 100644 --- a/ulc_mm_package/image_processing/data_storage.py +++ b/ulc_mm_package/image_processing/data_storage.py @@ -465,13 +465,13 @@ def save_uniform_sample(self) -> None: num_subsequences=NUM_SUBSEQUENCES, ) except ValueError: - self.logger.info("Too few images, so no subsample was generated.") + self.logger.error("Too few images, so no subsample was generated.") return try: sub_seq_path = self._create_subseq_folder() except: - self.logger.info( + self.logger.error( "Unable to create the subsample folder. Aborting subsampling." ) return diff --git a/ulc_mm_package/image_processing/flow_control.py b/ulc_mm_package/image_processing/flow_control.py index 2e5f549b3..24d93ba0f 100644 --- a/ulc_mm_package/image_processing/flow_control.py +++ b/ulc_mm_package/image_processing/flow_control.py @@ -92,7 +92,6 @@ def __init__( self.first_image: bool = True self.target_flowrate: Optional[float] = None - self.logger = logging.getLogger() def reset(self): self.fre.reset() From c6c21fdd93ef9d2802c191f2d480eb3020ea777f Mon Sep 17 00:00:00 2001 From: "paul.lebel" Date: Fri, 14 Mar 2025 20:54:51 +0300 Subject: [PATCH 02/12] Replaced print statements with logger. Added additional debug logging. Added new log file on new experiment --- ulc_mm_package/QtGUI/oracle.py | 32 ++++++++++++--- .../hardware/real/motorcontroller.py | 40 +++++++++---------- .../hardware/sim/motorcontroller.py | 40 +++++++++---------- 3 files changed, 66 insertions(+), 46 deletions(-) diff --git a/ulc_mm_package/QtGUI/oracle.py b/ulc_mm_package/QtGUI/oracle.py index df882d192..0f736f070 100644 --- a/ulc_mm_package/QtGUI/oracle.py +++ b/ulc_mm_package/QtGUI/oracle.py @@ -305,14 +305,14 @@ def _init_ssd(self): samsung_ext_dir ): self.ext_dir = samsung_ext_dir + "/" - print(f"Saving data to {self.ext_dir}") + self.logger.info(f"Saving data to {self.ext_dir}") else: if not path.exists(samsung_ext_dir): - print( + self.logger.warning( f"'Couldn't find {SSD_NAME}' in {SSD_DIR}. Searching for other folders in this directory." ) elif not DataStorage.is_there_sufficient_storage(samsung_ext_dir): - print( + self.logger.warning( f"'{SSD_NAME}' in {SSD_DIR} is out of storage. Searching for other folders in this directory." ) @@ -326,10 +326,10 @@ def _init_ssd(self): if candidate_path != samsung_ext_dir and path.isdir(candidate_path): if DataStorage.is_there_sufficient_storage(candidate_path): self.ext_dir = candidate_path + "/" - print(f"Saving data to {self.ext_dir}") + self.logger.info(f"Saving data to {self.ext_dir}") break except (FileNotFoundError, IndexError): - print( + self.logger.error( f"Could not find any folders within {SSD_DIR}. Check that the SSD is plugged in." ) self.display_message( @@ -346,7 +346,7 @@ def _init_ssd(self): sys.exit(1) def ssd_full_msg_and_exit(self): - print( + self.logger.error( "Couldn't find any folders in /media/pi with sufficient storage. Please eject and replace the SSD with a new one. Thank you!" ) self.display_message( @@ -769,6 +769,7 @@ def _start_intermission(self, msg=None, parasitemia_vis_path=""): if message_result == QMessageBox.No: self.shutoff() elif message_result == QMessageBox.Yes: + self._start_new_log() self.logger.info("Starting new experiment.") if not DataStorage.is_there_sufficient_storage(self.ext_dir): self.ssd_full_msg_and_exit() @@ -780,6 +781,25 @@ def _start_intermission(self, msg=None, parasitemia_vis_path=""): self.scopeop.to_intermission() self.scopeop.rerun() + def _start_new_log(self): + """ + Closes the current log file and creates new timestamped log file. + """ + + logging.shutdown() + + logger_config_path = Path(__file__).resolve().parent.parent / "logger.config" + fileConfig( + fname=str(logger_config_path), + defaults={ + "filename": path.join(log_dir, f"{self.datetime_str}.log"), + "fileHandlerLevel": "DEBUG" if VERBOSE else "INFO", + }, + ) + self.logger = logging.root + + self.logger.info("CREATED LOG") + def shutoff(self): self.logger.info("Starting oracle shut off.") diff --git a/ulc_mm_package/hardware/real/motorcontroller.py b/ulc_mm_package/hardware/real/motorcontroller.py index b653ddea7..254cb8658 100644 --- a/ulc_mm_package/hardware/real/motorcontroller.py +++ b/ulc_mm_package/hardware/real/motorcontroller.py @@ -305,7 +305,7 @@ def move_rel( if time.perf_counter() - start_time >= timeout_s: raise MotorMoveTimeout() if verbose: - print(f"Steps {i} \ Position: {self.pos}") + self.logger.debug(f"Steps {i} \ Position: {self.pos}") except KeyboardInterrupt: raise MotorControllerError("User keyboard interrupt") @@ -323,14 +323,14 @@ def move_rel( # Print report status if verbose: - print("\nRpiMotorLib, Motor Run finished, Details:.\n") - print("Motor type = {}".format(self.motor_type)) - print("Direction = {}".format(dir)) - print("Step Type = {}".format(self.steptype)) - print("Number of steps = {}".format(self.pos - start_pos)) - print("Step Delay = {}".format(stepdelay)) - print("Intial delay = {}".format(initdelay)) - print("Size of turn in degrees = {}".format(self.degree_calc(steps))) + self.logger.debug("\nRpiMotorLib, Motor Run finished, Details:.\n") + self.logger.debug("Motor type = {}".format(self.motor_type)) + self.logger.debug("Direction = {}".format(dir)) + self.logger.debug("Step Type = {}".format(self.steptype)) + self.logger.debug("Number of steps = {}".format(self.pos - start_pos)) + self.logger.debug("Step Delay = {}".format(stepdelay)) + self.logger.debug("Intial delay = {}".format(initdelay)) + self.logger.debug("Size of turn in degrees = {}".format(self.degree_calc(steps))) @lock_no_block(MOTOR_LOCK, MotorInMotion) def move_abs(self, pos: int = 200, stepdelay=0.005, verbose=False, initdelay=0.05): @@ -384,14 +384,14 @@ def move_abs(self, pos: int = 200, stepdelay=0.005, verbose=False, initdelay=0.0 time.sleep(stepdelay) self.pos += step_increment if verbose: - print(f"Steps {i} \ Position: {self.pos}") + self.logger.debug(f"Steps {i} \ Position: {self.pos}") except KeyboardInterrupt: - print("User Keyboard Interrupt") + self.logger.error("User Keyboard Interrupt") except StopMotorInterrupt: raise except Exception: - print("RpiMotorLib : Unexpected error:") + self.logger.error("RpiMotorLib : Unexpected error:") raise finally: @@ -401,14 +401,14 @@ def move_abs(self, pos: int = 200, stepdelay=0.005, verbose=False, initdelay=0.0 # Print report status if verbose: - print("\nRpiMotorLib, Motor Run finished, Details:.\n") - print("Motor type = {}".format(self.motor_type)) - print("Direction = {}".format(dir)) - print("Step Type = {}".format(self.steptype)) - print("Number of steps = {}".format(self.pos - start_pos)) - print("Step Delay = {}".format(stepdelay)) - print("Intial delay = {}".format(initdelay)) - print("Size of turn in degrees = {}".format(self.degree_calc(steps))) + self.logger.debug("\nRpiMotorLib, Motor Run finished, Details:.\n") + self.logger.debug("Motor type = {}".format(self.motor_type)) + self.logger.debug("Direction = {}".format(dir)) + self.logger.debug("Step Type = {}".format(self.steptype)) + self.logger.debug("Number of steps = {}".format(self.pos - start_pos)) + self.logger.debug("Step Delay = {}".format(stepdelay)) + self.logger.debug("Intial delay = {}".format(initdelay)) + self.logger.debug("Size of turn in degrees = {}".format(self.degree_calc(steps))) def threaded_move_rel(self, *args, **kwargs): if not MOTOR_LOCK.locked(): diff --git a/ulc_mm_package/hardware/sim/motorcontroller.py b/ulc_mm_package/hardware/sim/motorcontroller.py index 7a2e39953..6dd902b43 100644 --- a/ulc_mm_package/hardware/sim/motorcontroller.py +++ b/ulc_mm_package/hardware/sim/motorcontroller.py @@ -244,7 +244,7 @@ def move_rel( if time.perf_counter() - start_time >= timeout_s: raise MotorMoveTimeout() if verbose: - print(f"Steps {i} \ Position: {self.pos}") + self.logger.debug(f"Steps {i} \ Position: {self.pos}") except KeyboardInterrupt: raise MotorControllerError("User keyboard interrupt") @@ -258,14 +258,14 @@ def move_rel( finally: # Print report status if verbose: - print("\nRpiMotorLib, Motor Run finished, Details:.\n") - print("Motor type = {}".format(self.motor_type)) - print("Direction = {}".format(dir)) - print("Step Type = {}".format(self.steptype)) - print("Number of steps = {}".format(self.pos - start_pos)) - print("Step Delay = {}".format(stepdelay)) - print("Intial delay = {}".format(initdelay)) - print("Size of turn in degrees = {}".format(self.degree_calc(steps))) + self.logger.debug("\nRpiMotorLib, Motor Run finished, Details:.\n") + self.logger.debug("Motor type = {}".format(self.motor_type)) + self.logger.debug("Direction = {}".format(dir)) + self.logger.debug("Step Type = {}".format(self.steptype)) + self.logger.debug("Number of steps = {}".format(self.pos - start_pos)) + self.logger.debug("Step Delay = {}".format(stepdelay)) + self.logger.debug("Intial delay = {}".format(initdelay)) + self.logger.debug("Size of turn in degrees = {}".format(self.degree_calc(steps))) @lock_no_block(MOTOR_LOCK, MotorInMotion) def move_abs(self, pos: int = 200, stepdelay=0.005, verbose=False, initdelay=0.05): @@ -316,27 +316,27 @@ def move_abs(self, pos: int = 200, stepdelay=0.005, verbose=False, initdelay=0.0 time.sleep(stepdelay) self.pos += step_increment if verbose: - print(f"Steps {i} \ Position: {self.pos}") + self.logger.debug(f"Steps {i} \ Position: {self.pos}") except KeyboardInterrupt: - print("User Keyboard Interrupt") + self.logger.error("User Keyboard Interrupt") except StopMotorInterrupt: raise except Exception: - print("RpiMotorLib : Unexpected error:") + self.logger.error("RpiMotorLib : Unexpected error:") raise finally: # Print report status if verbose: - print("\nRpiMotorLib, Motor Run finished, Details:.\n") - print("Motor type = {}".format(self.motor_type)) - print("Direction = {}".format(dir)) - print("Step Type = {}".format(self.steptype)) - print("Number of steps = {}".format(self.pos - start_pos)) - print("Step Delay = {}".format(stepdelay)) - print("Intial delay = {}".format(initdelay)) - print("Size of turn in degrees = {}".format(self.degree_calc(steps))) + self.logger.debug("\nRpiMotorLib, Motor Run finished, Details:.\n") + self.logger.debug("Motor type = {}".format(self.motor_type)) + self.logger.debug("Direction = {}".format(dir)) + self.logger.debug("Step Type = {}".format(self.steptype)) + self.logger.debug("Number of steps = {}".format(self.pos - start_pos)) + self.logger.debug("Step Delay = {}".format(stepdelay)) + self.logger.debug("Intial delay = {}".format(initdelay)) + self.logger.debug("Size of turn in degrees = {}".format(self.degree_calc(steps))) @staticmethod def is_locked(): From 99bdc43fa82dfb3d1c6f145d50455990f0979081 Mon Sep 17 00:00:00 2001 From: "paul.lebel" Date: Fri, 14 Mar 2025 21:06:46 +0300 Subject: [PATCH 03/12] forgot a variable --- ulc_mm_package/QtGUI/oracle.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/ulc_mm_package/QtGUI/oracle.py b/ulc_mm_package/QtGUI/oracle.py index 0f736f070..e2a5d4383 100644 --- a/ulc_mm_package/QtGUI/oracle.py +++ b/ulc_mm_package/QtGUI/oracle.py @@ -787,7 +787,7 @@ def _start_new_log(self): """ logging.shutdown() - + log_dir = path.join(self.ext_dir, "logs") logger_config_path = Path(__file__).resolve().parent.parent / "logger.config" fileConfig( fname=str(logger_config_path), @@ -798,7 +798,7 @@ def _start_new_log(self): ) self.logger = logging.root - self.logger.info("CREATED LOG") + self.logger.info("CREATED LOG.") def shutoff(self): self.logger.info("Starting oracle shut off.") From 2c27698cdfc6619648c658bfe3811cde421b0160 Mon Sep 17 00:00:00 2001 From: "paul.lebel" Date: Fri, 14 Mar 2025 21:10:02 +0300 Subject: [PATCH 04/12] formattinggit add . --- ulc_mm_package/hardware/real/motorcontroller.py | 8 ++++++-- ulc_mm_package/hardware/sim/motorcontroller.py | 8 ++++++-- 2 files changed, 12 insertions(+), 4 deletions(-) diff --git a/ulc_mm_package/hardware/real/motorcontroller.py b/ulc_mm_package/hardware/real/motorcontroller.py index 254cb8658..fb9bbbaa3 100644 --- a/ulc_mm_package/hardware/real/motorcontroller.py +++ b/ulc_mm_package/hardware/real/motorcontroller.py @@ -330,7 +330,9 @@ def move_rel( self.logger.debug("Number of steps = {}".format(self.pos - start_pos)) self.logger.debug("Step Delay = {}".format(stepdelay)) self.logger.debug("Intial delay = {}".format(initdelay)) - self.logger.debug("Size of turn in degrees = {}".format(self.degree_calc(steps))) + self.logger.debug( + "Size of turn in degrees = {}".format(self.degree_calc(steps)) + ) @lock_no_block(MOTOR_LOCK, MotorInMotion) def move_abs(self, pos: int = 200, stepdelay=0.005, verbose=False, initdelay=0.05): @@ -408,7 +410,9 @@ def move_abs(self, pos: int = 200, stepdelay=0.005, verbose=False, initdelay=0.0 self.logger.debug("Number of steps = {}".format(self.pos - start_pos)) self.logger.debug("Step Delay = {}".format(stepdelay)) self.logger.debug("Intial delay = {}".format(initdelay)) - self.logger.debug("Size of turn in degrees = {}".format(self.degree_calc(steps))) + self.logger.debug( + "Size of turn in degrees = {}".format(self.degree_calc(steps)) + ) def threaded_move_rel(self, *args, **kwargs): if not MOTOR_LOCK.locked(): diff --git a/ulc_mm_package/hardware/sim/motorcontroller.py b/ulc_mm_package/hardware/sim/motorcontroller.py index 6dd902b43..0aeb50573 100644 --- a/ulc_mm_package/hardware/sim/motorcontroller.py +++ b/ulc_mm_package/hardware/sim/motorcontroller.py @@ -265,7 +265,9 @@ def move_rel( self.logger.debug("Number of steps = {}".format(self.pos - start_pos)) self.logger.debug("Step Delay = {}".format(stepdelay)) self.logger.debug("Intial delay = {}".format(initdelay)) - self.logger.debug("Size of turn in degrees = {}".format(self.degree_calc(steps))) + self.logger.debug( + "Size of turn in degrees = {}".format(self.degree_calc(steps)) + ) @lock_no_block(MOTOR_LOCK, MotorInMotion) def move_abs(self, pos: int = 200, stepdelay=0.005, verbose=False, initdelay=0.05): @@ -336,7 +338,9 @@ def move_abs(self, pos: int = 200, stepdelay=0.005, verbose=False, initdelay=0.0 self.logger.debug("Number of steps = {}".format(self.pos - start_pos)) self.logger.debug("Step Delay = {}".format(stepdelay)) self.logger.debug("Intial delay = {}".format(initdelay)) - self.logger.debug("Size of turn in degrees = {}".format(self.degree_calc(steps))) + self.logger.debug( + "Size of turn in degrees = {}".format(self.degree_calc(steps)) + ) @staticmethod def is_locked(): From 9a50c2bc553d9bb33eee55afb197d209d34ae523 Mon Sep 17 00:00:00 2001 From: "paul.lebel" Date: Fri, 14 Mar 2025 23:39:43 +0300 Subject: [PATCH 05/12] Added periodic metadata logging --- ulc_mm_package/QtGUI/scope_op.py | 12 ++++++++++++ ulc_mm_package/scope_constants.py | 21 +++++++++++++++++++++ 2 files changed, 33 insertions(+) diff --git a/ulc_mm_package/QtGUI/scope_op.py b/ulc_mm_package/QtGUI/scope_op.py index 899fddd71..27d450f07 100644 --- a/ulc_mm_package/QtGUI/scope_op.py +++ b/ulc_mm_package/QtGUI/scope_op.py @@ -64,6 +64,8 @@ VERBOSE, ACQUISITION_PERIOD, LIVEVIEW_PERIOD, + FRAME_LOG_INTERVAL, + PERIODIC_METADATA_KEYS, ) @@ -1006,6 +1008,16 @@ def run_experiment(self, img, timestamp) -> None: self.img_metadata["classic_sharpness_ratio"] = sharpness_ratio_rel_peak self.img_metadata["mean_pixel_val"] = curr_mean_pixel_val + if self.frame_count % FRAME_LOG_INTERVAL == 0: + all_values = { + key: self.img_metadata.get(key, None) for key in PERIODIC_METADATA_KEYS + } + self.logger.info( + f"[Frame {self.frame_count}] Full periodic metadata: {all_values}" + ) + else: + all_values = [] + if self.frame_count % TH_PERIOD_NUM == 0: try: ( diff --git a/ulc_mm_package/scope_constants.py b/ulc_mm_package/scope_constants.py index a973bdba0..dab72ac54 100644 --- a/ulc_mm_package/scope_constants.py +++ b/ulc_mm_package/scope_constants.py @@ -206,3 +206,24 @@ def IMG_HEIGHT(self) -> int: SSD_DIR = "../QtGUI/sim_media/pi/" else: SSD_DIR = "/media/pi/" + +# ================ Log file constants ================ # +PERIODIC_METADATA_KEYS = [ + "motor_pos", + "pressure_hpa", + "syringe_pos", + "flowrate", + "filtered_focus_error", + "classic_sharpness_ratio", + "temperature", + "camera_temperature", +] + +END_OF_RUN_METADATA_KEYS = [ + "im_counter", + "location", + "estimated_parasitemia", + "cell_counts", +] + +FRAME_LOG_INTERVAL = 100 From c2710fcf051466f579f9891719f1cfcb78f1f19d Mon Sep 17 00:00:00 2001 From: "paul.lebel" Date: Mon, 17 Mar 2025 23:28:32 +0300 Subject: [PATCH 06/12] Added end of run and periodic logging --- ulc_mm_package/QtGUI/scope_op.py | 36 +++++++++++++------ .../image_processing/ewma_filtering_utils.py | 2 ++ ulc_mm_package/scope_constants.py | 2 +- 3 files changed, 28 insertions(+), 12 deletions(-) diff --git a/ulc_mm_package/QtGUI/scope_op.py b/ulc_mm_package/QtGUI/scope_op.py index 27d450f07..1ef6a968c 100644 --- a/ulc_mm_package/QtGUI/scope_op.py +++ b/ulc_mm_package/QtGUI/scope_op.py @@ -250,6 +250,8 @@ def _set_exp_variables(self): self.parasitemia_vis_path = "" + self.periodic_log_values = {key: None for key in PERIODIC_METADATA_KEYS} + self.update_img_count.emit(0) self.update_msg.emit("Starting new experiment") @@ -552,6 +554,7 @@ def _end_experiment(self, *args): f"Finished processing {num_images_leftover} images in {t1-t0:.0f} seconds" ) + self.finishing_experiment.emit(65) self.mscope.reset_for_end_experiment() @@ -559,6 +562,16 @@ def _end_experiment(self, *args): # Turn camera back on self.mscope.camera.startAcquisition() + class_counts_str = ", ".join( + f"{class_name}={count}" + for class_name, count in zip(YOGO_CLASS_LIST, self.raw_cell_count) + ) + + self.logger.info( + f"Finished experiment at location {self.location}. " + f"Processed {self.frame_count} frames. " + f"Final class counts: {class_counts_str}" + ) self.finishing_experiment.emit(100) def _start_intermission(self, msg): @@ -983,7 +996,7 @@ def run_experiment(self, img, timestamp) -> None: curr_mean_pixel_val = self.periodic_autobrightness_routine.send(resized_img) # ------------------------------------ - # Update remaining metadata in per-image csv + # Update remaining metadata in per-image csv and log # ------------------------------------ t0 = perf_counter() self.img_metadata["motor_pos"] = self.mscope.motor.getCurrentPosition() @@ -1008,16 +1021,6 @@ def run_experiment(self, img, timestamp) -> None: self.img_metadata["classic_sharpness_ratio"] = sharpness_ratio_rel_peak self.img_metadata["mean_pixel_val"] = curr_mean_pixel_val - if self.frame_count % FRAME_LOG_INTERVAL == 0: - all_values = { - key: self.img_metadata.get(key, None) for key in PERIODIC_METADATA_KEYS - } - self.logger.info( - f"[Frame {self.frame_count}] Full periodic metadata: {all_values}" - ) - else: - all_values = [] - if self.frame_count % TH_PERIOD_NUM == 0: try: ( @@ -1060,5 +1063,16 @@ def run_experiment(self, img, timestamp) -> None: t1 = perf_counter() self._update_metadata_if_verbose("datastorage.writeData", t1 - t0) + for key in PERIODIC_METADATA_KEYS: + val = self.img_metadata.get(key, None) + if val is not None: + self.periodic_log_values[key] = val + + if self.frame_count % FRAME_LOG_INTERVAL == 0: + # Log full periodic metadata + self.logger.info( + f"[Frame {self.frame_count}] Full periodic metadata: {self.periodic_log_values}" + ) + if self.running: self.img_signal.connect(self.run_experiment) diff --git a/ulc_mm_package/image_processing/ewma_filtering_utils.py b/ulc_mm_package/image_processing/ewma_filtering_utils.py index 0b1ea36e6..2cd7a706c 100644 --- a/ulc_mm_package/image_processing/ewma_filtering_utils.py +++ b/ulc_mm_package/image_processing/ewma_filtering_utils.py @@ -128,6 +128,8 @@ def update_and_get_val_arr(self, new_measurement: npt.NDArray) -> npt.NDArray: self.prev_val, new_measurement, self.alpha ) + return + @staticmethod def get_halflife_from_smoothing_factor(alpha: float) -> float: """Determine the half-life of the filter given its alpha value diff --git a/ulc_mm_package/scope_constants.py b/ulc_mm_package/scope_constants.py index dab72ac54..ee49b3528 100644 --- a/ulc_mm_package/scope_constants.py +++ b/ulc_mm_package/scope_constants.py @@ -220,7 +220,7 @@ def IMG_HEIGHT(self) -> int: ] END_OF_RUN_METADATA_KEYS = [ - "im_counter", + "frame_count", "location", "estimated_parasitemia", "cell_counts", From abd325d8f19bdc9694056f01d54d1ca1926b8352 Mon Sep 17 00:00:00 2001 From: "paul.lebel" Date: Mon, 17 Mar 2025 23:50:45 +0300 Subject: [PATCH 07/12] Added experiment's metadata to the log --- ulc_mm_package/QtGUI/oracle.py | 3 +++ ulc_mm_package/QtGUI/scope_op.py | 3 +-- 2 files changed, 4 insertions(+), 2 deletions(-) diff --git a/ulc_mm_package/QtGUI/oracle.py b/ulc_mm_package/QtGUI/oracle.py index e2a5d4383..ab0004c97 100644 --- a/ulc_mm_package/QtGUI/oracle.py +++ b/ulc_mm_package/QtGUI/oracle.py @@ -667,6 +667,9 @@ def save_form(self): ) sample_type = self.experiment_metadata["sample_type"] + + self.logger.info(f"Experiment Metadata: {self.experiment_metadata}") + clinical = sample_type == CLINICAL_SAMPLE skip = not clinical and not sample_type == CULTURED_SAMPLE if skip: diff --git a/ulc_mm_package/QtGUI/scope_op.py b/ulc_mm_package/QtGUI/scope_op.py index 1ef6a968c..d642b1cf8 100644 --- a/ulc_mm_package/QtGUI/scope_op.py +++ b/ulc_mm_package/QtGUI/scope_op.py @@ -554,7 +554,6 @@ def _end_experiment(self, *args): f"Finished processing {num_images_leftover} images in {t1-t0:.0f} seconds" ) - self.finishing_experiment.emit(65) self.mscope.reset_for_end_experiment() @@ -568,7 +567,7 @@ def _end_experiment(self, *args): ) self.logger.info( - f"Finished experiment at location {self.location}. " + f"Finished experiment." f"Processed {self.frame_count} frames. " f"Final class counts: {class_counts_str}" ) From 71d1955fb242ed4f814b1eb484bf555d20dc975d Mon Sep 17 00:00:00 2001 From: "paul.lebel" Date: Tue, 18 Mar 2025 04:35:36 +0300 Subject: [PATCH 08/12] Fixed a bug and some formatting errors --- ulc_mm_package/QtGUI/oracle.py | 12 +++++++----- ulc_mm_package/QtGUI/scope_op.py | 3 ++- ulc_mm_package/logger.config | 8 +++++++- 3 files changed, 16 insertions(+), 7 deletions(-) diff --git a/ulc_mm_package/QtGUI/oracle.py b/ulc_mm_package/QtGUI/oracle.py index ab0004c97..7f81f0846 100644 --- a/ulc_mm_package/QtGUI/oracle.py +++ b/ulc_mm_package/QtGUI/oracle.py @@ -305,14 +305,14 @@ def _init_ssd(self): samsung_ext_dir ): self.ext_dir = samsung_ext_dir + "/" - self.logger.info(f"Saving data to {self.ext_dir}") + print(f"Saving data to {self.ext_dir}") else: if not path.exists(samsung_ext_dir): - self.logger.warning( + print( f"'Couldn't find {SSD_NAME}' in {SSD_DIR}. Searching for other folders in this directory." ) elif not DataStorage.is_there_sufficient_storage(samsung_ext_dir): - self.logger.warning( + print( f"'{SSD_NAME}' in {SSD_DIR} is out of storage. Searching for other folders in this directory." ) @@ -326,10 +326,10 @@ def _init_ssd(self): if candidate_path != samsung_ext_dir and path.isdir(candidate_path): if DataStorage.is_there_sufficient_storage(candidate_path): self.ext_dir = candidate_path + "/" - self.logger.info(f"Saving data to {self.ext_dir}") + print(f"Saving data to {self.ext_dir}") break except (FileNotFoundError, IndexError): - self.logger.error( + print( f"Could not find any folders within {SSD_DIR}. Check that the SSD is plugged in." ) self.display_message( @@ -792,12 +792,14 @@ def _start_new_log(self): logging.shutdown() log_dir = path.join(self.ext_dir, "logs") logger_config_path = Path(__file__).resolve().parent.parent / "logger.config" + self.datetime_str = datetime.now().strftime(DATETIME_FORMAT) fileConfig( fname=str(logger_config_path), defaults={ "filename": path.join(log_dir, f"{self.datetime_str}.log"), "fileHandlerLevel": "DEBUG" if VERBOSE else "INFO", }, + disable_existing_loggers=False, ) self.logger = logging.root diff --git a/ulc_mm_package/QtGUI/scope_op.py b/ulc_mm_package/QtGUI/scope_op.py index d642b1cf8..59e46eb40 100644 --- a/ulc_mm_package/QtGUI/scope_op.py +++ b/ulc_mm_package/QtGUI/scope_op.py @@ -342,6 +342,7 @@ def setup(self): def lid_open_pause_handler(self, *args): self.lid_opened = True + self.logger.info("Lid opened.") if self.mscope.led._isOn: self.lid_open_pause.emit() @@ -567,7 +568,7 @@ def _end_experiment(self, *args): ) self.logger.info( - f"Finished experiment." + f"Finished experiment. " f"Processed {self.frame_count} frames. " f"Final class counts: {class_counts_str}" ) diff --git a/ulc_mm_package/logger.config b/ulc_mm_package/logger.config index 96d264fc2..eff745b73 100644 --- a/ulc_mm_package/logger.config +++ b/ulc_mm_package/logger.config @@ -1,5 +1,5 @@ [loggers] -keys=root +keys=root, transitionscore [handlers] keys=fileHandler, printHandler @@ -11,6 +11,12 @@ keys=stringFormatter, printFormatter level=INFO handlers=fileHandler, printHandler +[logger_transitionscore] +level=ERROR +handlers=fileHandler, printHandler +qualname=transitions.core +propagate=0 + [handler_fileHandler] class=FileHandler args=('%(filename)s', 'a') From e861a31182ccf32ec8960846510efdd674b307d7 Mon Sep 17 00:00:00 2001 From: "paul.lebel" Date: Tue, 18 Mar 2025 22:12:01 +0300 Subject: [PATCH 09/12] Added LED data to logs --- ulc_mm_package/scope_constants.py | 8 +------- 1 file changed, 1 insertion(+), 7 deletions(-) diff --git a/ulc_mm_package/scope_constants.py b/ulc_mm_package/scope_constants.py index ee49b3528..7db87fffd 100644 --- a/ulc_mm_package/scope_constants.py +++ b/ulc_mm_package/scope_constants.py @@ -217,13 +217,7 @@ def IMG_HEIGHT(self) -> int: "classic_sharpness_ratio", "temperature", "camera_temperature", -] - -END_OF_RUN_METADATA_KEYS = [ - "frame_count", - "location", - "estimated_parasitemia", - "cell_counts", + "led_pwm_val", ] FRAME_LOG_INTERVAL = 100 From 4233d29887e6a07c78070a798d55e370ea461be7 Mon Sep 17 00:00:00 2001 From: "paul.lebel" Date: Wed, 19 Mar 2025 21:03:15 +0300 Subject: [PATCH 10/12] added setup script --- .gitignore | 3 + OS_instructions/setup_promtail.sh | 140 ++++++++++++++++++++++++++++++ 2 files changed, 143 insertions(+) create mode 100755 OS_instructions/setup_promtail.sh diff --git a/.gitignore b/.gitignore index b6b225509..44d886161 100644 --- a/.gitignore +++ b/.gitignore @@ -126,3 +126,6 @@ lock.py # config ini files */configs/*.ini + +#logging config +/log_config diff --git a/OS_instructions/setup_promtail.sh b/OS_instructions/setup_promtail.sh new file mode 100755 index 000000000..990ba02bd --- /dev/null +++ b/OS_instructions/setup_promtail.sh @@ -0,0 +1,140 @@ +#!/bin/bash +# This script moves old log files to an archive folder, +# creates a Promtail configuration file, +# downloads and installs the promtail binary, +# and sets up promtail as a systemd service. +# +# Usage: +# ./setup_promtail.sh -p -n + +usage() { + echo "Usage: $0 -p -n " + exit 1 +} + +# Parse command line options +while getopts "p:n:" opt; do + case ${opt} in + p) + PASSWORD=${OPTARG} + ;; + n) + HOST=${OPTARG} + ;; + *) + usage + ;; + esac +done + +# Ensure both variables are provided +if [ -z "${PASSWORD}" ] || [ -z "${HOST}" ]; then + echo "Error: Both PASSWORD and HOST must be provided." + usage +fi + +# --- Step 1: Move old log files to archive --- +LOG_DIR="/media/pi/SamsungSSD/logs" +ARCHIVE_DIR="/media/pi/SamsungSSD/archive" + +if [ -d "$LOG_DIR" ]; then + echo "Creating archive directory and moving old log files from $LOG_DIR to $ARCHIVE_DIR..." + mkdir -p "$ARCHIVE_DIR" + mv "$LOG_DIR"/*.log "$ARCHIVE_DIR"/ 2>/dev/null +else + echo "Log directory $LOG_DIR does not exist. Skipping file archival." +fi + +# --- Step 2: Setup Promtail configuration --- +GRAFANA_DIR=/home/pi/Documents/ulc-malaria-scope/log_config +mkdir -p "$GRAFANA_DIR" + +CONFIG_FILE="$GRAFANA_DIR/promtail-config.yaml" +cat << 'EOF' > "$CONFIG_FILE" +server: + disable: true # Disables Promtail's internal HTTP server +positions: + filename: /home/pi/Documents/ulc-malaria-scope/log_config/positions.yaml # Stores file tracking state + sync_period: 10s +clients: + - url: https://api-grafana.sf.czbiohub.org/loki/push + basic_auth: + username: bioe + password: ${LOKI_PASSWORD} +scrape_configs: +- job_name: remoscope-logs + static_configs: + - targets: + - localhost + labels: + app: Remoscope + host: ${HOSTNAME} + __path__: /media/pi/SamsungSSD/logs/*.log # Watches all logs in this directory + pipeline_stages: + - match: + selector: '{app="Remoscope"}' + stages: + - multiline: + firstline: '^\\d{4}-\\d{2}-\\d{2}-\\d{6} .*' + max_wait_time: 5s + - regex: + expression: '^\\d{4}-\\d{2}-\\d{2}-\\d{6} - (?P\\w+) - .*' + - labels: + severity: +EOF + +echo "Promtail configuration file created at $CONFIG_FILE" + +# --- Step 3: Download and install Promtail --- +echo "Downloading promtail..." +wget https://github.com/grafana/loki/releases/download/v3.3.2/promtail-linux-arm.zip -O /tmp/promtail-linux-arm.zip + +echo "Unzipping promtail..." +unzip -o /tmp/promtail-linux-arm.zip -d /tmp/ + +echo "Making promtail executable and moving it to /usr/local/bin..." +chmod +x /tmp/promtail-linux-arm +sudo mv /tmp/promtail-linux-arm /usr/local/bin/promtail + +# --- Step 4: Create systemd service for Promtail using sed for environment variable substitution --- +echo "Creating systemd service file for promtail..." +sudo tee /etc/systemd/system/promtail.service > /dev/null <<'EOF' +[Unit] +Description=Promtail Service +After=network.target + +[Service] +Type=simple +ExecStart=/usr/local/bin/promtail --config.file=/home/pi/Documents/ulc-malaria-scope/log_config/promtail-config.yaml --config.expand-env=true +Restart=on-failure +User=pi +Environment="HOSTNAME=HOST_PLACEHOLDER" +Environment="LOKI_PASSWORD=PASSWORD_PLACEHOLDER" + +[Install] +WantedBy=multi-user.target +EOF + +echo "Updating systemd service file with provided HOST and PASSWORD..." +sudo sed -i "s/Environment=\"HOSTNAME=HOST_PLACEHOLDER\"/Environment=\"HOSTNAME=${HOST}\"/" /etc/systemd/system/promtail.service +sudo sed -i "s/Environment=\"LOKI_PASSWORD=PASSWORD_PLACEHOLDER\"/Environment=\"LOKI_PASSWORD=${PASSWORD}\"/" /etc/systemd/system/promtail.service + +echo "Adding LOKI_PASSWORD to as environment variable for interactive sessions..." +sudo sed -i '/^LOKI_PASSWORD=/d' /etc/environment +echo "LOKI_PASSWORD=${PASSWORD}" | sudo tee -a /etc/environment + +sed -i '/^export LOKI_PASSWORD=/d' ~/.bashrc +echo "export LOKI_PASSWORD=${PASSWORD}" >> ~/.bashrc +echo "source ~/.bashrc" + +echo "Adding permissions to log_config folder" +sudo chmod -R 777 /home/pi/Documents/ulc-malaria-scope/log_config + +echo "Reloading systemd daemon..." +sudo systemctl daemon-reload +echo "Enabling promtail service..." +sudo systemctl enable promtail.service +echo "Starting promtail service..." +sudo systemctl start promtail.service + +echo "Promtail setup complete." \ No newline at end of file From b5178807c46a35e7aeb2d7689cdc4520864fae8d Mon Sep 17 00:00:00 2001 From: "paul.lebel" Date: Thu, 20 Mar 2025 04:00:31 +0300 Subject: [PATCH 11/12] Had to remove filename label bc of high cardinality query issues in Loki, added experimentID to log to compensate. --- OS_instructions/setup_promtail.sh | 2 ++ ulc_mm_package/QtGUI/oracle.py | 24 +++++++++++++++++++++++- ulc_mm_package/logger.config | 2 +- 3 files changed, 26 insertions(+), 2 deletions(-) diff --git a/OS_instructions/setup_promtail.sh b/OS_instructions/setup_promtail.sh index 990ba02bd..19cfc32e6 100755 --- a/OS_instructions/setup_promtail.sh +++ b/OS_instructions/setup_promtail.sh @@ -71,6 +71,8 @@ scrape_configs: host: ${HOSTNAME} __path__: /media/pi/SamsungSSD/logs/*.log # Watches all logs in this directory pipeline_stages: + - labeldrop: + - filename - match: selector: '{app="Remoscope"}' stages: diff --git a/ulc_mm_package/QtGUI/oracle.py b/ulc_mm_package/QtGUI/oracle.py index 7f81f0846..e1ac19c9d 100644 --- a/ulc_mm_package/QtGUI/oracle.py +++ b/ulc_mm_package/QtGUI/oracle.py @@ -23,6 +23,7 @@ from transitions.core import MachineError from time import sleep from logging.config import fileConfig +from logging import LogRecord from datetime import datetime from pathlib import Path @@ -109,6 +110,16 @@ def closeEvent(self, event): event.accept() +class DateTimeFilter(logging.Filter): + def __init__(self, datetime_str): + super().__init__() + self.datetime_str = datetime_str + + def filter(self, record: LogRecord): + record.datetime_str = self.datetime_str + return True + + class Oracle(Machine): def __init__(self): self.shutoff_done = False @@ -137,6 +148,7 @@ def __init__(self): }, ) self.logger = logging.root + self._init_log_format() self.logger.info("STARTING ORACLE.") # Instantiate GUI windows @@ -159,6 +171,16 @@ def __init__(self): def _init_tcp(self): self.liveview_window.update_tcp("unavailable") + def _init_log_format(self): + old_factory = logging.getLogRecordFactory() + + def record_factory(*args, **kwargs): + record = old_factory(*args, **kwargs) + record.datetime_str = self.datetime_str # Inject dynamically + return record + + logging.setLogRecordFactory(record_factory) + def _check_lock(self): if path.isfile(LOCKFILE): message_result = self.display_message( @@ -802,7 +824,7 @@ def _start_new_log(self): disable_existing_loggers=False, ) self.logger = logging.root - + self.logger.addFilter(DateTimeFilter(self.datetime_str)) self.logger.info("CREATED LOG.") def shutoff(self): diff --git a/ulc_mm_package/logger.config b/ulc_mm_package/logger.config index eff745b73..60d42db29 100644 --- a/ulc_mm_package/logger.config +++ b/ulc_mm_package/logger.config @@ -30,7 +30,7 @@ args=() level=INFO [formatter_stringFormatter] -format=%(asctime)s - %(levelname)s - %(message)s [%(name)s] +format=%(asctime)s - %(levelname)s - %(datetime_str)s - %(message)s [%(name)s] datefmt=%Y-%m-%d-%H%M%S [formatter_printFormatter] From 4cef2d727ad1c074134b94a3252a4c11ac578ea8 Mon Sep 17 00:00:00 2001 From: i-jey Date: Thu, 27 Mar 2025 11:55:09 -0700 Subject: [PATCH 12/12] remove unused function --- .../image_processing/ewma_filtering_utils.py | 21 ------------------- 1 file changed, 21 deletions(-) diff --git a/ulc_mm_package/image_processing/ewma_filtering_utils.py b/ulc_mm_package/image_processing/ewma_filtering_utils.py index 2cd7a706c..31e3b4a10 100644 --- a/ulc_mm_package/image_processing/ewma_filtering_utils.py +++ b/ulc_mm_package/image_processing/ewma_filtering_utils.py @@ -109,27 +109,6 @@ def update_and_get_val(self, new_measurement: float) -> float: ) return self.prev_val - def update_and_get_val_arr(self, new_measurement: npt.NDArray) -> npt.NDArray: - """EWMA calculation step for arrays (uses an njit'd function under the hood, so is - slightly more performant than the regular `update_and_get_val()` call). However, - if using a single float value, this function is less performant than `update_and_get_val()` - - Parameters - ---------- - new_measurement: npt.NDArray - - Returns - ------- - npt.NDArray - The updated filter value. - """ - - self.prev_val = self._ewma_update_step_arr( - self.prev_val, new_measurement, self.alpha - ) - - return - @staticmethod def get_halflife_from_smoothing_factor(alpha: float) -> float: """Determine the half-life of the filter given its alpha value