From 273b23f65a419422bbd097b689f3ccfe778160d8 Mon Sep 17 00:00:00 2001
From: ahmedk <karim.ahmed@xfel.eu>
Date: Fri, 6 Sep 2024 09:49:56 +0200
Subject: [PATCH] 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 | 11 ++-
notebooks/test/test-error.ipynb | 135 ++++++++++++++++++++++++++++
src/xfel_calibrate/calibrate.py | 9 +-
src/xfel_calibrate/notebooks.py | 16 ++++
src/xfel_calibrate/settings.py | 3 +
src/xfel_calibrate/setup_logging.py | 102 +++++++++++++++++++++
6 files changed, 270 insertions(+), 6 deletions(-)
create mode 100644 notebooks/test/test-error.ipynb
create mode 100644 src/xfel_calibrate/setup_logging.py
diff --git a/bin/slurm_calibrate.sh b/bin/slurm_calibrate.sh
index a600fa7ea..04fadbc94 100755
--- a/bin/slurm_calibrate.sh
+++ b/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
diff --git a/notebooks/test/test-error.ipynb b/notebooks/test/test-error.ipynb
new file mode 100644
index 000000000..4ad97550f
--- /dev/null
+++ b/notebooks/test/test-error.ipynb
@@ -0,0 +1,135 @@
+{
+ "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
+}
diff --git a/src/xfel_calibrate/calibrate.py b/src/xfel_calibrate/calibrate.py
index 90dd3c4b5..3537443c1 100755
--- a/src/xfel_calibrate/calibrate.py
+++ b/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')
diff --git a/src/xfel_calibrate/notebooks.py b/src/xfel_calibrate/notebooks.py
index a2aa8f02e..013358f79 100644
--- a/src/xfel_calibrate/notebooks.py
+++ b/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": {
diff --git a/src/xfel_calibrate/settings.py b/src/xfel_calibrate/settings.py
index 15067c0a6..eb9f096a5 100644
--- a/src/xfel_calibrate/settings.py
+++ b/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"
diff --git a/src/xfel_calibrate/setup_logging.py b/src/xfel_calibrate/setup_logging.py
new file mode 100644
index 000000000..5526ef72d
--- /dev/null
+++ b/src/xfel_calibrate/setup_logging.py
@@ -0,0 +1,102 @@
+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
--
GitLab