Intoduce Global Logger for xfel-calibrate

- New setup_logging.py module to set the global logger handler
- Use new princess feature to run setup_logging.py before executing notebook
- copy setup_logging.py to the CAL_WORKING_DIRECTORY for more simplicity in accessing the file from anywhere (should be enough for reproducability?).
- LOGGING:
  - WARNINGs to warnings.logs
  - ERRORs to errors.logs
  - ALL console logs are not using any special format on purpose

bin/slurm_calibrate.sh

@@ -24,6 +24,11 @@ echo "cluster_cores: $cluster_cores"
 echo "job ID: ${SLURM_JOB_ID:-none}"
 
 export CAL_NOTEBOOK_NAME="$notebook"
+export CAL_WORKING_DIR="$(pwd)"
+
+# This is created by calibrate.py in CAL_WORKING_DIR
+setup_logger="setup-logging-nb.py"
+
 
 # make sure we use agg backend
 export MPLBACKEND=AGG
@@ -39,13 +44,11 @@ then
     sleep 15
 fi
 
-echo "Running notebook"
 if [ "$caltype" == "CORRECT" ]
 then
-  # calparrot stores and repeats calcat queries
-  ${python_path} -m calparrot -- ${python_path} -m princess ${nb_path} --save
+    ${python_path} -m calparrot -- ${python_path} -m princess ${nb_path} --save --run-before "$setup_logger"
 else
-  ${python_path} -m princess ${nb_path} --save
+    ${python_path} -m princess ${nb_path} --save --run-before "$setup_logger"
 fi
 
 # stop the cluster if requested

notebooks/test/test-error.ipynb

+{
+ "cells": [
+  {
+   "cell_type": "code",
+   "execution_count": 1,
+   "id": "98e38fec",
+   "metadata": {},
+   "outputs": [],
+   "source": [
+    "in_folder = \"./\" # input folder\n",
+    "out_folder = \"./\" # output folder"
+   ]
+  },
+  {
+   "cell_type": "code",
+   "execution_count": null,
+   "id": "7fbce574",
+   "metadata": {},
+   "outputs": [],
+   "source": [
+    "from logging import debug, error, info, warning"
+   ]
+  },
+  {
+   "cell_type": "markdown",
+   "id": "ba0663ca",
+   "metadata": {},
+   "source": [
+    "## INFO/DEBUG"
+   ]
+  },
+  {
+   "cell_type": "code",
+   "execution_count": null,
+   "id": "a3b5e455",
+   "metadata": {},
+   "outputs": [],
+   "source": [
+    "debug(\"(DEBUG)ing for some logs\")\n",
+    "info(\"Logging some (INFO)rmation\")"
+   ]
+  },
+  {
+   "cell_type": "markdown",
+   "id": "1bf72c57",
+   "metadata": {},
+   "source": [
+    "## WARNINGS"
+   ]
+  },
+  {
+   "cell_type": "code",
+   "execution_count": null,
+   "id": "c0d290a1",
+   "metadata": {},
+   "outputs": [],
+   "source": [
+    "from warnings import warn\n",
+    "if 1 < 2:\n",
+    "    warn('This inequality is true!')"
+   ]
+  },
+  {
+   "cell_type": "code",
+   "execution_count": null,
+   "id": "9b79ea47",
+   "metadata": {},
+   "outputs": [],
+   "source": [
+    "warning(\"This is a warning message using logging standard library.\")"
+   ]
+  },
+  {
+   "cell_type": "markdown",
+   "id": "2b22e2e0",
+   "metadata": {},
+   "source": [
+    "## ERRORS"
+   ]
+  },
+  {
+   "cell_type": "code",
+   "execution_count": null,
+   "id": "0f3bfeb7",
+   "metadata": {},
+   "outputs": [],
+   "source": [
+    "error(\"Logging some (ERROR) without failing the notebook\")"
+   ]
+  },
+  {
+   "cell_type": "code",
+   "execution_count": 2,
+   "id": "c3b87719",
+   "metadata": {},
+   "outputs": [
+    {
+     "ename": "ValueError",
+     "evalue": "FAIL",
+     "output_type": "error",
+     "traceback": [
+      "\u001b[0;31m---------------------------------------------------------------------------\u001b[0m",
+      "\u001b[0;31mValueError\u001b[0m                                Traceback (most recent call last)",
+      "Cell \u001b[0;32mIn[2], line 1\u001b[0m\n\u001b[0;32m----> 1\u001b[0m \u001b[38;5;28;01mraise\u001b[39;00m \u001b[38;5;167;01mValueError\u001b[39;00m(\u001b[38;5;124m'\u001b[39m\u001b[38;5;124mFAIL\u001b[39m\u001b[38;5;124m'\u001b[39m)\n",
+      "\u001b[0;31mValueError\u001b[0m: FAIL"
+     ]
+    }
+   ],
+   "source": [
+    "raise ValueError('FAIL')"
+   ]
+  }
+ ],
+ "metadata": {
+  "kernelspec": {
+   "display_name": ".venv",
+   "language": "python",
+   "name": "python3"
+  },
+  "language_info": {
+   "codemirror_mode": {
+    "name": "ipython",
+    "version": 3
+   },
+   "file_extension": ".py",
+   "mimetype": "text/x-python",
+   "name": "python",
+   "nbconvert_exporter": "python",
+   "pygments_lexer": "ipython3",
+   "version": "3.11.9"
+  }
+ },
+ "nbformat": 4,
+ "nbformat_minor": 5
+}

