Improved logging

.gitignore

@@ -126,3 +126,6 @@ lock.py
 
 # config ini files
 */configs/*.ini
+
+#logging config
+/log_config

OS_instructions/setup_promtail.sh

@@ -0,0 +1,142 @@
+#!/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 <LOKI_PASSWORD> -n <HOSTNAME>
+
+usage() {
+    echo "Usage: $0 -p <LOKI_PASSWORD> -n <HOSTNAME>"
+    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:
+  - labeldrop:
+    - filename
+  - 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<severity>\\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."

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)

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(
@@ -346,7 +368,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(
@@ -656,7 +678,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,
@@ -667,6 +689,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:
@@ -769,6 +794,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 +806,27 @@ 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()
+        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
+        self.logger.addFilter(DateTimeFilter(self.datetime_str))
+        self.logger.info("CREATED LOG.")
+
     def shutoff(self):
         self.logger.info("Starting oracle shut off.")
 
@@ -856,7 +903,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

ulc_mm_package/QtGUI/scope_op.py

@@ -64,6 +64,8 @@
     VERBOSE,
     ACQUISITION_PERIOD,
     LIVEVIEW_PERIOD,
+    FRAME_LOG_INTERVAL,
+    PERIODIC_METADATA_KEYS,
 )
 
 
@@ -248,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")
 
@@ -338,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()
 
@@ -424,7 +429,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),
@@ -557,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. "
+            f"Processed {self.frame_count} frames. "
+            f"Final class counts: {class_counts_str}"
+        )
         self.finishing_experiment.emit(100)
 
     def _start_intermission(self, msg):
@@ -578,7 +593,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 +981,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
@@ -981,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()
@@ -993,7 +1008,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 +1035,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
@@ -1048,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)