src/xfel_calibrate/calibrate.py

@@ -580,12 +580,10 @@ def make_par_table(parms):
 
     return textwrap.dedent(tmpl.render(p=col_type, lines=l_parms))
 
-
 def run(argv=None):
     """ Run a calibration task with parser arguments """
     if argv is None:
         argv = sys.argv
-
     args, nb_details = parse_argv_and_load_nb(argv)
 
     concurrency = nb_details.concurrency
@@ -675,6 +673,13 @@ def run(argv=None):
         cal_work_dir / "pycalib-run-nb.sh"
     )
 
+    # Copy the setup logger handler
+    shutil.copy2(
+        os.path.join(PKG_DIR, "setup_logging.py"),
+        cal_work_dir / "setup-logging-nb.py"
+    )
+
+
     if nb_details.user_venv:
         print("Using specified venv:", nb_details.user_venv)
         python_exe = str(nb_details.user_venv / 'bin' / 'python')

src/xfel_calibrate/notebooks.py

@@ -393,6 +393,22 @@ notebooks = {
                 "cluster cores": 1
             },
         },
+        "TEST-LOG-ERROR": {
+            "notebook": "notebooks/test/test-error.ipynb",
+            "concurrency": {
+                "parameter": None,
+                "default concurrency": None,
+                "cluster cores": 1,
+            },
+        },
+        "TEST-LOG-WARNING": {
+            "notebook": "notebooks/test/test-warning.ipynb",
+            "concurrency": {
+                "parameter": None,
+                "default concurrency": None,
+                "cluster cores": 1,
+            },
+        },
     },
     "TEST-RAISES-ERRORS": {
         "TEST-BAD-KEY": {

src/xfel_calibrate/settings.py

@@ -16,6 +16,9 @@ try_report_to_output = True
 # logo file for calibration report (located in cal_tools/cal_tools)
 logo_path = "xfel.pdf"
 
+# Logger handler
+setup_logger = "setup_loggeing.py"
+
 # the command to run this concurrently. It is prepended to the actual call
 sprof = os.environ.get("XFELCALSLURM", "exfel")  # TODO: https://git.xfel.eu/gitlab/calibration/planning/issues/3
 launcher_command = "sbatch -t 24:00:00 --requeue --output {temp_path}/slurm-%j.out --parsable"

src/xfel_calibrate/setup_logging.py

+import logging
+import sys
+import traceback
+import warnings
+import os
+
+
+class ContextFilter(logging.Filter):
+    def filter(self, record):
+        record.notebook = NOTEBOOK_NAME
+        record.directory = CURRENT_WORKING_DIR
+        return True
+
+
+# Define a custom log format
+formatter = logging.Formatter(
+    '%(asctime)s - %(levelname)s - %(filename)s:%(lineno)d - '
+    '[Notebook: %(notebook)s] - [Directory: %(directory)s] - %(message)s'
+)
+
+# Retrieve notebook name and current working directory from environment variables
+NOTEBOOK_NAME = os.getenv('CAL_NOTEBOOK_NAME', 'Unknown notebook')
+CURRENT_WORKING_DIR = os.getenv('CAL_WORKING_DIR', 'Unknown directory')
+
+# Create a logger
+logger = logging.getLogger()
+logger.setLevel(logging.DEBUG)  # Capture all levels
+
+# Create file handlers
+error_handler = logging.FileHandler('errors.log')
+error_handler.setLevel(logging.ERROR)
+error_handler.setFormatter(formatter)
+
+warning_handler = logging.FileHandler('warnings.log')
+warning_handler.setLevel(logging.WARNING)
+# Avoid errors being logged in warnings.log
+warning_handler.addFilter(lambda record: record.levelno < logging.ERROR)
+warning_handler.setFormatter(formatter)
+
+# Create console handler for info and debug
+# No formatter used for console handler on purpose.
+# console is slurm.out & the notebook output cells.
+console_handler = logging.StreamHandler()
+console_handler.setLevel(logging.DEBUG)
+
+# Add the custom filter to handlers
+context_filter = ContextFilter()
+error_handler.addFilter(context_filter)
+warning_handler.addFilter(context_filter)
+console_handler.addFilter(context_filter)
+
+# Add handlers to logger
+logger.addHandler(error_handler)
+logger.addHandler(warning_handler)
+logger.addHandler(console_handler)
+
+handling_error = False
+
+
+def safe_handle_error(exc_type, exc_value, exc_traceback):
+    global handling_error
+    if handling_error:  # Avoid infinite loop of errors.
+        sys.stderr.write("Recursive error detected!\n")
+        traceback.print_exception(exc_type, exc_value, exc_traceback, file=sys.stderr)
+        return
+
+    handling_error = True
+    try:
+        # Log the error with the notebook name and additional metadata
+        logger.error(
+            "An error occurred. Exception type: %s, Message: %s",
+            exc_type.__name__, str(exc_value),
+            extra={'notebook': NOTEBOOK_NAME, 'directory': CURRENT_WORKING_DIR},
+            exc_info=(exc_type, exc_value, exc_traceback)
+        )
+
+    except Exception as log_error:
+        sys.stderr.write(f"Logging failed: {log_error}\n")
+        traceback.print_exception(exc_type, exc_value, exc_traceback, file=sys.stderr)
+    finally:
+        handling_error = False
+
+
+def handle_warning(message, category, filename, lineno, file=None, line=None):
+    try:
+        # Log the warning with the notebook name and additional metadata
+        logger.warning(
+            "Warning occurred: %s, File: %s, Line: %d",
+            message, filename, lineno,
+            extra={'notebook': NOTEBOOK_NAME, 'directory': CURRENT_WORKING_DIR}
+        )
+    except Exception as log_error:
+        sys.stderr.write(f"Logging failed: {log_error}\n")
+
+
+# Replace the handlers with our custom ones
+sys.excepthook = safe_handle_error
+warnings.showwarning = handle_warning
+
+# Override IPython's exception handling
+import IPython
+IPython.core.interactiveshell.InteractiveShell.showtraceback = lambda self, *args, **kwargs: safe_handle_error(*sys.exc_info())
\ No newline at end of file