diff --git a/README.md b/README.md index 6ad766d..39e5813 100644 --- a/README.md +++ b/README.md @@ -45,4 +45,32 @@ PyRPOD utilizies scientific libraries such as NumPy, SciPy, Matplotlib, and SymP python -m pytest -m verification # verification tests only python -m pytest -m rpod # a specific subsystem (mdao, mission, plume, rpod) python -m pytest tests/rpod # or just point pytest at a directory/file directly - ``` \ No newline at end of file + ``` + +## Logging + +PyRPOD ships a formal, opt-in operational logging system built entirely on the +Python standard library. **Importing PyRPOD has no logging side effects** — no +files, directories, handlers, or root-logger changes. Applications turn logging +on explicitly: + +```python +from pyrpod.logging_utils import configure_logging + +session = configure_logging(case_dir) +try: + # ... run the PyRPOD workflow, e.g. study.jfh_plume_strikes() ... + session.finalize("successful") +finally: + session.close() +``` + +Runtime logs are written to `/results/logs/_.log` +(a new file per run). Behavior is configured per case via an optional +`/logging.ini`, with environment variables (`PYRPOD_LOG_LEVEL`, +`PYRPOD_LOG_FORMAT`) and explicit API arguments taking precedence. + +See [docs/logging.md](docs/logging.md) for the full architecture, the +`logging.ini` schema ([example](docs/logging.ini.example)), configuration +precedence, log-level guidance, input checksums, configuration snapshots, +performance/memory caveats, and serial-fallback behavior. \ No newline at end of file diff --git a/case/rpod/1d_approach/logging.ini b/case/rpod/1d_approach/logging.ini new file mode 100644 index 0000000..be5dd32 --- /dev/null +++ b/case/rpod/1d_approach/logging.ini @@ -0,0 +1,18 @@ +# PyRPOD logging configuration for the 1d_approach RPOD plume-strike case. +# +# Read by pyrpod.logging_utils.configure_logging(case_dir). See docs/logging.md +# and docs/logging.ini.example for the full schema. +# +# Demonstrates a coarser progress cadence: an INFO progress record is emitted +# every 2 firings (and always for the final firing). + +[logging] +enabled = true +console = true +file = true +level = INFO +progress_every_n_firings = 2 +log_array_stats = true +log_performance = true +snapshot_config = true +checksum_inputs = true diff --git a/case/rpod/1d_approach/run.py b/case/rpod/1d_approach/run.py new file mode 100644 index 0000000..2e2ab84 --- /dev/null +++ b/case/rpod/1d_approach/run.py @@ -0,0 +1,66 @@ +"""Demonstration driver for the 1d_approach RPOD plume-strike case. + +Mirrors tests/rpod/rpod_integration_test_02.py (minus the assertions) and wraps +the workflow in PyRPOD's operational logging. This case models a notional VV +firing its adverse thrusters to slow down along a 1D approach. Run it with: + + python case/rpod/1d_approach/run.py + +A runtime log is written to case/rpod/1d_approach/results/logs/. Logging +behavior (here, a progress record every 2 firings) is set by logging.ini. +""" +import os +import sys + +_HERE = os.path.dirname(os.path.abspath(__file__)) +_REPO_ROOT = os.path.abspath(os.path.join(_HERE, "..", "..", "..")) +if _REPO_ROOT not in sys.path: + sys.path.insert(0, _REPO_ROOT) + +from pyrpod.logging_utils import configure_logging +from pyrpod.rpod import JetFiringHistory, PlumeStrikeEstimationStudy +from pyrpod.vehicle import LogisticsModule, TargetVehicle +from pyrpod.mission import MissionEnvironment + +CASE_DIR = _HERE.replace(os.sep, "/") + "/" + + +def main(): + session = configure_logging(CASE_DIR) + try: + # 1. Set up assets. + jfh = JetFiringHistory.JetFiringHistory(CASE_DIR) + + tv = TargetVehicle.TargetVehicle(CASE_DIR) + tv.set_stl() + + lm = LogisticsModule.LogisticsModule(CASE_DIR) + # Define LM mass distribution properties. + lm.set_inertial_props(14000, 11, 2) # mass (kg), height (m), radius (m) + lm.set_thruster_config() + lm.set_thruster_metrics() + lm.assign_thruster_groups() + + me = MissionEnvironment.MissionEnvironment(CASE_DIR) + study = PlumeStrikeEstimationStudy.PlumeStrikeEstimationStudy(me) + study.study_init(jfh, tv, lm) + + # Uses the pre-generated 1D-approach JFH shipped with the case. + jfh.read_jfh() + + # 2. Execute the RPOD plume-strike analysis. + study.graph_jfh() + study.jfh_plume_strikes() + + session.finalize("successful") + except Exception: + session.finalize("failed") + raise + finally: + session.close() + + print("Run complete. Runtime log:", session.log_path) + + +if __name__ == "__main__": + main() diff --git a/case/rpod/base_case/logging.ini b/case/rpod/base_case/logging.ini new file mode 100644 index 0000000..325f5fc --- /dev/null +++ b/case/rpod/base_case/logging.ini @@ -0,0 +1,19 @@ +# PyRPOD logging configuration for the base_case RPOD plume-strike case. +# +# Read by pyrpod.logging_utils.configure_logging(case_dir) when this case is +# run (e.g. via run.py). See docs/logging.md and docs/logging.ini.example for +# the full schema and configuration precedence. +# +# base_case is the reference demonstration: default INFO logging to both the +# console and a runtime log file, with a progress record for every firing. + +[logging] +enabled = true +console = true +file = true +level = INFO +progress_every_n_firings = 1 +log_array_stats = true +log_performance = true +snapshot_config = true +checksum_inputs = true diff --git a/case/rpod/base_case/run.py b/case/rpod/base_case/run.py new file mode 100644 index 0000000..fb5d145 --- /dev/null +++ b/case/rpod/base_case/run.py @@ -0,0 +1,65 @@ +"""Demonstration driver for the base_case RPOD plume-strike case. + +Mirrors tests/rpod/rpod_integration_test_01.py (minus the assertions) and wraps +the workflow in PyRPOD's operational logging. Run it directly from anywhere: + + python case/rpod/base_case/run.py + +Logging is configured from this case's logging.ini. A fresh runtime log is +written to: + + case/rpod/base_case/results/logs/base_case_.log + +along with a config.ini snapshot and SHA-256 checksums of every input asset. +""" +import os +import sys + +_HERE = os.path.dirname(os.path.abspath(__file__)) +_REPO_ROOT = os.path.abspath(os.path.join(_HERE, "..", "..", "..")) +if _REPO_ROOT not in sys.path: + sys.path.insert(0, _REPO_ROOT) + +from pyrpod.logging_utils import configure_logging +from pyrpod.rpod import JetFiringHistory, PlumeStrikeEstimationStudy +from pyrpod.vehicle import LogisticsModule, TargetVehicle +from pyrpod.mission import MissionEnvironment + +# PyRPOD's case_dir convention is a directory path with a trailing separator. +CASE_DIR = _HERE.replace(os.sep, "/") + "/" + + +def main(): + session = configure_logging(CASE_DIR) + try: + # 1. Set up assets. + jfh = JetFiringHistory.JetFiringHistory(CASE_DIR) + + tv = TargetVehicle.TargetVehicle(CASE_DIR) + tv.set_stl() + + lm = LogisticsModule.LogisticsModule(CASE_DIR) + lm.set_thruster_config() + + me = MissionEnvironment.MissionEnvironment(CASE_DIR) + study = PlumeStrikeEstimationStudy.PlumeStrikeEstimationStudy(me) + study.study_init(jfh, tv, lm) + + jfh.read_jfh() + + # 2. Execute the RPOD plume-strike analysis. + study.graph_jfh() + study.jfh_plume_strikes() + + session.finalize("successful") + except Exception: + session.finalize("failed") + raise + finally: + session.close() + + print("Run complete. Runtime log:", session.log_path) + + +if __name__ == "__main__": + main() diff --git a/case/rpod/hollow_cube/logging.ini b/case/rpod/hollow_cube/logging.ini new file mode 100644 index 0000000..da75464 --- /dev/null +++ b/case/rpod/hollow_cube/logging.ini @@ -0,0 +1,19 @@ +# PyRPOD logging configuration for the hollow_cube RPOD plume-strike case. +# +# Read by pyrpod.logging_utils.configure_logging(case_dir). See docs/logging.md +# and docs/logging.ini.example for the full schema. +# +# Demonstrates independent handler toggles: the console handler is disabled, so +# output goes only to the runtime log file under results/logs/. Useful for +# unattended/batch runs. + +[logging] +enabled = true +console = false +file = true +level = DEBUG +progress_every_n_firings = 1 +log_array_stats = true +log_performance = true +snapshot_config = true +checksum_inputs = true diff --git a/case/rpod/hollow_cube/run.py b/case/rpod/hollow_cube/run.py new file mode 100644 index 0000000..26b8173 --- /dev/null +++ b/case/rpod/hollow_cube/run.py @@ -0,0 +1,60 @@ +"""Demonstration driver for the hollow_cube RPOD plume-strike case. + +Mirrors tests/rpod/rpod_integration_test_04.py (minus the assertions) and wraps +the workflow in PyRPOD's operational logging. Run it with: + + python case/rpod/hollow_cube/run.py + +This case's logging.ini disables console output, so records go only to the +runtime log file in case/rpod/hollow_cube/results/logs/. +""" +import os +import sys + +_HERE = os.path.dirname(os.path.abspath(__file__)) +_REPO_ROOT = os.path.abspath(os.path.join(_HERE, "..", "..", "..")) +if _REPO_ROOT not in sys.path: + sys.path.insert(0, _REPO_ROOT) + +from pyrpod.logging_utils import configure_logging +from pyrpod.rpod import JetFiringHistory, PlumeStrikeEstimationStudy +from pyrpod.vehicle import TargetVehicle, VisitingVehicle +from pyrpod.mission import MissionEnvironment + +CASE_DIR = _HERE.replace(os.sep, "/") + "/" + + +def main(): + session = configure_logging(CASE_DIR) + try: + # 1. Set up assets. + jfh = JetFiringHistory.JetFiringHistory(CASE_DIR) + jfh.read_jfh() + + tv = TargetVehicle.TargetVehicle(CASE_DIR) + tv.set_stl() + + vv = VisitingVehicle.VisitingVehicle(CASE_DIR) + vv.set_stl() + vv.set_thruster_config() + + me = MissionEnvironment.MissionEnvironment(CASE_DIR) + study = PlumeStrikeEstimationStudy.PlumeStrikeEstimationStudy(me) + study.study_init(jfh, tv, vv) + + # 2. Execute the RPOD plume-strike analysis. + study.graph_jfh() + study.jfh_plume_strikes() + + session.finalize("successful") + except Exception: + session.finalize("failed") + raise + finally: + session.close() + + print("Run complete. Runtime log:", session.log_path) + + +if __name__ == "__main__": + main() diff --git a/case/rpod/koz/logging.ini b/case/rpod/koz/logging.ini new file mode 100644 index 0000000..f1202a3 --- /dev/null +++ b/case/rpod/koz/logging.ini @@ -0,0 +1,19 @@ +# PyRPOD logging configuration for the koz (keep-out-zone) RPOD case. +# +# Read by pyrpod.logging_utils.configure_logging(case_dir). See docs/logging.md +# and docs/logging.ini.example for the full schema. +# +# Demonstrates verbose diagnostics: level = DEBUG adds candidate/resolved asset +# paths, NumPy array summaries, and per-firing detail on top of the normal INFO +# workflow milestones. Handy when investigating a case. + +[logging] +enabled = true +console = true +file = true +level = DEBUG +progress_every_n_firings = 1 +log_array_stats = true +log_performance = true +snapshot_config = true +checksum_inputs = true diff --git a/case/rpod/koz/run.py b/case/rpod/koz/run.py new file mode 100644 index 0000000..f8042c8 --- /dev/null +++ b/case/rpod/koz/run.py @@ -0,0 +1,61 @@ +"""Demonstration driver for the koz (keep-out-zone) RPOD plume-strike case. + +Mirrors tests/rpod/rpod_integration_test_03.py (minus the assertions) and wraps +the workflow in PyRPOD's operational logging. Run it with: + + python case/rpod/koz/run.py + +This case's logging.ini sets level = DEBUG, so the runtime log in +case/rpod/koz/results/logs/ also includes candidate asset paths, array +summaries, and per-firing diagnostics. +""" +import os +import sys + +_HERE = os.path.dirname(os.path.abspath(__file__)) +_REPO_ROOT = os.path.abspath(os.path.join(_HERE, "..", "..", "..")) +if _REPO_ROOT not in sys.path: + sys.path.insert(0, _REPO_ROOT) + +from pyrpod.logging_utils import configure_logging +from pyrpod.rpod import JetFiringHistory, PlumeStrikeEstimationStudy +from pyrpod.vehicle import LogisticsModule, TargetVehicle +from pyrpod.mission import MissionEnvironment + +CASE_DIR = _HERE.replace(os.sep, "/") + "/" + + +def main(): + session = configure_logging(CASE_DIR) + try: + # 1. Set up assets. + jfh = JetFiringHistory.JetFiringHistory(CASE_DIR) + + tv = TargetVehicle.TargetVehicle(CASE_DIR) + tv.set_stl() + + lm = LogisticsModule.LogisticsModule(CASE_DIR) + lm.set_thruster_config() + + me = MissionEnvironment.MissionEnvironment(CASE_DIR) + study = PlumeStrikeEstimationStudy.PlumeStrikeEstimationStudy(me) + study.study_init(jfh, tv, lm) + + jfh.read_jfh() + + # 2. Execute the RPOD plume-strike analysis. + study.graph_jfh() + study.jfh_plume_strikes() + + session.finalize("successful") + except Exception: + session.finalize("failed") + raise + finally: + session.close() + + print("Run complete. Runtime log:", session.log_path) + + +if __name__ == "__main__": + main() diff --git a/case/rpod/multi_thrusters_square/logging.ini b/case/rpod/multi_thrusters_square/logging.ini new file mode 100644 index 0000000..ccdb2f8 --- /dev/null +++ b/case/rpod/multi_thrusters_square/logging.ini @@ -0,0 +1,20 @@ +# PyRPOD logging configuration for the multi_thrusters_square RPOD case. +# +# Read by pyrpod.logging_utils.configure_logging(case_dir). See docs/logging.md +# and docs/logging.ini.example for the full schema. +# +# This case enables plume kinetics (Simplified + Maxwellian), so the per-firing +# INFO progress records include the physical maxima (max_pressure_pa, +# max_shear_pa, max_heat_flux_w_m2, max_heat_flux_load_j_m2) in addition to +# geometry. Performance logging reports wall/CPU time and peak Python memory. + +[logging] +enabled = true +console = true +file = true +level = INFO +progress_every_n_firings = 1 +log_array_stats = true +log_performance = true +snapshot_config = true +checksum_inputs = true diff --git a/case/rpod/multi_thrusters_square/run.py b/case/rpod/multi_thrusters_square/run.py new file mode 100644 index 0000000..0fe7845 --- /dev/null +++ b/case/rpod/multi_thrusters_square/run.py @@ -0,0 +1,63 @@ +"""Demonstration driver for the multi_thrusters_square RPOD plume-strike case. + +Mirrors tests/rpod/rpod_integration_test_05.py (minus the assertions) and wraps +the workflow in PyRPOD's operational logging. This case enables plume kinetics +(Simplified gas kinetics + Maxwellian wall model), so the log captures the +per-firing and overall physical maxima. Run it with: + + python case/rpod/multi_thrusters_square/run.py + +A runtime log is written to +case/rpod/multi_thrusters_square/results/logs/. +""" +import os +import sys + +_HERE = os.path.dirname(os.path.abspath(__file__)) +_REPO_ROOT = os.path.abspath(os.path.join(_HERE, "..", "..", "..")) +if _REPO_ROOT not in sys.path: + sys.path.insert(0, _REPO_ROOT) + +from pyrpod.logging_utils import configure_logging +from pyrpod.rpod import JetFiringHistory, PlumeStrikeEstimationStudy +from pyrpod.vehicle import TargetVehicle, VisitingVehicle +from pyrpod.mission import MissionEnvironment + +CASE_DIR = _HERE.replace(os.sep, "/") + "/" + + +def main(): + session = configure_logging(CASE_DIR) + try: + # 1. Set up assets. + jfh = JetFiringHistory.JetFiringHistory(CASE_DIR) + jfh.read_jfh() + + tv = TargetVehicle.TargetVehicle(CASE_DIR) + tv.set_stl() + + vv = VisitingVehicle.VisitingVehicle(CASE_DIR) + vv.set_stl() + vv.set_thruster_config() + vv.set_thruster_metrics() # required: kinetics is enabled for this case + + me = MissionEnvironment.MissionEnvironment(CASE_DIR) + study = PlumeStrikeEstimationStudy.PlumeStrikeEstimationStudy(me) + study.study_init(jfh, tv, vv) + + # 2. Execute the RPOD plume-strike analysis (with kinetics). + study.graph_jfh() + study.jfh_plume_strikes() + + session.finalize("successful") + except Exception: + session.finalize("failed") + raise + finally: + session.close() + + print("Run complete. Runtime log:", session.log_path) + + +if __name__ == "__main__": + main() diff --git a/case/rpod/stl_to_vtk/logging.ini b/case/rpod/stl_to_vtk/logging.ini new file mode 100644 index 0000000..55bdaa9 --- /dev/null +++ b/case/rpod/stl_to_vtk/logging.ini @@ -0,0 +1,18 @@ +# PyRPOD logging configuration for the stl_to_vtk utility case. +# +# Read by pyrpod.logging_utils.configure_logging(case_dir). See docs/logging.md +# and docs/logging.ini.example for the full schema. +# +# This case does not run a plume-strike sweep; it demonstrates the asset-load +# provenance/checksum logging and directory-creation logging around a simple +# STL -> VTK conversion. progress_every_n_firings is unused here. + +[logging] +enabled = true +console = true +file = true +level = INFO +log_array_stats = true +log_performance = true +snapshot_config = true +checksum_inputs = true diff --git a/case/rpod/stl_to_vtk/run.py b/case/rpod/stl_to_vtk/run.py new file mode 100644 index 0000000..a850521 --- /dev/null +++ b/case/rpod/stl_to_vtk/run.py @@ -0,0 +1,48 @@ +"""Demonstration driver for the stl_to_vtk utility case. + +Mirrors tests/rpod/rpod_unit_test_01.py (minus the assertions) and wraps the +STL -> VTK conversion in PyRPOD's operational logging. Unlike the other cases +this one does not run a plume-strike sweep; it showcases the asset-load +provenance/checksum records and directory-creation logging. Run it with: + + python case/rpod/stl_to_vtk/run.py + +A runtime log is written to case/rpod/stl_to_vtk/results/logs/. +""" +import os +import sys + +_HERE = os.path.dirname(os.path.abspath(__file__)) +_REPO_ROOT = os.path.abspath(os.path.join(_HERE, "..", "..", "..")) +if _REPO_ROOT not in sys.path: + sys.path.insert(0, _REPO_ROOT) + +from pyrpod.logging_utils import configure_logging +from pyrpod.vehicle import Vehicle +from pyrpod.mission import MissionEnvironment + +CASE_DIR = _HERE.replace(os.sep, "/") + "/" + + +def main(): + session = configure_logging(CASE_DIR) + try: + # The vehicle STL (cylinder.stl) resolves from the shared data/ tree, + # which the asset log records as source=shared-data. + MissionEnvironment.MissionEnvironment(CASE_DIR) + v = Vehicle.Vehicle(CASE_DIR) + v.set_stl() # read STL surface data (logged as an asset load) + v.convert_stl_to_vtk() # convert to VTK and save under results/ + + session.finalize("successful") + except Exception: + session.finalize("failed") + raise + finally: + session.close() + + print("Run complete. Runtime log:", session.log_path) + + +if __name__ == "__main__": + main() diff --git a/docs/logging.ini.example b/docs/logging.ini.example new file mode 100644 index 0000000..e9e8a6e --- /dev/null +++ b/docs/logging.ini.example @@ -0,0 +1,56 @@ +# Example PyRPOD case logging configuration. +# +# Copy this file into a case directory as: +# +# /logging.ini +# +# When present, its [logging] section is read by +# pyrpod.logging_utils.configure_logging(case_dir). When absent, the built-in +# defaults below are used and PyRPOD logs that it fell back to defaults. +# +# Precedence (highest wins): +# 1. Explicit configure_logging(...) keyword arguments +# 2. Environment variables (PYRPOD_LOG_LEVEL, PYRPOD_LOG_FORMAT) +# 3. This logging.ini +# 4. Built-in defaults +# +# The values shown here are also the built-in defaults. + +[logging] +# Master switch. When false, PyRPOD installs no console/file handlers and +# opens no runtime log file (module loggers still exist but emit nowhere by +# default). +enabled = true + +# Console (stderr) logging can be toggled independently of file logging. +console = true + +# File logging (a fresh runtime log per run under results/logs/) can be +# toggled independently of console logging. +file = true + +# Logging level applied to both the console and file handlers. +# One of: DEBUG, INFO, WARNING, ERROR. +level = INFO + +# Emit an INFO progress record every N completed firings (and always for the +# final firing). Minimum 1. +progress_every_n_firings = 1 + +# Log compact NumPy array summaries (shape/dtype/min/max/mean/nonzero/nan/...) +# at DEBUG. Full arrays are never logged. +log_array_stats = true + +# Measure and log wall time, CPU time, and tracemalloc peak Python memory. +log_performance = true + +# Copy the case config.ini (and this logging.ini) into results/logs/ and log +# their SHA-256 checksums for reproducibility. +snapshot_config = true + +# Compute and log SHA-256 checksums of loaded input assets. +checksum_inputs = true + +# Optional: override the record format. The default is: +# %(asctime)s [%(levelname)s] %(name)s: %(message)s +# format = %(asctime)s [%(levelname)s] %(name)s: %(message)s diff --git a/docs/logging.md b/docs/logging.md new file mode 100644 index 0000000..1c962e1 --- /dev/null +++ b/docs/logging.md @@ -0,0 +1,246 @@ +# PyRPOD Operational Logging + +PyRPOD has a formal operational logging system built entirely on the Python +standard library (`logging`, `hashlib`, `tracemalloc`, `subprocess`, ...). It +records what a run did — which case and assets were used, their checksums, +workflow phases, per-firing progress, performance, and the final status — so a +plume-strike run is fully traceable and reproducible. + +Operational logs are **not** scientific result files. Full numerical fields +(per-face strike/pressure/shear/heat-flux arrays, JFH records, meshes) stay in +the existing VTK/STL/CSV/JFH outputs. The runtime log contains only summaries, +paths, dimensions, input checksums, and performance data. + +## PyRPOD does not configure logging on import + +Importing `pyrpod` (or any submodule) has **no logging side effects**: no log +files, no directories, no handlers, no root-logger changes, no output. Modules +obtain a logger the standard way and never configure handlers: + +```python +import logging +logger = logging.getLogger(__name__) +``` + +An application turns logging on explicitly at its boundary. + +## Minimal usage + +```python +from pyrpod.logging_utils import configure_logging + +case_dir = "case/rpod/base_case/" +session = configure_logging(case_dir) +try: + # ... build the study and run the PyRPOD workflow ... + # e.g. study.jfh_plume_strikes() + session.finalize("successful") +finally: + session.close() +``` + +`configure_logging` attaches PyRPOD-owned handlers to the **`pyrpod` package +logger** (never the root logger), opens a fresh runtime log, writes the startup +metadata block, and snapshots the case configuration. `session.close()` detaches +and closes only the handlers PyRPOD installed; handlers belonging to an +embedding application are never inspected or modified. Calling +`configure_logging` again replaces PyRPOD's own handlers, so messages and +handlers are never duplicated. + +### Runnable per-case demos + +Several `case/rpod/` cases ship a ready-to-run driver and a `logging.ini` that +each highlight a different capability. They mirror the corresponding +`tests/rpod/` cases minus the assertions: + +```bash +python case/rpod/base_case/run.py # default INFO, console + file +python case/rpod/1d_approach/run.py # progress_every_n_firings = 2 +python case/rpod/koz/run.py # level = DEBUG (paths, array summaries) +python case/rpod/hollow_cube/run.py # console = false (file only) +python case/rpod/multi_thrusters_square/run.py # kinetics on: per-firing pressure/shear/heat-flux +python case/rpod/stl_to_vtk/run.py # asset + directory logging around STL -> VTK +``` + +Each writes its runtime log to `/results/logs/_.log`. + +## Configuration file + +Each case may optionally contain `/logging.ini`. When absent, the +built-in defaults are used and PyRPOD logs that it fell back to defaults. See +[`docs/logging.ini.example`](logging.ini.example) for a fully commented file. + +```ini +[logging] +enabled = true +console = true +file = true +level = INFO +progress_every_n_firings = 1 +log_array_stats = true +log_performance = true +snapshot_config = true +checksum_inputs = true +# format = %(asctime)s [%(levelname)s] %(name)s: %(message)s +``` + +- **`console`** and **`file`** are toggled independently. +- Console and file handlers share one level. +- No log rotation; retention is user-managed. +- Plain-text logging only (no JSON/JSONL). + +## Configuration precedence + +Highest wins: + +1. Explicit `configure_logging(...)` keyword arguments +2. Environment variables — `PYRPOD_LOG_LEVEL`, `PYRPOD_LOG_FORMAT` +3. `/logging.ini` +4. Built-in defaults + +```bash +# Raise verbosity for one run without editing any file: +PYRPOD_LOG_LEVEL=DEBUG python your_driver.py + +# Override the record format: +PYRPOD_LOG_FORMAT="%(levelname)s %(name)s %(message)s" python your_driver.py +``` + +```python +# Explicit arguments beat everything, e.g. silence the console for a batch job: +session = configure_logging(case_dir, console=False, level="INFO") +``` + +## Runtime-log location and naming + +Runtime logs are written under: + +``` +/results/logs/_.log +``` + +`` is the normalized final path component of `case_dir`; the +timestamp is `YYYYMMDD_HHMMSS`. A **new file is created for every configured +run**, e.g. `base_case_20260725_143102.log`. There is one primary runtime log +per run — not one per firing or artifact. (`.log` is reserved for these runtime +logs; expected-result fixtures use `.txt`/`.dat`.) + +## Record format and levels + +``` +timestamp [LEVEL] module.name: message +2026-07-25 14:31:02 [INFO] pyrpod.rpod.PlumeStrikeEstimationStudy: Firing 17/95 completed: struck_faces=246 ... +``` + +| Level | Use | +|-------|-----| +| `DEBUG` | Candidate/resolved paths, array shapes and summary stats, per-thruster transforms, existing-directory messages, per-artifact paths, DataFrame summaries. | +| `INFO` | Run started, config loaded, assets loaded, JFH loaded, geometry/thruster config loaded, phase start/complete, progress updates, per-firing maxima, summary artifacts, run completed, final status. | +| `WARNING` | Optional config absent, optional visualization failed, parallel→serial fallback, questionable-but-usable input, nonessential write failed (with traceback). | +| `ERROR` | Failed requested operations, invalid required inputs (fail fast after logging), unrecoverable failures. | + +`CRITICAL` is not used. + +## Startup metadata + +`configure_logging` writes a compact startup block once: absolute case path, +start time, Python version, CPU count, git dirty-working-tree status (via a safe +`git status --porcelain`; `unknown` if git/repo is unavailable), effective log +level, console/file enabled flags, the active runtime-log path, and whether +`logging.ini` or built-in defaults were used. The plume-strike run start (next +section) adds execution mode, worker count, and model parameters. + +## Configuration snapshots + +When `snapshot_config` is enabled, the case `config.ini` (and `logging.ini` if +present) are copied verbatim into `results/logs/` as +`__config.ini` / `..._logging.ini`, and their SHA-256 +checksums are logged. Snapshots are for reproducibility and never replace the +original case files. + +## Input-asset tracking + +Each loaded input asset (target/visiting-vehicle STL, thruster/plume STL, JFH, +TCF, TDF, CCF, ...) is logged at INFO with its category, filename, absolute +resolved path, source (`case-local` vs `shared-data`), size in bytes, and +streaming SHA-256 (`checksum_inputs` toggles the hash). Checksums are cached per +run so an unchanged asset is not rehashed. Candidate paths and case-local vs +shared fallback decisions are logged at DEBUG (see +`pyrpod.util.io.fs.resolve_asset_path`). + +## Plume-strike workflow logging + +`PlumeStrikeEstimationStudy.jfh_plume_strikes()`: + +- **Fail-fast validation** of every required input (config keys, readable + non-empty target mesh / JFH / thruster config, valid thruster references; and, + when kinetics is enabled, TDF / surface_temp / sigma / thruster metrics). A + missing required input is logged at ERROR and raises — never a silent `None`. +- **Run started (INFO):** firings, target faces, kinetics on/off, plume model, + radius, wedge angle, serial/parallel mode, worker count, progress interval. +- **Progress (INFO):** every `progress_every_n_firings` firings and the final + firing — index, JFH id, sim time, active thrusters, worker PID, struck-face + count, and (when kinetics is on) max pressure/shear/heat-flux/heat-flux-load, + plus per-firing wall time and tracked-array memory. Kinetics-specific maxima + are omitted (not faked) when kinetics is disabled. +- **DEBUG:** array summaries and per-artifact paths. +- **Completion (INFO):** firings completed, total struck-face events, unique + struck faces, overall maxima, wall/CPU time, average wall time per firing, + peak Python-tracked memory, tracked array memory, artifact count, final + execution mode, whether fallback occurred, and final run status. + +`tqdm` progress bars have been replaced by this logging-based progress. + +## Performance and memory + +Standard library only: `time.perf_counter()` (wall), `time.process_time()` +(CPU), `tracemalloc` (Python-managed current/peak allocations), and NumPy +`.nbytes` for tracked arrays. `tracemalloc` **does not** capture all native +memory allocated by NumPy/compiled libraries, so peak memory is reported as +`python_peak_memory_mb` (not total process memory) and known major arrays are +summed separately as `tracked_array_memory_mb`. To avoid slowing unit tests, +`tracemalloc` is engaged only for an explicitly configured run +(`configure_logging` called) with `log_performance = true`. + +Unit-bearing field names are used for physical quantities, e.g. `pressure_pa`, +`shear_pa`, `heat_flux_w_m2`, `heat_flux_load_j_m2`, `wall_time_s`, +`cpu_time_s`, `python_peak_memory_mb`, `tracked_array_memory_mb`. + +## Serial / parallel and fallback + +Parallel execution uses parent-process logging: workers return only +non-numerical metadata (PID, per-firing wall/CPU time); the parent emits the +records. Numerical accumulation order is unchanged — cumulative arrays and VTK +output are produced serially in JFH order by the parent. Serial and parallel +modes emit the same major event categories. + +If process-based execution fails, the full traceback is logged at WARNING +(`exc_info=True`), serial fallback runs, and the final status becomes +`successful_with_warning` when the serial calculation succeeds (or `failed` if +it does not). + +## Final run status + +One of `successful`, `successful_with_warning`, `partial`, or `failed`. Call +`session.finalize(status)` to record it along with warning/error counts, +runtime, and the runtime-log path. `session.close()` releases the handlers and +should run from a `finally` block so finalization happens even on exceptions +(without suppressing the original exception). + +## Helper API summary + +From `pyrpod.logging_utils`: + +- `configure_logging(case_dir, **overrides) -> LoggingSession` +- `LoggingSession.finalize(status, summary=None)`, `LoggingSession.close()` +- `get_active_session()`, `get_settings()`, `performance_logging_enabled()` +- `log_asset(category, filename, resolved_path, case_dir, logger=None)` +- `summarize_array(name, array)`, `log_array_summary(logger, name, array, level=DEBUG)` +- `sha256_file(path)`, `git_dirty_status(path)` + +## Future extensions (not implemented) + +`run_summary.json`, output-artifact checksums, JSONL structured logs, log +rotation, true total-process memory via an optional external dependency, a +multiprocessing logging queue, and generated run IDs are documented as possible +future work and are intentionally out of scope for this version. diff --git a/pyproject.toml b/pyproject.toml index a20d6eb..6fa69a7 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -34,6 +34,7 @@ markers = [ "unit: unit-level test cases", "integration: integration test cases", "verification: verification/validation test cases", + "logging: logging subsystem tests", "mdao: mdao subsystem tests", "mission: mission subsystem tests", "plume: plume subsystem tests", diff --git a/pyrpod/README_new.md b/pyrpod/README_new.md index 3df1fef..6fa2d1b 100644 --- a/pyrpod/README_new.md +++ b/pyrpod/README_new.md @@ -56,22 +56,35 @@ Run tests using the `config_test.py` or dedicated test cases provided for each m ## Logging -We use Python's logging across modules. - -- Get a logger: - - from pyrpod.logging_utils import get_logger - - logger = get_logger("pyrpod..") -- Default level: INFO. Override via env var (PowerShell): - - $env:PYRPOD_LOG_LEVEL = "DEBUG" -- Customize format via env var: - - $env:PYRPOD_LOG_FORMAT = "%(asctime)s [%(levelname)s] %(name)s: %(message)s" +PyRPOD has a centralized, opt-in operational logging system. **Importing PyRPOD +has no logging side effects** — modules never configure handlers on import. + +- In a module, get a logger the standard way: + - `import logging` + - `logger = logging.getLogger(__name__)` +- At the application boundary, turn logging on explicitly: + - `from pyrpod.logging_utils import configure_logging` + - `session = configure_logging(case_dir)` +- Override level/format via env vars (PowerShell): + - `$env:PYRPOD_LOG_LEVEL = "DEBUG"` + - `$env:PYRPOD_LOG_FORMAT = "%(asctime)s [%(levelname)s] %(name)s: %(message)s"` + +Runtime logs are written to `/results/logs/_.log`. +See [`docs/logging.md`](../docs/logging.md) for the full architecture, the +`logging.ini` schema, configuration precedence, input checksums, configuration +snapshots, performance/memory caveats, and serial-fallback behavior. Example: ```python -from pyrpod.logging_utils import get_logger -logger = get_logger("pyrpod.example") -logger.info("Hello from PyRPOD") +from pyrpod.logging_utils import configure_logging + +session = configure_logging(case_dir) +try: + # ... run the PyRPOD workflow, e.g. study.jfh_plume_strikes() ... + session.finalize("successful") +finally: + session.close() ``` ## Adding New Modules diff --git a/pyrpod/logging_utils.py b/pyrpod/logging_utils.py index 12a68d1..aa0864c 100644 --- a/pyrpod/logging_utils.py +++ b/pyrpod/logging_utils.py @@ -1,29 +1,656 @@ +"""pyrpod.logging_utils — centralized, opt-in operational logging for PyRPOD. + +PyRPOD is primarily a reusable library, so importing ``pyrpod`` (or this +module) has **no logging side effects**: it does not create files or +directories, does not add handlers, does not touch the root logger, and does +not emit output. Production modules obtain a logger with the standard idiom:: + + import logging + logger = logging.getLogger(__name__) + +and never configure handlers themselves. + +An application turns logging on explicitly at its boundary:: + + from pyrpod.logging_utils import configure_logging + + session = configure_logging(case_dir) + try: + ... # run the PyRPOD workflow + session.finalize("successful") + finally: + session.close() + +``configure_logging`` attaches PyRPOD-owned handlers to the ``pyrpod`` package +logger (never the root logger), so records from ``pyrpod.*`` module loggers +propagate up to those handlers. Handlers belonging to an embedding application +are never inspected or modified; calling ``configure_logging`` again closes and +replaces only the handlers PyRPOD itself installed, so messages are never +duplicated. + +Configuration precedence (highest first): + +1. Explicit Python API arguments to ``configure_logging`` +2. Environment variables (``PYRPOD_LOG_LEVEL``, ``PYRPOD_LOG_FORMAT``) +3. ``/logging.ini`` ``[logging]`` section +4. Built-in defaults (see :class:`LoggingSettings`) +""" +from __future__ import annotations + +import configparser +import hashlib import logging import os +import platform +import re +import shutil +import subprocess +import time +from dataclasses import dataclass, field +from datetime import datetime +from typing import Any, Dict, Optional + +import numpy as np + +# --------------------------------------------------------------------------- # +# Constants +# --------------------------------------------------------------------------- # +PACKAGE_LOGGER_NAME = "pyrpod" +DEFAULT_LOG_FORMAT = "%(asctime)s [%(levelname)s] %(name)s: %(message)s" +DEFAULT_DATE_FORMAT = "%Y-%m-%d %H:%M:%S" + +_OWNED_HANDLER_ATTR = "_pyrpod_owned" + +# The repo-level shared data directory, mirroring pyrpod.util.io.fs so asset +# provenance ("case-local" vs "shared") can be reported consistently. +_REPO_ROOT = os.path.dirname(os.path.dirname(os.path.abspath(__file__))) +_SHARED_DATA_DIR = os.path.join(_REPO_ROOT, "data") + +# The single active PyRPOD logging session, if any. Kept module-global so +# workflow code can read run-scoped settings (progress interval, array-stats +# toggle, ...) without threading a session object through every call site. +_ACTIVE_SESSION: Optional["LoggingSession"] = None + + +# --------------------------------------------------------------------------- # +# Settings +# --------------------------------------------------------------------------- # +@dataclass +class LoggingSettings: + """Resolved logging configuration for a run. + + These are the built-in defaults; ``logging.ini``, environment variables, + and explicit API arguments override them per the documented precedence. + """ + + enabled: bool = True + console: bool = True + file: bool = True + level: str = "INFO" + log_format: str = DEFAULT_LOG_FORMAT + progress_every_n_firings: int = 1 + log_array_stats: bool = True + log_performance: bool = True + snapshot_config: bool = True + checksum_inputs: bool = True + + +_INI_BOOL_KEYS = ( + "enabled", + "console", + "file", + "log_array_stats", + "log_performance", + "snapshot_config", + "checksum_inputs", +) + + +def _read_logging_ini(case_dir: str): + """Return (``[logging]`` section proxy or None, ini path).""" + ini_path = os.path.join(case_dir, "logging.ini") + if not os.path.isfile(ini_path): + return None, ini_path + parser = configparser.ConfigParser() + try: + parser.read(ini_path) + except configparser.Error: + return None, ini_path + if not parser.has_section("logging"): + return None, ini_path + return parser["logging"], ini_path + + +def _apply_ini(settings: LoggingSettings, section) -> None: + for key in _INI_BOOL_KEYS: + if key in section: + try: + setattr(settings, key, section.getboolean(key)) + except ValueError: + pass + if "level" in section: + settings.level = section.get("level") + if "format" in section: + settings.log_format = section.get("format") + if "progress_every_n_firings" in section: + try: + settings.progress_every_n_firings = section.getint( + "progress_every_n_firings" + ) + except ValueError: + pass + + +def _resolve_settings(case_dir: str, overrides: Dict[str, Any]): + """Resolve :class:`LoggingSettings` following the documented precedence.""" + settings = LoggingSettings() + + # 3. logging.ini + ini_section, ini_path = _read_logging_ini(case_dir) + used_ini = ini_section is not None + if ini_section is not None: + _apply_ini(settings, ini_section) + + # 2. environment variables (only level and format are supported) + env_level = os.environ.get("PYRPOD_LOG_LEVEL") + if env_level: + settings.level = env_level + env_format = os.environ.get("PYRPOD_LOG_FORMAT") + if env_format: + settings.log_format = env_format + + # 1. explicit API arguments + for key, value in overrides.items(): + if value is not None: + setattr(settings, key, value) + + settings.level = str(settings.level).upper() + if settings.progress_every_n_firings < 1: + settings.progress_every_n_firings = 1 + return settings, used_ini, ini_path + + +# --------------------------------------------------------------------------- # +# Handler ownership helpers +# --------------------------------------------------------------------------- # +class _LevelCounter(logging.Handler): + """Owned handler that tallies WARNING/ERROR records for the run summary.""" + + def __init__(self) -> None: + super().__init__(level=logging.WARNING) + self.warning_count = 0 + self.error_count = 0 + + def emit(self, record: logging.LogRecord) -> None: # noqa: D401 + if record.levelno >= logging.ERROR: + self.error_count += 1 + elif record.levelno >= logging.WARNING: + self.warning_count += 1 + + +def _mark_owned(handler: logging.Handler) -> logging.Handler: + setattr(handler, _OWNED_HANDLER_ATTR, True) + return handler + + +def _remove_owned_handlers(logger: logging.Logger) -> None: + """Detach and close only handlers PyRPOD installed; leave app handlers.""" + for handler in list(logger.handlers): + if getattr(handler, _OWNED_HANDLER_ATTR, False): + logger.removeHandler(handler) + try: + handler.close() + except Exception: + pass + + +def _level_to_int(level) -> int: + if isinstance(level, int): + return level + return getattr(logging, str(level).upper(), logging.INFO) + + +def _safe_case_name(case_dir: str) -> str: + name = os.path.basename(os.path.normpath(case_dir)) or "case" + return re.sub(r"[^A-Za-z0-9._-]+", "_", name) + + +def _unique_log_path(log_dir: str, case_name: str, timestamp: str) -> str: + base = os.path.join(log_dir, f"{case_name}_{timestamp}.log") + if not os.path.exists(base): + return base + # Two runs in the same wall-clock second: keep the convention but stay + # unique by appending microseconds, then the PID as a last resort. + for _ in range(1000): + micro = datetime.now().strftime("%f") + candidate = os.path.join(log_dir, f"{case_name}_{timestamp}_{micro}.log") + if not os.path.exists(candidate): + return candidate + return os.path.join(log_dir, f"{case_name}_{timestamp}_{os.getpid()}.log") + + +# --------------------------------------------------------------------------- # +# Session +# --------------------------------------------------------------------------- # +@dataclass +class LoggingSession: + """Handle for one configured PyRPOD logging run. + + Returned by :func:`configure_logging`. Carries the resolved settings, the + active runtime-log path, and a run-scoped input-checksum cache. Use + :meth:`finalize` to record the final status and :meth:`close` to release + the PyRPOD-owned handlers. + """ + + case_dir: str + case_name: str + settings: LoggingSettings + log_path: Optional[str] + used_ini: bool + ini_path: str + timestamp: str + logger: logging.Logger + _counter: _LevelCounter + _hash_cache: Dict[str, str] = field(default_factory=dict) + _closed: bool = False + _start_wall: float = field(default_factory=time.perf_counter) + _start_dt: datetime = field(default_factory=datetime.now) + + @property + def warning_count(self) -> int: + return self._counter.warning_count + + @property + def error_count(self) -> int: + return self._counter.error_count + def finalize(self, status: str = "successful", *, + summary: Optional[Dict[str, Any]] = None) -> None: + """Log the final run status and an optional summary once. -def get_logger(name: str = "pyrpod", level: str | None = None) -> logging.Logger: + ``status`` is one of ``successful``, ``successful_with_warning``, + ``partial``, or ``failed``. This does not close handlers; call + :meth:`close` (typically from a ``finally`` block) for that. + """ + elapsed = time.perf_counter() - self._start_wall + fields = { + "status": status, + "warnings": self.warning_count, + "errors": self.error_count, + "runtime_s": round(elapsed, 3), + "runtime_log": self.log_path, + } + if summary: + fields.update(summary) + self.logger.info("run finalized: %s", _format_fields(fields)) + + def close(self) -> None: + """Detach and close PyRPOD-owned handlers installed for this session.""" + global _ACTIVE_SESSION + if self._closed: + return + _remove_owned_handlers(self.logger) + self._closed = True + if _ACTIVE_SESSION is self: + _ACTIVE_SESSION = None + + +# --------------------------------------------------------------------------- # +# Public configuration API +# --------------------------------------------------------------------------- # +def configure_logging(case_dir: str, *, + console: Optional[bool] = None, + file: Optional[bool] = None, + level: Optional[str] = None, + log_format: Optional[str] = None, + enabled: Optional[bool] = None, + progress_every_n_firings: Optional[int] = None, + log_array_stats: Optional[bool] = None, + log_performance: Optional[bool] = None, + snapshot_config: Optional[bool] = None, + checksum_inputs: Optional[bool] = None, + write_startup: bool = True) -> LoggingSession: + """Configure PyRPOD logging for a case and return a :class:`LoggingSession`. + + Resolves the absolute case directory, reads an optional + ``/logging.ini``, applies environment-variable and explicit-API + overrides, installs PyRPOD-owned console/file handlers on the ``pyrpod`` + package logger, opens a fresh timestamped runtime log under + ``/results/logs/``, writes the startup-metadata block, and (when + enabled) snapshots the case configuration files. + + Calling this repeatedly is safe: previously installed PyRPOD handlers are + closed and replaced, never duplicated, and handlers owned by an embedding + application are left untouched. """ - Return a configured logger for the PyRPOD project. + global _ACTIVE_SESSION + + abs_case_dir = os.path.abspath(case_dir) + overrides = { + "console": console, + "file": file, + "level": level, + "log_format": log_format, + "enabled": enabled, + "progress_every_n_firings": progress_every_n_firings, + "log_array_stats": log_array_stats, + "log_performance": log_performance, + "snapshot_config": snapshot_config, + "checksum_inputs": checksum_inputs, + } + settings, used_ini, ini_path = _resolve_settings(abs_case_dir, overrides) + + pkg_logger = logging.getLogger(PACKAGE_LOGGER_NAME) + + # Replace only PyRPOD-owned handlers so repeated configuration never + # duplicates output and never disturbs the embedding application. + _remove_owned_handlers(pkg_logger) + + case_name = _safe_case_name(abs_case_dir) + timestamp = datetime.now().strftime("%Y%m%d_%H%M%S") + level_value = _level_to_int(settings.level) + + counter = _mark_owned(_LevelCounter()) + pkg_logger.addHandler(counter) + + log_path: Optional[str] = None + if settings.enabled: + pkg_logger.setLevel(level_value) + formatter = logging.Formatter(settings.log_format, + datefmt=DEFAULT_DATE_FORMAT) + if settings.console: + console_handler = _mark_owned(logging.StreamHandler()) + console_handler.setLevel(level_value) + console_handler.setFormatter(formatter) + pkg_logger.addHandler(console_handler) + if settings.file: + log_dir = os.path.join(abs_case_dir, "results", "logs") + os.makedirs(log_dir, exist_ok=True) + log_path = _unique_log_path(log_dir, case_name, timestamp) + file_handler = _mark_owned( + logging.FileHandler(log_path, encoding="utf-8")) + file_handler.setLevel(level_value) + file_handler.setFormatter(formatter) + pkg_logger.addHandler(file_handler) + + session = LoggingSession( + case_dir=abs_case_dir, + case_name=case_name, + settings=settings, + log_path=log_path, + used_ini=used_ini, + ini_path=ini_path, + timestamp=timestamp, + logger=pkg_logger, + _counter=counter, + ) + _ACTIVE_SESSION = session + + if settings.enabled and write_startup: + _write_startup_metadata(session) + if settings.snapshot_config: + _write_config_snapshots(session) + + return session - - Uses a StreamHandler with a concise formatter - - Respects PYRPOD_LOG_LEVEL and PYRPOD_LOG_FORMAT env vars - - Avoids duplicate handlers on repeated calls + +def get_active_session() -> Optional[LoggingSession]: + """Return the currently active :class:`LoggingSession`, or None.""" + return _ACTIVE_SESSION + + +def get_settings() -> LoggingSettings: + """Return the active run's settings, or built-in defaults if unconfigured.""" + if _ACTIVE_SESSION is not None: + return _ACTIVE_SESSION.settings + return LoggingSettings() + + +def performance_logging_enabled() -> bool: + """True only when a session is active and performance logging is on. + + tracemalloc has real overhead, so it is engaged only for an explicitly + configured run — never merely because a workflow function was called. """ - logger = logging.getLogger(name) - if not logger.handlers: - handler = logging.StreamHandler() - fmt = os.environ.get( - "PYRPOD_LOG_FORMAT", - "%(asctime)s [%(levelname)s] %(name)s: %(message)s", + return _ACTIVE_SESSION is not None and _ACTIVE_SESSION.settings.log_performance + + +# --------------------------------------------------------------------------- # +# Startup metadata and configuration snapshots +# --------------------------------------------------------------------------- # +def git_dirty_status(path: str) -> str: + """Return 'clean', 'dirty', or 'unknown' for the repo containing ``path``. + + Uses a short, safe standard-library subprocess call. Any failure (git + missing, not a repository, timeout) yields 'unknown' rather than raising — + logging must never take down a simulation. + """ + work_dir = path if os.path.isdir(path) else os.path.dirname(path) or "." + try: + result = subprocess.run( + ["git", "-C", work_dir, "status", "--porcelain"], + capture_output=True, text=True, timeout=5, ) - handler.setFormatter(logging.Formatter(fmt)) - logger.addHandler(handler) + except (OSError, subprocess.SubprocessError): + return "unknown" + if result.returncode != 0: + return "unknown" + return "dirty" if result.stdout.strip() else "clean" + + +def _write_startup_metadata(session: LoggingSession) -> None: + logger = session.logger + settings = session.settings + logger.info("=== PyRPOD run start ===") + fields = { + "case_path": session.case_dir, + "start_time": session._start_dt.strftime("%Y-%m-%d %H:%M:%S"), + "python": platform.python_version(), + "cpu_count": os.cpu_count(), + "git_dirty": git_dirty_status(session.case_dir), + "log_level": settings.level, + "console_logging": "on" if settings.console else "off", + "file_logging": "on" if settings.file else "off", + "runtime_log": session.log_path, + "logging_config": "logging.ini" if session.used_ini else "built-in defaults", + } + logger.info("startup: %s", _format_fields(fields)) + if not session.used_ini: + logger.info("No logging.ini found in case; using built-in default " + "logging configuration.") + - level_name = (level or os.environ.get("PYRPOD_LOG_LEVEL", "INFO")).upper() - logger.setLevel(getattr(logging, level_name, logging.INFO)) +def _write_config_snapshots(session: LoggingSession) -> None: + """Copy case config files into the log dir and log their SHA-256 sums.""" + logger = session.logger + if session.log_path: + log_dir = os.path.dirname(session.log_path) + else: + log_dir = os.path.join(session.case_dir, "results", "logs") + try: + os.makedirs(log_dir, exist_ok=True) + except OSError as exc: + logger.warning("Could not create log dir for config snapshots: %s", + exc, exc_info=True) + return + + prefix = f"{session.case_name}_{session.timestamp}" + + config_src = os.path.join(session.case_dir, "config.ini") + if os.path.isfile(config_src): + try: + dst = os.path.join(log_dir, f"{prefix}_config.ini") + shutil.copyfile(config_src, dst) + logger.info("config snapshot: src=%s snapshot=%s sha256=%s", + config_src, dst, sha256_file(dst)) + except OSError as exc: + logger.warning("Failed to snapshot config.ini: %s", exc, + exc_info=True) + else: + logger.warning("No config.ini found at %s; snapshot skipped.", + config_src) + + if session.used_ini and os.path.isfile(session.ini_path): + try: + dst = os.path.join(log_dir, f"{prefix}_logging.ini") + shutil.copyfile(session.ini_path, dst) + logger.info("logging.ini snapshot: src=%s snapshot=%s sha256=%s", + session.ini_path, dst, sha256_file(dst)) + except OSError as exc: + logger.warning("Failed to snapshot logging.ini: %s", exc, + exc_info=True) + else: + logger.info("No logging.ini present; built-in defaults used " + "(no logging.ini snapshot).") + + +# --------------------------------------------------------------------------- # +# Input-asset tracking +# --------------------------------------------------------------------------- # +def sha256_file(path: str, chunk_size: int = 65536) -> str: + """Streaming SHA-256 so large assets are not read fully into memory.""" + digest = hashlib.sha256() + with open(path, "rb") as handle: + for chunk in iter(lambda: handle.read(chunk_size), b""): + digest.update(chunk) + return digest.hexdigest() + + +def _asset_source(abs_path: str, case_dir: str) -> str: + abs_case = os.path.abspath(case_dir) + try: + if os.path.commonpath([abs_path, abs_case]) == abs_case: + return "case-local" + except ValueError: + pass + try: + if os.path.commonpath([abs_path, _SHARED_DATA_DIR]) == _SHARED_DATA_DIR: + return "shared-data" + except ValueError: + pass + return "external" + + +def _cached_checksum(session: Optional[LoggingSession], abs_path: str) -> Optional[str]: + if not os.path.isfile(abs_path): + return None + if session is not None: + cache = session._hash_cache + if abs_path in cache: + return cache[abs_path] + digest = sha256_file(abs_path) + cache[abs_path] = digest + return digest + return sha256_file(abs_path) + + +def log_asset(category: str, filename: str, resolved_path: str, case_dir: str, + *, logger: Optional[logging.Logger] = None) -> None: + """Record a loaded input asset at INFO with provenance and checksum. + + Logs the asset category, filename, absolute resolved path, whether it came + from the case-local directory or the shared repository data, the file size + in bytes, and (unless disabled via ``checksum_inputs``) its SHA-256. The + checksum is cached per run so an unchanged asset is not rehashed. + """ + logger = logger or logging.getLogger(PACKAGE_LOGGER_NAME) + abs_path = os.path.abspath(resolved_path) + source = _asset_source(abs_path, case_dir) + try: + size = os.path.getsize(abs_path) + except OSError: + size = -1 + + digest = None + if get_settings().checksum_inputs: + digest = _cached_checksum(get_active_session(), abs_path) + + logger.info( + "asset loaded: %s", + _format_fields({ + "category": category, + "file": filename, + "path": abs_path, + "source": source, + "size_bytes": size, + "sha256": digest if digest is not None else "n/a", + }), + ) + + +# --------------------------------------------------------------------------- # +# Array summaries +# --------------------------------------------------------------------------- # +def summarize_array(name: str, array: Any) -> str: + """Return a compact one-line summary of a NumPy-like array. + + Reports name, shape, dtype, min/max/mean, nonzero/zero/NaN counts, and + memory in bytes. Handles empty, non-numeric, integer, boolean, NaN-bearing, + and non-array inputs without raising — a summary must never break a run. + Full array contents are never logged. + """ + try: + arr = np.asarray(array) + except Exception: + return _format_fields({"name": name, + "note": f"unsummarizable {type(array).__name__}"}) + + parts: Dict[str, Any] = { + "name": name, + "shape": tuple(arr.shape), + "dtype": str(arr.dtype), + "nbytes": int(arr.nbytes), + } + if arr.size == 0: + parts["empty"] = True + return _format_fields(parts) + + is_numeric = np.issubdtype(arr.dtype, np.number) + is_bool = np.issubdtype(arr.dtype, np.bool_) + if not (is_numeric or is_bool): + parts["numeric"] = False + return _format_fields(parts) + + try: + numeric = arr if is_numeric else arr.astype(np.int64) + if np.issubdtype(numeric.dtype, np.floating): + nan_count = int(np.isnan(numeric).sum()) + finite = numeric[np.isfinite(numeric)] + else: + nan_count = 0 + finite = numeric.ravel() + if finite.size: + parts["min"] = f"{float(finite.min()):.6g}" + parts["max"] = f"{float(finite.max()):.6g}" + parts["mean"] = f"{float(finite.mean()):.6g}" + else: + parts["min"] = parts["max"] = parts["mean"] = "nan" + nonzero = int(np.count_nonzero(arr)) + parts["nonzero"] = nonzero + parts["zero"] = int(arr.size - nonzero) + parts["nan"] = nan_count + except Exception as exc: # pragma: no cover - defensive + parts["note"] = f"summary error: {exc}" + return _format_fields(parts) + + +def log_array_summary(logger: logging.Logger, name: str, array: Any, + level: int = logging.DEBUG) -> None: + """Log :func:`summarize_array` output, honoring the array-stats toggle. + + Skips the (cheap but non-zero) summary work entirely when the level is not + enabled or ``log_array_stats`` is off. + """ + if not get_settings().log_array_stats: + return + if not logger.isEnabledFor(level): + return + logger.log(level, "array: %s", summarize_array(name, array)) - # Prevent messages from bubbling to the root logger if user configured it - logger.propagate = False - return logger +# --------------------------------------------------------------------------- # +# Small formatting helper +# --------------------------------------------------------------------------- # +def _format_fields(fields: Dict[str, Any]) -> str: + """Render an ordered mapping as ``key=value`` pairs for concise records.""" + return " ".join(f"{key}={value}" for key, value in fields.items()) diff --git a/pyrpod/mdao/TradeStudy.py b/pyrpod/mdao/TradeStudy.py index baf92bb..662d222 100644 --- a/pyrpod/mdao/TradeStudy.py +++ b/pyrpod/mdao/TradeStudy.py @@ -1,13 +1,19 @@ import os import csv +import time +import logging import numpy as np import pandas as pd import matplotlib.pyplot as plt from pyrpod.rpod import JetFiringHistory, PlumeStrikeEstimationStudy from pyrpod.mdao import SweepConfig +from pyrpod.util.io.fs import ensure_dir import configparser +logger = logging.getLogger(__name__) + + class TradeStudy(): def __init__(self, case_dir): self.case_dir = case_dir @@ -92,7 +98,9 @@ def graph_mission_report(self, report_results): first_column = report_results.columns[0] # Convert DataFrame columns to NumPy arrays for indexing x_values = report_results[first_column].to_numpy() - print(report_results) + # Do not log full DataFrames at INFO; a compact DEBUG summary suffices. + logger.debug("Mission report DataFrame: shape=%s columns=%s", + report_results.shape, list(report_results.columns)) # Plot each parameter against the first parameter for column in report_results.columns[1:8]: y_values = report_results[column].to_numpy() @@ -155,20 +163,26 @@ def run_axial_overshoot_sweep(self, sweep_vars, lm, tv): axial_overshoot = sweep_vars['axial_overshoot'] self.max_v0 = np.max(axial_overshoot) + logger.info("Trade study initialized: sweep_type=axial_overshoot " + "case_dir=%s n_configurations=%d", self.case_dir, + len(axial_overshoot)) + study_start = time.perf_counter() + # Link elements for RPOD analysis. self.init_trade_study(lm, tv) # Create results directory if necessary. results_dir = self.case_dir + 'results' - if not os.path.isdir(results_dir): - os.mkdir(results_dir) + ensure_dir(results_dir) # Loop through over shoot velocities to test. for i, v_o in enumerate(axial_overshoot): - # print(i, v_o) - # # Set unique case identifier within trade study. self.rpod.set_case_key(i, 0) + config_start = time.perf_counter() + logger.info("Trade-study config %d/%d: case_key=%s " + "axial_overshoot_m_s=%s", i + 1, len(axial_overshoot), + self.rpod.get_case_key(), v_o) # Create JFH for a given velocity. self.rpod.print_jfh_1d_approach_n_fire( @@ -180,16 +194,22 @@ def run_axial_overshoot_sweep(self, sweep_vars, lm, tv): ) # Reset JFH according to specific case. - self.init_trade_study_case() + self.init_trade_study_case() self.rpod.graph_jfh(trade_study= True) self.rpod.jfh_plume_strikes(trade_study = True) self.print_mission_report() - self.interpret_mission_report() - + logger.info("Trade-study config %d/%d completed: case_key=%s " + "config_time_s=%.3f", i + 1, len(axial_overshoot), + self.rpod.get_case_key(), + time.perf_counter() - config_start) + report_path = self.case_dir + 'results/MissionReport.csv' + logger.info("Trade study completed: sweep_type=axial_overshoot " + "configurations=%d mission_report=%s total_time_s=%.3f " + "status=successful", len(axial_overshoot), report_path, + time.perf_counter() - study_start) + self.interpret_mission_report() - # self.rpod.jfh_plume_strikes(trade_study = True) - def run_surface_cant_sweep(self, sweep_vars, lm, tv): """ """ @@ -206,8 +226,7 @@ def run_surface_cant_sweep(self, sweep_vars, lm, tv): # Create results directory if necessary. results_dir = self.case_dir + 'results' - if not os.path.isdir(results_dir): - os.mkdir(results_dir) + ensure_dir(results_dir) # Loop through over shoot velocities to test. for i, cant in enumerate(surface_cant_angles): @@ -255,8 +274,7 @@ def run_multi_var_sweep(self, sweep_vars, lm, tv): # Create results directory if necessary. results_dir = self.case_dir + 'results' - if not os.path.isdir(results_dir): - os.mkdir(results_dir) + ensure_dir(results_dir) # Loop through over shoot velocities to test. for i, v_o in enumerate(axial_overshoot): diff --git a/pyrpod/mission/fuel_management.py b/pyrpod/mission/fuel_management.py index 0b1fca0..e59fc18 100644 --- a/pyrpod/mission/fuel_management.py +++ b/pyrpod/mission/fuel_management.py @@ -1,10 +1,11 @@ +import logging + from pyrpod.mission.SubModule import SubModule import numpy as np import pandas as pd -from pyrpod.logging_utils import get_logger from pyrpod.util.io.fs import resolve_asset_path -logger = get_logger(__name__) +logger = logging.getLogger(__name__) class FuelManager(SubModule): # def __init__(self, isp, mass): diff --git a/pyrpod/mission/orbital_transfer.py b/pyrpod/mission/orbital_transfer.py index 325e512..782160c 100644 --- a/pyrpod/mission/orbital_transfer.py +++ b/pyrpod/mission/orbital_transfer.py @@ -1,8 +1,8 @@ from pyrpod.orbital import HohmannTransfer from astropy import units as u -from pyrpod.logging_utils import get_logger +import logging -logger = get_logger("pyrpod.mission.orbital_transfer") +logger = logging.getLogger(__name__) class OrbitalTransferEngine: def __init__(self): diff --git a/pyrpod/mission/post_processing.py b/pyrpod/mission/post_processing.py index 7a26b40..6e037ca 100644 --- a/pyrpod/mission/post_processing.py +++ b/pyrpod/mission/post_processing.py @@ -1,8 +1,8 @@ import numpy as np import matplotlib.pyplot as plt -from pyrpod.logging_utils import get_logger +import logging -logger = get_logger(__name__) +logger = logging.getLogger(__name__) class PostProcessor: diff --git a/pyrpod/plume/PlumeStrikeCalculator.py b/pyrpod/plume/PlumeStrikeCalculator.py index 4ac9463..5ecbef2 100644 --- a/pyrpod/plume/PlumeStrikeCalculator.py +++ b/pyrpod/plume/PlumeStrikeCalculator.py @@ -32,8 +32,10 @@ """ from __future__ import annotations +import os +import time from concurrent.futures import ProcessPoolExecutor -from typing import Any, Dict, List, Optional, Sequence +from typing import Any, Dict, List, Optional, Sequence, Tuple import numpy as np from pyrpod.plume.RarefiedPlumeGasKinetics import ( @@ -409,9 +411,14 @@ def _parallel_worker_init( def _parallel_worker_compute(task) -> Any: """Compute strikes for one firing inside a worker process. - task is (firing_index, jfh_step); returns (firing_index, result dict). + task is (firing_index, jfh_step); returns + (firing_index, result dict, meta dict). The meta carries only + non-numerical observability data (worker PID, per-firing wall/CPU time) + for the parent to log — it never participates in numerical accumulation. """ firing_index, jfh_step = task + wall_start = time.perf_counter() + cpu_start = time.process_time() result = _compute_plume_strikes_core( face_centroids=_WORKER_STATE['face_centroids'], target_unit_normals=_WORKER_STATE['target_unit_normals'], @@ -420,7 +427,13 @@ def _parallel_worker_compute(task) -> Any: jfh_step=jfh_step, plume_params=_WORKER_STATE['plume_params'], ) - return firing_index, result + meta = { + 'pid': os.getpid(), + 'firing_index': firing_index, + 'wall_time_s': time.perf_counter() - wall_start, + 'cpu_time_s': time.process_time() - cpu_start, + } + return firing_index, result, meta def run_parallel_plume_strikes( @@ -431,7 +444,8 @@ def run_parallel_plume_strikes( thruster_metrics: Optional[Dict[str, Any]], plume_params: Dict[str, Any], workers: int, -) -> List[Dict[str, np.ndarray]]: + return_meta: bool = False, +): """Compute per-firing strike results across processes, one firing per task. All inputs must be plain serializable data (NumPy arrays, dicts, @@ -440,10 +454,17 @@ def run_parallel_plume_strikes( regardless of completion order; cumulative accumulation and VTK output remain the caller's responsibility (serial, in the parent process). + By default returns ``List[result dict]`` (unchanged legacy contract). When + ``return_meta`` is True, returns ``(results, metas)`` where ``metas`` is a + firing-indexed list of worker observability dicts (PID, wall/CPU time) so + the parent process can emit per-firing progress records; the numerical + results are identical either way. + Raises whatever the executor or workers raise; callers are expected to fall back to the serial path with a clear message. """ results: List[Optional[Dict[str, np.ndarray]]] = [None] * len(jfh_steps) + metas: List[Optional[Dict[str, Any]]] = [None] * len(jfh_steps) with ProcessPoolExecutor( max_workers=workers, initializer=_parallel_worker_init, @@ -460,8 +481,11 @@ def run_parallel_plume_strikes( for i, step in enumerate(jfh_steps) ] for future in futures: - firing_index, result = future.result() + firing_index, result, meta = future.result() results[firing_index] = result + metas[firing_index] = meta + if return_meta: + return results, metas return results diff --git a/pyrpod/rpod/JetFiringHistory.py b/pyrpod/rpod/JetFiringHistory.py index 6e210d2..b369737 100644 --- a/pyrpod/rpod/JetFiringHistory.py +++ b/pyrpod/rpod/JetFiringHistory.py @@ -1,13 +1,15 @@ import configparser +import logging +import time import numpy as np import sympy as sp from pyrpod.util.io.file_print import print_JFH -from pyrpod.logging_utils import get_logger +from pyrpod.logging_utils import log_asset from pyrpod.util.math.transform import rotation_matrix_from_vectors from pyrpod.util.io.fs import resolve_asset_path -logger = get_logger("pyrpod.rpod.JetFiringHistory") +logger = logging.getLogger(__name__) def make_norm(vector_value_function): """Calculate vector norm/magnitude using the Pythagoream Theorem.""" @@ -84,12 +86,16 @@ def read_jfh(self): """ + parse_start = time.perf_counter() try: - path_to_jfh = resolve_asset_path(self.case_dir, 'jfh', self.config['jfh']['jfh']) + jfh_name = self.config['jfh']['jfh'] except KeyError: - # print("WARNING: Jet Firing History not set") + logger.debug("No [jfh] jfh configured for case %s; JFH not loaded.", + self.case_dir) self.JFH = None return + logger.debug("Resolving JFH asset %r for case %s", jfh_name, self.case_dir) + path_to_jfh = resolve_asset_path(self.case_dir, 'jfh', jfh_name) with open(path_to_jfh, 'r') as f: lines = f.readlines() @@ -98,7 +104,8 @@ def read_jfh(self): try: self.nt = int(lines.pop(0).split(' ')[4]) except IndexError: - logger.warning("Supplied JFH file is empty: %s", path_to_jfh) + logger.error("Supplied JFH file is empty (no header/firing " + "count): %s", path_to_jfh) self.JFH = None return @@ -162,6 +169,27 @@ def read_jfh(self): JFH.append(time_step) self.JFH = JFH f.close() + + parse_s = time.perf_counter() - parse_start + + # INFO summary of the loaded JFH; provenance + checksum via log_asset. + log_asset("JFH", jfh_name, path_to_jfh, self.case_dir, logger=logger) + try: + times = [float(step['t']) for step in JFH] + total_activations = sum(len(step['thrusters']) for step in JFH) + unique_ids = sorted({thr for step in JFH for thr in step['thrusters']}) + logger.info( + "JFH loaded: firings=%d time_range_s=[%s, %s] " + "total_thruster_activations=%d unique_thruster_ids=%s " + "parse_time_s=%.4f", + len(JFH), + f"{min(times):.4g}" if times else "n/a", + f"{max(times):.4g}" if times else "n/a", + total_activations, unique_ids, parse_s, + ) + except (KeyError, ValueError) as exc: # pragma: no cover - defensive + logger.warning("JFH loaded but summary stats failed: %s", exc, + exc_info=True) return diff --git a/pyrpod/rpod/PlumeStrikeEstimationStudy.py b/pyrpod/rpod/PlumeStrikeEstimationStudy.py index 56521b5..e20a7a3 100644 --- a/pyrpod/rpod/PlumeStrikeEstimationStudy.py +++ b/pyrpod/rpod/PlumeStrikeEstimationStudy.py @@ -1,6 +1,9 @@ import numpy as np import os import math +import logging +import time +import tracemalloc from stl import mesh import matplotlib.pyplot as plt @@ -14,10 +17,14 @@ from pyrpod.util.io.fs import ensure_dir, resolve_asset_path from pyrpod.util.stl.stl import load_stl, transform_mesh -from tqdm import tqdm from queue import Queue -from pyrpod.logging_utils import get_logger +from pyrpod.logging_utils import ( + get_active_session, + get_settings, + log_array_summary, + performance_logging_enabled, +) from pyrpod.util.math.transform import rotation_matrix_from_vectors # New modular imports for refactor @@ -34,7 +41,24 @@ run_parallel_plume_strikes, ) -logger = get_logger("pyrpod.rpod.PlumeStrikeEstimationStudy") +logger = logging.getLogger(__name__) + + +def _log_jfh_generation_complete(jfh_path, n_firings, gen_start): + """Log completion of a JFH-generation step (path, size, count, runtime). + + Never raises: JFH generation is a scientific write, so an observability + failure must not mask a successful (or failed) file write. + """ + gen_s = time.perf_counter() - gen_start + try: + size = os.path.getsize(jfh_path) + except OSError: + size = -1 + logger.info("JFH generation completed: firings=%d output=%s " + "output_size_bytes=%d generation_time_s=%.4f", + n_firings, os.path.abspath(jfh_path), size, gen_s) + class PlumeStrikeEstimationStudy (MissionPlanner): """ @@ -343,16 +367,11 @@ def graph_jfh(self, trade_study = False): # Create results directory if it doesn't already exist. results_dir = self.environment.case_dir + 'results' - if not os.path.isdir(results_dir): - # print("results dir doesn't exist") - os.mkdir(results_dir) - + ensure_dir(results_dir) if not trade_study: results_dir = results_dir + "/jfh" - if not os.path.isdir(results_dir): - #print("results dir doesn't exist") - os.mkdir(results_dir) + ensure_dir(results_dir) if trade_study: v_o = ['vo_0', 'vo_1', 'vo_2', 'vo_3', 'vo_4'] @@ -360,9 +379,12 @@ def graph_jfh(self, trade_study = False): for v in v_o: for cant in cants: results_dir_case = results_dir + "/" + v + '_' + cant - if not os.path.isdir(results_dir_case): - #print("results dir doesn't exist") - os.mkdir(results_dir_case) + ensure_dir(results_dir_case) + + logger.info("JFH visualization export started: firings=%d " + "trade_study=%s", len(self.jfh.JFH), trade_study) + viz_files_written = 0 + viz_failures = 0 # Save STL surface of target vehicle to local variable. target = self.target.mesh @@ -456,9 +478,26 @@ def graph_jfh(self, trade_study = False): path_to_stl = os.path.join(self.environment.case_dir, "results", self.get_case_key(), "jfh", f"firing-{firing}.stl") # self.vv.convert_stl_to_vtk(path_to_vtk, mesh =VVmesh) - self.viz.export_firing(VVmesh, path_to_stl) - - def visualize_sweep(self, config_iter): + # The JFH trajectory STLs are an optional visualization aid (viewed + # in ParaView); a write failure must warn and continue rather than + # abort the run, since the numerical strike calculation does not + # depend on them. + try: + self.viz.export_firing(VVmesh, path_to_stl) + viz_files_written += 1 + logger.debug("Wrote JFH firing artifact: %s", path_to_stl) + except Exception: + viz_failures += 1 + logger.warning("Optional JFH visualization write failed for " + "firing %d (%s); continuing.", firing, + path_to_stl, exc_info=True) + + jfh_export_dir = os.path.join(self.environment.case_dir, "results", "jfh") + logger.info("Completed JFH visualization export: files_written=%d " + "failures=%d directory=%s", viz_files_written, + viz_failures, jfh_export_dir) + + def visualize_sweep(self, config_iter): """ Creates visualization data for the trajectory of the proposed RPOD analysis. @@ -488,14 +527,10 @@ def visualize_sweep(self, config_iter): # Create results directory if it doesn't already exist. results_dir = self.environment.case_dir + 'results' - if not os.path.isdir(results_dir): - # print("results dir doesn't exist") - os.mkdir(results_dir) + ensure_dir(results_dir) results_dir = results_dir + "/jfh" - if not os.path.isdir(results_dir): - # print("results dir doesn't exist") - os.mkdir(results_dir) + ensure_dir(results_dir) # Save STL surface of target vehicle to local variable. target = self.target.mesh @@ -504,7 +539,7 @@ def visualize_sweep(self, config_iter): for firing in range(len(self.jfh.JFH)): # print('firing =', firing+1) - # Save active thrusters for current firing. + # Save active thrusters for current firing. thrusters = self.jfh.JFH[firing]['thrusters'] # print("thrusters is", thrusters) @@ -811,6 +846,94 @@ def _resolve_parallel_options(self, parallel, workers, n_firings): return False, 1 return True, workers + def _validate_plume_strike_inputs(self): + """Fail-fast validation of the inputs a plume-strike run requires. + + Logs an ERROR naming the case, the offending section/key, and any + searched context, then raises a clear exception on the first missing + required input rather than silently returning ``None``. Conditionally + required inputs (TDF, surface temperature, sigma, thruster metrics) are + enforced only when kinetics is enabled. + + Returns + ------- + bool + Whether plume kinetics is enabled for this run. + """ + config = self.environment.config + case_dir = self.environment.case_dir + + def require_option(section, key): + if not config.has_option(section, key): + logger.error("Missing required config [%s] %s (case %s)", + section, key, case_dir) + raise KeyError( + f"Missing required config [{section}] {key} (case " + f"{case_dir})") + return config[section][key] + + require_option('tv', 'stl') + require_option('jfh', 'jfh') + require_option('tcd', 'tcf') + kinetics = require_option('pm', 'kinetics') + require_option('plume', 'radius') + require_option('plume', 'wedge_theta') + + target = getattr(self, 'target', None) + if target is None or getattr(target, 'mesh', None) is None: + logger.error("Target vehicle mesh not loaded (case %s)", case_dir) + raise ValueError( + f"Target vehicle mesh not loaded (case {case_dir}); call " + "TargetVehicle.set_stl() before the plume-strike run.") + if len(target.mesh.vectors) == 0: + logger.error("Target mesh is empty (case %s)", case_dir) + raise ValueError(f"Target mesh is empty (case {case_dir}).") + + jfh = getattr(self, 'jfh', None) + if jfh is None or getattr(jfh, 'JFH', None) is None: + logger.error("JFH not loaded (case %s)", case_dir) + raise ValueError( + f"JFH not loaded (case {case_dir}); call " + "JetFiringHistory.read_jfh() with a valid [jfh] jfh.") + if len(jfh.JFH) == 0: + logger.error("JFH is empty (case %s)", case_dir) + raise ValueError(f"JFH is empty (case {case_dir}).") + + thruster_data = getattr(self.vv, 'thruster_data', None) + if not thruster_data: + logger.error("Thruster configuration not loaded (case %s)", case_dir) + raise ValueError( + f"Thruster configuration not loaded (case {case_dir}); call " + "set_thruster_config() before the plume-strike run.") + + # Every JFH thruster index must map to a configured thruster; the + # numeric index is 1-based over the thruster configuration order. + n_configured = len(thruster_data) + for firing_idx, step in enumerate(jfh.JFH): + for thr in step['thrusters']: + if not (1 <= int(thr) <= n_configured): + logger.error( + "JFH firing %d references invalid thruster index %s " + "(configured thrusters: %d, case %s)", + firing_idx, thr, n_configured, case_dir) + raise ValueError( + f"JFH firing {firing_idx} references invalid thruster " + f"index {thr}; case {case_dir} configures " + f"{n_configured} thrusters.") + + kinetics_on = kinetics != 'None' + if kinetics_on: + require_option('tcd', 'tdf') + require_option('tv', 'surface_temp') + require_option('tv', 'sigma') + if getattr(self.vv, 'thruster_metrics', None) is None: + logger.error("Kinetics enabled but thruster metrics (TDF) not " + "loaded (case %s)", case_dir) + raise ValueError( + f"Kinetics enabled but thruster metrics not loaded (case " + f"{case_dir}); call set_thruster_metrics().") + return kinetics_on + def jfh_plume_strikes(self, parallel=None, workers=None): """ Calculates number of plume strikes according to data provided for RPOD analysis. @@ -848,6 +971,10 @@ def jfh_plume_strikes(self, parallel=None, workers=None): enabled, pressures, max_pressures, shear_stress, max_shears, heat_flux_rate, heat_flux_load, cum_heat_flux_load. """ + # Fail-fast validation of every required input before doing any work + # or writing any output. Returns whether kinetics is enabled. + kinetics_on = self._validate_plume_strike_inputs() + # Prepare results directories and target data self.create_results_dir() target = self.target.mesh @@ -855,9 +982,10 @@ def jfh_plume_strikes(self, parallel=None, workers=None): # The target is stationary for the whole run, so face centroids are # computed once here and reused for every firing. target_centroids = compute_face_centroids(target.vectors) + log_array_summary(logger, "target_unit_normals", target_normals) + log_array_summary(logger, "target_face_centroids", target_centroids) # Initialize cumulative arrays - kinetics_on = self.environment.config['pm']['kinetics'] != 'None' if kinetics_on: cum_strikes, max_pressures, max_shears, cum_heat_flux_load = self.set_strike_fields(target) else: @@ -879,13 +1007,44 @@ def jfh_plume_strikes(self, parallel=None, workers=None): parallel_enabled, n_workers = self._resolve_parallel_options(parallel, workers, n_firings) + # Run-scoped logging settings (progress cadence, performance toggle). + settings = get_settings() + progress_every = max(1, settings.progress_every_n_firings) + plume_model = self.environment.config['pm']['kinetics'] + plume_radius = float(self.environment.config['plume']['radius']) + wedge_theta = float(self.environment.config['plume']['wedge_theta']) + exec_mode = 'parallel' if parallel_enabled else 'serial' + + logger.info( + "Plume-strike run started: firings=%d target_faces=%d kinetics=%s " + "plume_model=%s plume_radius=%s wedge_theta=%s mode=%s workers=%d " + "progress_every_n_firings=%d", + n_firings, len(target.vectors), kinetics_on, plume_model, + plume_radius, wedge_theta, exec_mode, + n_workers if parallel_enabled else 1, progress_every, + ) + + # Performance/memory tracking (standard library only). tracemalloc is + # engaged solely for an explicitly configured run, never merely because + # this method was called, so unit tests are not slowed. + perf_on = performance_logging_enabled() + tracemalloc_started_here = False + if perf_on and not tracemalloc.is_tracing(): + tracemalloc.start() + tracemalloc_started_here = True + run_wall_start = time.perf_counter() + run_cpu_start = time.process_time() + fallback_occurred = False + worker_meta = None + overall_max_heat_flux_rate = 0.0 + # Optionally compute independent per-firing results in worker # processes. Workers receive only plain serializable inputs (arrays, # dicts, config scalars) — never the study/vehicle/environment objects. per_firing_results = None if parallel_enabled: try: - per_firing_results = run_parallel_plume_strikes( + per_firing_results, worker_meta = run_parallel_plume_strikes( jfh_steps=steps, face_centroids=target_centroids, target_unit_normals=target_normals, @@ -893,17 +1052,23 @@ def jfh_plume_strikes(self, parallel=None, workers=None): thruster_metrics=getattr(self.vv, 'thruster_metrics', None), plume_params=extract_plume_params(self.environment), workers=n_workers, + return_meta=True, ) + logger.info("Parallel execution completed across %d workers.", + n_workers) except Exception as exc: logger.warning( "Parallel plume strike execution failed (%s: %s); " "falling back to serial execution.", - type(exc).__name__, exc, + type(exc).__name__, exc, exc_info=True, ) per_firing_results = None + worker_meta = None + fallback_occurred = True # Loop through each firing in the JFH and delegate to impingement module for firing in range(n_firings): + firing_wall_start = time.perf_counter() step = steps[firing] if per_firing_results is not None: @@ -1006,12 +1171,102 @@ def jfh_plume_strikes(self, parallel=None, workers=None): path_to_vtk = "strikes/firing-" + str(firing) self.target.convert_stl_to_vtk_strikes(path_to_vtk, cellData.copy(), target) - + logger.debug("Wrote firing artifact: %s", os.path.join( + self.environment.case_dir, "results", path_to_vtk + ".vtu")) + + # Detailed per-firing array diagnostics (DEBUG only). + log_array_summary(logger, f"firing_{firing + 1}_strikes", strikes) + + # Track overall max heat-flux RATE for the completion summary. This + # is a scalar used only for logging; it is never written to output + # nor added to firing_data, so numerical results are unchanged. + if kinetics_on: + overall_max_heat_flux_rate = max( + overall_max_heat_flux_rate, float(heat_flux_rate.max())) + + # Configured progress reporting: every Nth firing and the final one. + if logger.isEnabledFor(logging.INFO) and ( + (firing + 1) % progress_every == 0 or firing == n_firings - 1): + firing_wall_s = time.perf_counter() - firing_wall_start + struck_faces = int(np.count_nonzero(strikes)) + pct = 100.0 * (firing + 1) / n_firings + fields = [ + f"progress_pct={pct:.1f}", + f"jfh_id={self.jfh.JFH[firing]['nt']}", + f"sim_time_s={step['t']}", + f"thrusters={list(step['thrusters'])}", + f"struck_faces={struck_faces}", + ] + if kinetics_on: + fields += [ + f"max_pressure_pa={float(result['pressures'].max()):.6g}", + f"max_shear_pa={float(result['shear_stress'].max()):.6g}", + f"max_heat_flux_w_m2={float(result['heat_flux_rate'].max()):.6g}", + f"max_heat_flux_load_j_m2={float(result['heat_flux_load'].max()):.6g}", + ] + if worker_meta is not None and worker_meta[firing] is not None: + wm = worker_meta[firing] + fields += [f"worker_pid={wm['pid']}", + f"wall_time_s={wm['wall_time_s']:.4f}"] + else: + fields += [f"worker_pid={os.getpid()}", + f"wall_time_s={firing_wall_s:.4f}"] + tracked_bytes = cum_strikes.nbytes + if kinetics_on: + tracked_bytes += (max_pressures.nbytes + max_shears.nbytes + + cum_heat_flux_load.nbytes) + fields.append( + f"tracked_array_memory_mb={tracked_bytes / 1e6:.4f}") + logger.info("Firing %d/%d completed: %s", + firing + 1, n_firings, " ".join(fields)) + # if self.environment.config['pm']['kinetics'] != 'None' and checking_constraints: # if not failed_constraints: # constraint_file.write(f"All impingement constraints met.") # # constraint_file.close() + # Completion summary (INFO). + run_wall_s = time.perf_counter() - run_wall_start + run_cpu_s = time.process_time() - run_cpu_start + peak_memory_mb = None + if perf_on and tracemalloc.is_tracing(): + _current, peak_bytes = tracemalloc.get_traced_memory() + peak_memory_mb = peak_bytes / 1e6 + if tracemalloc_started_here: + tracemalloc.stop() + + tracked_bytes = cum_strikes.nbytes + if kinetics_on: + tracked_bytes += (max_pressures.nbytes + max_shears.nbytes + + cum_heat_flux_load.nbytes) + run_status = 'successful_with_warning' if fallback_occurred else 'successful' + summary = { + 'firings_completed': n_firings, + 'total_struck_face_events': float(cum_strikes.sum()), + 'unique_struck_faces': int(np.count_nonzero(cum_strikes)), + 'wall_time_s': round(run_wall_s, 3), + 'cpu_time_s': round(run_cpu_s, 3), + 'avg_wall_time_s_per_firing': ( + round(run_wall_s / n_firings, 4) if n_firings else 0.0), + 'tracked_array_memory_mb': round(tracked_bytes / 1e6, 4), + 'output_artifacts': n_firings, + 'execution_mode': ( + 'parallel' if (parallel_enabled and not fallback_occurred) + else 'serial'), + 'fallback_occurred': fallback_occurred, + 'run_status': run_status, + } + if kinetics_on: + summary['max_pressure_pa'] = f"{float(max_pressures.max()):.6g}" + summary['max_shear_pa'] = f"{float(max_shears.max()):.6g}" + summary['max_heat_flux_w_m2'] = f"{overall_max_heat_flux_rate:.6g}" + summary['max_heat_flux_load_j_m2'] = ( + f"{float(cum_heat_flux_load.max()):.6g}") + if peak_memory_mb is not None: + summary['python_peak_memory_mb'] = round(peak_memory_mb, 3) + logger.info("Plume-strike run completed: %s", + " ".join(f"{k}={v}" for k, v in summary.items())) + return firing_data def calc_time_multiplier(self, v_ida, v_o, r_o): @@ -1170,8 +1425,13 @@ def calc_v_e(self, group): else: jfh_path = self.environment.case_dir + 'jfh/' + self.get_case_key() + '.A' + logger.info("JFH generation started (1D n-fire approach): " + "v_ida_m_s=%s v_o_m_s=%s r_o_m=%s n_firings=%s", + v_ida, v_o, r_o, n_firings) + gen_start = time.perf_counter() os.makedirs(os.path.dirname(jfh_path), exist_ok=True) write_jfh(t_values, r, rot, jfh_path, mode="1d") + _log_jfh_generation_complete(jfh_path, len(t_values), gen_start) def print_jfh_1d_approach(self, v_ida, v_o, r_o, trade_study = False): @@ -1227,8 +1487,12 @@ def calc_v_e(self, group): else: jfh_path = self.environment.case_dir + 'jfh/' + self.get_case_key() + '.A' + logger.info("JFH generation started (1D approach): " + "v_ida_m_s=%s v_o_m_s=%s r_o_m=%s", v_ida, v_o, r_o) + gen_start = time.perf_counter() os.makedirs(os.path.dirname(jfh_path), exist_ok=True) write_jfh(t_values, r, rot, jfh_path, mode="1d") + _log_jfh_generation_complete(jfh_path, len(t_values), gen_start) return def edit_1d_JFH(self, t_values, r, rot): diff --git a/pyrpod/util/io/fs.py b/pyrpod/util/io/fs.py index 3133b55..52302c8 100644 --- a/pyrpod/util/io/fs.py +++ b/pyrpod/util/io/fs.py @@ -75,6 +75,11 @@ def ensure_dir(path): """ Ensure that a directory exists. If it does not exist, create it. + Centralized directory helper: logs at INFO when a directory is created and + at DEBUG when it already exists, so directory activity is traceable without + scattering ``os.path.isdir``/``os.mkdir`` blocks through the workflows. A + logging failure never prevents creation of a required directory. + Parameters ---------- path : str @@ -82,6 +87,15 @@ def ensure_dir(path): """ if not os.path.exists(path): os.makedirs(path) + try: + log.info("Created directory: %s", os.path.abspath(path)) + except Exception: + pass + else: + try: + log.debug("Directory already exists: %s", os.path.abspath(path)) + except Exception: + pass def ensure_parent_dir(file_path): """ @@ -94,4 +108,8 @@ def ensure_parent_dir(file_path): """ parent_dir = os.path.dirname(file_path) if parent_dir and not os.path.exists(parent_dir): - os.makedirs(parent_dir) \ No newline at end of file + os.makedirs(parent_dir) + try: + log.info("Created directory: %s", os.path.abspath(parent_dir)) + except Exception: + pass \ No newline at end of file diff --git a/pyrpod/vehicle/LogisticsModule.py b/pyrpod/vehicle/LogisticsModule.py index b559353..e5fd9c0 100644 --- a/pyrpod/vehicle/LogisticsModule.py +++ b/pyrpod/vehicle/LogisticsModule.py @@ -5,10 +5,10 @@ from mpl_toolkits import mplot3d import os import configparser -from pyrpod.logging_utils import get_logger +import logging from pyrpod.util.io.fs import resolve_asset_path -logger = get_logger("pyrpod.vehicle.LogisticsModule") +logger = logging.getLogger(__name__) class LogisticsModule(VisitingVehicle): """ diff --git a/pyrpod/vehicle/TargetVehicle.py b/pyrpod/vehicle/TargetVehicle.py index b4e74ad..6c3bc37 100644 --- a/pyrpod/vehicle/TargetVehicle.py +++ b/pyrpod/vehicle/TargetVehicle.py @@ -1,7 +1,13 @@ +import logging + from stl import mesh from pyrpod.vehicle.Vehicle import Vehicle +from pyrpod.logging_utils import log_asset, log_array_summary from pyrpod.util.io.fs import resolve_asset_path +logger = logging.getLogger(__name__) + + class TargetVehicle(Vehicle): """ Class responsible for handling visiting vehicle data. @@ -47,6 +53,12 @@ def set_stl(self): self.mesh = next(meshes) #self.mesh = next(meshes) self.path_to_stl = path_to_stl + + log_asset("target-vehicle STL", self.config['tv']['stl'], path_to_stl, + self.case_dir, logger=logger) + logger.info("Target vehicle geometry loaded: mesh_faces=%d", + len(self.mesh.vectors)) + log_array_summary(logger, "target_mesh_vectors", self.mesh.vectors) return def set_stl_elements(self): diff --git a/pyrpod/vehicle/Vehicle.py b/pyrpod/vehicle/Vehicle.py index 3cd1edc..431a6d2 100644 --- a/pyrpod/vehicle/Vehicle.py +++ b/pyrpod/vehicle/Vehicle.py @@ -2,11 +2,15 @@ import numpy as np import os import configparser +import logging from pyevtk.vtk import VtkTriangle, VtkQuad from pyrpod.util.stl.stl import convert_stl_to_vtk +from pyrpod.logging_utils import log_asset from pyrpod.util.io.fs import resolve_asset_path +logger = logging.getLogger(__name__) + class Vehicle: """ Class responsible for handling visiting vehicle data. @@ -50,6 +54,10 @@ def set_stl(self): self.mesh = mesh.Mesh.from_file(path_to_stl) self.path_to_stl = path_to_stl + log_asset("vehicle STL", self.config['vv']['stl_lm'], path_to_stl, + self.case_dir, logger=logger) + logger.info("Vehicle geometry loaded: mesh_faces=%d", + len(self.mesh.vectors)) return def convert_stl_to_vtk_strikes(self, path_to_vtk, cellData, mesh): diff --git a/pyrpod/vehicle/VisitingVehicle.py b/pyrpod/vehicle/VisitingVehicle.py index 2bd99ab..9e37688 100644 --- a/pyrpod/vehicle/VisitingVehicle.py +++ b/pyrpod/vehicle/VisitingVehicle.py @@ -6,13 +6,14 @@ import numpy as np import math import os +import logging from pyrpod.vehicle.Vehicle import Vehicle from pyrpod.mdao import SweepConfig -from pyrpod.logging_utils import get_logger +from pyrpod.logging_utils import log_asset, log_array_summary from pyrpod.util.io.fs import resolve_asset_path -logger = get_logger("pyrpod.vehicle.VisitingVehicle") +logger = logging.getLogger(__name__) # Adapted from # https://stackoverflow.com/questions/54616049/converting-a-rotation-matrix-to-euler-angles-and-back-special-case @@ -213,6 +214,11 @@ def set_stl(self): path_to_stl = resolve_asset_path(self.case_dir, 'stl', self.config['vv']['stl_lm']) self.mesh = mesh.Mesh.from_file(path_to_stl) self.path_to_stl = path_to_stl + log_asset("visiting-vehicle STL", self.config['vv']['stl_lm'], + path_to_stl, self.case_dir, logger=logger) + logger.info("Visiting vehicle geometry loaded: mesh_faces=%d", + len(self.mesh.vectors)) + log_array_summary(logger, "vv_mesh_vectors", self.mesh.vectors) return def get_thruster_cant(self, thruster_name): @@ -284,10 +290,12 @@ def set_thruster_config(self, thruster_data=None): """ if thruster_data is None: try: - path_to_tcf = resolve_asset_path(self.case_dir, 'tcd', self.config['tcd']['tcf']) + tcf_name = self.config['tcd']['tcf'] except KeyError: - # print("WARNING: Thruster Configuration File not set") + logger.warning("No [tcd] tcf configured for case %s; thruster " + "configuration not loaded.", self.case_dir) return + path_to_tcf = resolve_asset_path(self.case_dir, 'tcd', tcf_name) # Simple program, reading text from a file. with open(path_to_tcf, 'r') as f: lines = f.readlines() @@ -307,12 +315,26 @@ def set_thruster_config(self, thruster_data=None): self.thruster_data = process_str_thrusters(str_thrusters) self.jet_interactions = lines.pop(0) - + + log_asset("thruster config (TCF)", tcf_name, path_to_tcf, + self.case_dir, logger=logger) + else: + logger.debug("Thruster configuration overwritten in-memory " + "(%d thrusters).", len(thruster_data)) self.thruster_data = thruster_data self.use_clusters = False - + + n_types = len({self.thruster_data[t]['type'][0] + for t in self.thruster_data}) + logger.info("Thruster configuration loaded: thrusters=%d " + "thruster_types=%d", len(self.thruster_data), n_types) + if logger.isEnabledFor(logging.DEBUG): + exits = np.array([self.thruster_data[t]['exit'][0] + for t in self.thruster_data]) + log_array_summary(logger, "thruster_exit_coords", exits) + return def change_cluster_config(self, x): @@ -361,9 +383,14 @@ def set_cluster_config(self): # Parse through strings and save data in a dictionary self.cluster_data = process_str_clusters(str_clusters) - + self.use_clusters = True - + + log_asset("cluster config (CCF)", self.config['tcd']['ccf'], + path_to_ccf, self.case_dir, logger=logger) + logger.info("Cluster configuration loaded: clusters=%d units=%s", + self.num_clusters, self.cluster_units) + return def set_thruster_metrics(self): @@ -383,11 +410,13 @@ def set_thruster_metrics(self): # Read in path for thruster metric data. try: - path_to_thruster_metrics = resolve_asset_path(self.case_dir, 'tcd', self.config['tcd']['tdf']) + tdf_name = self.config['tcd']['tdf'] except KeyError: - # print("WARNING: Thruster Metrics File Not Set") + logger.warning("No [tcd] tdf configured for case %s; thruster " + "performance metrics not loaded.", self.case_dir) self.thruster_metrics = None return + path_to_thruster_metrics = resolve_asset_path(self.case_dir, 'tcd', tdf_name) # specify columns to be read as strings. str_cols = ['#'] @@ -411,7 +440,11 @@ def set_thruster_metrics(self): # Save thruster metrics self.thruster_metrics[thruster_id] = thruster - # print(self.thruster_metrics) + log_asset("thruster metrics (TDF)", tdf_name, path_to_thruster_metrics, + self.case_dir, logger=logger) + logger.info("Thruster metrics loaded: thruster_types=%d " + "kinetics_performance_data=available", + len(self.thruster_metrics)) return diff --git a/tests/conftest.py b/tests/conftest.py index 2bb66bf..8b8f979 100644 --- a/tests/conftest.py +++ b/tests/conftest.py @@ -6,7 +6,7 @@ TESTS_DIR = Path(__file__).resolve().parent CATEGORIES = ("unit", "integration", "verification") -GROUPS = ("mdao", "mission", "plume", "rpod") +GROUPS = ("logging", "mdao", "mission", "plume", "rpod") # These files import a flat `pyrpod.` layout that no longer exists after # the rpod -> plume/vehicle refactor. Excluded from collection until they are diff --git a/tests/logging/logging_integration_test_01.py b/tests/logging/logging_integration_test_01.py new file mode 100644 index 0000000..216ce3e --- /dev/null +++ b/tests/logging/logging_integration_test_01.py @@ -0,0 +1,276 @@ +# ======================== +# PyRPOD: tests/logging/logging_integration_test_01.py +# ======================== +# Integration tests for operational logging of the plume-strike workflow: +# fail-fast validation of required inputs, progress cadence, serial/parallel +# event equivalence, DEBUG-vs-INFO artifact levels, parallel->serial fallback +# with successful_with_warning status, and optional-visualization warn-and- +# continue behavior. Uses the existing lightweight base_case (kinetics off). + +import logging + +import numpy as np +import pytest + +import pyrpod.logging_utils as lu +from pyrpod.logging_utils import configure_logging +from pyrpod.rpod import JetFiringHistory, PlumeStrikeEstimationStudy +from pyrpod.rpod import PlumeStrikeEstimationStudy as PSES_module +from pyrpod.vehicle import LogisticsModule, TargetVehicle +from pyrpod.mission import MissionEnvironment + +BASE_CASE = "../case/rpod/base_case/" +PKG_LOGGER = logging.getLogger("pyrpod") + + +@pytest.fixture(autouse=True) +def _isolate_pyrpod_logging(): + before_handlers = list(PKG_LOGGER.handlers) + before_level = PKG_LOGGER.level + yield + for handler in list(PKG_LOGGER.handlers): + if handler not in before_handlers: + PKG_LOGGER.removeHandler(handler) + try: + handler.close() + except Exception: + pass + PKG_LOGGER.setLevel(before_level) + lu._ACTIVE_SESSION = None + + +def build_study(case_dir=BASE_CASE, read_jfh=True): + jfh = JetFiringHistory.JetFiringHistory(case_dir) + if read_jfh: + jfh.read_jfh() + + tv = TargetVehicle.TargetVehicle(case_dir) + tv.set_stl() + + lm = LogisticsModule.LogisticsModule(case_dir) + lm.set_thruster_config() + + me = MissionEnvironment.MissionEnvironment(case_dir) + study = PlumeStrikeEstimationStudy.PlumeStrikeEstimationStudy(me) + study.study_init(jfh, tv, lm) + return study + + +def messages_at(caplog, level): + return [r.getMessage() for r in caplog.records if r.levelno == level] + + +# --------------------------------------------------------------------------- # +# 13, 14, 15: fail-fast validation of required inputs +# --------------------------------------------------------------------------- # +def test_missing_jfh_config_fails_fast(): + study = build_study() + study.environment.config.remove_option("jfh", "jfh") + with pytest.raises(KeyError): + study.jfh_plume_strikes() + + +def test_missing_tcf_config_fails_fast(): + study = build_study() + study.environment.config.remove_option("tcd", "tcf") + with pytest.raises(KeyError): + study.jfh_plume_strikes() + + +def test_empty_jfh_fails_fast(caplog): + study = build_study() + study.jfh.JFH = [] + with caplog.at_level(logging.ERROR, logger="pyrpod"): + with pytest.raises(ValueError): + study.jfh_plume_strikes() + assert any("JFH is empty" in m for m in messages_at(caplog, logging.ERROR)) + + +def test_unloaded_jfh_fails_fast(): + study = build_study(read_jfh=False) # JFH object exists but never read + study.jfh.JFH = None + with pytest.raises(ValueError): + study.jfh_plume_strikes() + + +def test_missing_target_mesh_fails_fast(): + study = build_study() + study.target.mesh = None + with pytest.raises(ValueError): + study.jfh_plume_strikes() + + +# --------------------------------------------------------------------------- # +# 16: conditionally required inputs stay optional when their feature is off +# --------------------------------------------------------------------------- # +def test_kinetics_disabled_does_not_require_metrics(): + # base_case has kinetics = None and never loads thruster metrics. + study = build_study() + assert getattr(study.vv, "thruster_metrics", None) is None + firing_data = study.jfh_plume_strikes() # must not raise + assert len(firing_data) == len(study.jfh.JFH) + + +# --------------------------------------------------------------------------- # +# 20: progress logging respects progress_every_n_firings +# --------------------------------------------------------------------------- # +def _count_progress_records(caplog): + return sum(1 for r in caplog.records + if r.levelno == logging.INFO + and r.getMessage().startswith("Firing ") + and "completed:" in r.getMessage()) + + +def test_progress_every_n_firings_default(caplog): + study = build_study() + n = len(study.jfh.JFH) + session = configure_logging(BASE_CASE, file=False, console=False, + write_startup=False, + progress_every_n_firings=1) + try: + with caplog.at_level(logging.INFO, logger="pyrpod"): + study.jfh_plume_strikes() + assert _count_progress_records(caplog) == n + finally: + session.close() + + +def test_progress_every_n_firings_interval(caplog): + study = build_study() + n = len(study.jfh.JFH) + session = configure_logging(BASE_CASE, file=False, console=False, + write_startup=False, + progress_every_n_firings=5) + try: + with caplog.at_level(logging.INFO, logger="pyrpod"): + study.jfh_plume_strikes() + # Every 5th firing plus the final firing. + expected = len([i for i in range(1, n + 1) if i % 5 == 0 or i == n]) + assert _count_progress_records(caplog) == expected + finally: + session.close() + + +# --------------------------------------------------------------------------- # +# 19: serial and parallel workflows emit equivalent major event categories +# --------------------------------------------------------------------------- # +def _event_categories(caplog): + joined = "\n".join(r.getMessage() for r in caplog.records) + return { + "run_started": "Plume-strike run started" in joined, + "progress": "completed:" in joined, + "run_completed": "Plume-strike run completed" in joined, + } + + +def test_serial_and_parallel_emit_equivalent_events(caplog): + with caplog.at_level(logging.INFO, logger="pyrpod"): + build_study().jfh_plume_strikes() + serial_events = _event_categories(caplog) + + caplog.clear() + with caplog.at_level(logging.INFO, logger="pyrpod"): + build_study().jfh_plume_strikes(parallel=True, workers=2) + parallel_events = _event_categories(caplog) + + assert serial_events == parallel_events + assert all(serial_events.values()) + + +# --------------------------------------------------------------------------- # +# 21: individual artifact paths at DEBUG, batch/summary at INFO +# --------------------------------------------------------------------------- # +def test_artifact_paths_debug_summary_info(caplog): + study = build_study() + with caplog.at_level(logging.DEBUG, logger="pyrpod"): + study.jfh_plume_strikes() + + per_artifact = [r for r in caplog.records + if r.getMessage().startswith("Wrote firing artifact:")] + assert per_artifact and all(r.levelno == logging.DEBUG for r in per_artifact) + + started = [r for r in caplog.records + if "Plume-strike run started" in r.getMessage()] + completed = [r for r in caplog.records + if "Plume-strike run completed" in r.getMessage()] + assert started and all(r.levelno == logging.INFO for r in started) + assert completed and all(r.levelno == logging.INFO for r in completed) + + +# --------------------------------------------------------------------------- # +# 17 & 18: parallel failure -> logged fallback -> successful_with_warning +# --------------------------------------------------------------------------- # +def test_parallel_fallback_logs_and_continues(caplog, monkeypatch): + def boom(*args, **kwargs): + raise RuntimeError("forced parallel failure") + + monkeypatch.setattr(PSES_module, "run_parallel_plume_strikes", boom) + + reference = build_study().jfh_plume_strikes() # plain serial baseline + + study = build_study() + with caplog.at_level(logging.INFO, logger="pyrpod"): + result = study.jfh_plume_strikes(parallel=True, workers=2) + + # Numerical result matches the serial baseline exactly. + for firing in reference: + np.testing.assert_array_equal(result[firing]["strikes"], + reference[firing]["strikes"]) + + warnings = messages_at(caplog, logging.WARNING) + assert any("falling back to serial execution" in m for m in warnings) + # Traceback captured on the fallback warning. + assert any(r.exc_info for r in caplog.records + if r.levelno == logging.WARNING) + + completed = next(m for m in messages_at(caplog, logging.INFO) + if "Plume-strike run completed" in m) + assert "run_status=successful_with_warning" in completed + assert "fallback_occurred=True" in completed + assert "execution_mode=serial" in completed + + +# --------------------------------------------------------------------------- # +# 22: optional visualization write failures warn and continue +# --------------------------------------------------------------------------- # +def test_optional_visualization_failure_warns_and_continues(caplog): + study = build_study() + calls = {"n": 0} + original = study.viz.export_firing + + def flaky_export(mesh_obj, path): + calls["n"] += 1 + if calls["n"] == 1: + raise OSError("disk full (simulated)") + return original(mesh_obj, path) + + study.viz.export_firing = flaky_export + + with caplog.at_level(logging.WARNING, logger="pyrpod"): + study.graph_jfh() # must not raise despite the first-firing failure + + warnings = messages_at(caplog, logging.WARNING) + assert any("Optional JFH visualization write failed" in m for m in warnings) + # All remaining firings were still attempted. + assert calls["n"] == len(study.jfh.JFH) + + +# --------------------------------------------------------------------------- # +# 23: the renamed expected-strikes .txt fixture is read correctly +# --------------------------------------------------------------------------- # +def test_expected_strikes_txt_fixture_is_readable(): + from pathlib import Path + fixture = Path(__file__).resolve().parents[1] / "rpod" / \ + "rpod_int_test_01_expected_strikes.txt" + assert fixture.is_file() + content = fixture.read_text(encoding="utf-8") + assert "n_firing" in content + # Non-'n_firing' lines are integer face indices. + for line in content.splitlines(): + if line and "n_firing" not in line: + int(line) + + +if __name__ == "__main__": + import pytest as _pytest + _pytest.main([__file__, "-v"]) diff --git a/tests/logging/logging_unit_test_01.py b/tests/logging/logging_unit_test_01.py new file mode 100644 index 0000000..01aa314 --- /dev/null +++ b/tests/logging/logging_unit_test_01.py @@ -0,0 +1,346 @@ +# ======================== +# PyRPOD: tests/logging/logging_unit_test_01.py +# ======================== +# Unit tests for the centralized operational logging system +# (pyrpod.logging_utils): import side effects, handler ownership, configuration +# precedence, console/file toggles, runtime-log naming/location, configuration +# snapshots, input-asset logging, and array summaries. +# +# These tests use temporary case directories and pytest's caplog/monkeypatch; +# none use logging.basicConfig. + +import json +import logging +import os +import subprocess +import sys +from pathlib import Path + +import numpy as np +import pytest + +import pyrpod.logging_utils as lu +from pyrpod.logging_utils import ( + LoggingSettings, + configure_logging, + log_asset, + summarize_array, +) + +REPO_ROOT = Path(__file__).resolve().parents[2] +PKG_LOGGER = logging.getLogger("pyrpod") + +MINIMAL_CONFIG = """[vv] +stl_lm = cylinder.stl + +[tv] +stl = plate.stl + +[pm] +kinetics = None + +[jfh] +jfh = firings.A + +[tcd] +tcf = thrusters.txt + +[plume] +radius = 25 +wedge_theta = 0.262 +""" + + +@pytest.fixture(autouse=True) +def _isolate_pyrpod_logging(): + """Restore the pyrpod logger and clear the active session after each test.""" + before_handlers = list(PKG_LOGGER.handlers) + before_level = PKG_LOGGER.level + yield + for handler in list(PKG_LOGGER.handlers): + if handler not in before_handlers: + PKG_LOGGER.removeHandler(handler) + try: + handler.close() + except Exception: + pass + PKG_LOGGER.setLevel(before_level) + lu._ACTIVE_SESSION = None + + +def make_case(tmp_path, *, config=MINIMAL_CONFIG, logging_ini=None): + case_dir = tmp_path / "mycase" + case_dir.mkdir() + (case_dir / "config.ini").write_text(config, encoding="utf-8") + if logging_ini is not None: + (case_dir / "logging.ini").write_text(logging_ini, encoding="utf-8") + # configure_logging normalizes trailing separators; keep the pyrpod + # convention of a trailing slash on case_dir strings. + return str(case_dir) + os.sep + + +def owned_handlers(logger): + return [h for h in logger.handlers + if getattr(h, lu._OWNED_HANDLER_ATTR, False)] + + +# --------------------------------------------------------------------------- # +# 1 & 2: import side effects +# --------------------------------------------------------------------------- # +def test_import_has_no_logging_side_effects(tmp_path): + """Importing PyRPOD creates no dirs/log files and configures no root logger.""" + code = ( + "import os, logging, json\n" + "before = set(os.listdir('.'))\n" + "import pyrpod\n" + "import pyrpod.rpod.PlumeStrikeEstimationStudy\n" + "import pyrpod.rpod.JetFiringHistory\n" + "import pyrpod.vehicle.VisitingVehicle\n" + "import pyrpod.vehicle.TargetVehicle\n" + "root = logging.getLogger()\n" + "pkg = logging.getLogger('pyrpod')\n" + "after = set(os.listdir('.'))\n" + "print(json.dumps({\n" + " 'root_handlers': len(root.handlers),\n" + " 'pkg_handlers': len(pkg.handlers),\n" + " 'new_files': sorted(after - before),\n" + "}))\n" + ) + env = dict(os.environ, PYTHONPATH=str(REPO_ROOT)) + proc = subprocess.run([sys.executable, "-c", code], cwd=tmp_path, + capture_output=True, text=True, env=env) + assert proc.returncode == 0, proc.stderr + data = json.loads(proc.stdout.strip().splitlines()[-1]) + assert data["root_handlers"] == 0 + assert data["pkg_handlers"] == 0 + assert data["new_files"] == [] + + +# --------------------------------------------------------------------------- # +# 3 & 25: repeated configuration does not duplicate handlers or messages +# --------------------------------------------------------------------------- # +def test_repeated_configuration_no_duplicate_handlers(tmp_path): + case = make_case(tmp_path) + s1 = configure_logging(case, console=False, write_startup=False) + n1 = len(owned_handlers(PKG_LOGGER)) + s2 = configure_logging(case, console=False, write_startup=False) + n2 = len(owned_handlers(PKG_LOGGER)) + try: + assert n1 == n2 # replaced, not accumulated + finally: + s2.close() + # s1's handlers were closed when s2 replaced them. + assert s1.log_path != s2.log_path + + +def test_repeated_configuration_no_duplicate_messages(tmp_path): + case = make_case(tmp_path) + configure_logging(case, console=False, write_startup=False) + session = configure_logging(case, console=False, write_startup=False) + try: + logging.getLogger("pyrpod.test").info("unique-marker-xyz") + for h in PKG_LOGGER.handlers: + h.flush() + content = Path(session.log_path).read_text(encoding="utf-8") + finally: + session.close() + assert content.count("unique-marker-xyz") == 1 + + +# --------------------------------------------------------------------------- # +# 4 & 5: console and file toggles are independent +# --------------------------------------------------------------------------- # +def test_console_toggle(tmp_path): + case = make_case(tmp_path) + s = configure_logging(case, console=True, file=False, write_startup=False) + try: + streams = [h for h in owned_handlers(PKG_LOGGER) + if isinstance(h, logging.StreamHandler) + and not isinstance(h, logging.FileHandler)] + assert len(streams) == 1 + finally: + s.close() + + s = configure_logging(case, console=False, file=False, write_startup=False) + try: + streams = [h for h in owned_handlers(PKG_LOGGER) + if type(h) is logging.StreamHandler] + assert streams == [] + finally: + s.close() + + +def test_file_toggle(tmp_path): + case = make_case(tmp_path) + s = configure_logging(case, console=False, file=True, write_startup=False) + try: + assert s.log_path is not None + assert os.path.isfile(s.log_path) + finally: + s.close() + + s = configure_logging(case, console=False, file=False, write_startup=False) + try: + assert s.log_path is None + assert [h for h in owned_handlers(PKG_LOGGER) + if isinstance(h, logging.FileHandler)] == [] + finally: + s.close() + + +# --------------------------------------------------------------------------- # +# 6 & 7: a new run creates a new timestamped file under case/results/logs/ +# --------------------------------------------------------------------------- # +def test_new_run_creates_new_log_under_results_logs(tmp_path): + case = make_case(tmp_path) + s1 = configure_logging(case, console=False, write_startup=False) + p1 = s1.log_path + s2 = configure_logging(case, console=False, write_startup=False) + p2 = s2.log_path + try: + assert p1 != p2 + assert os.path.isfile(p1) and os.path.isfile(p2) + expected_dir = os.path.join(os.path.abspath(case), "results", "logs") + assert os.path.dirname(p1) == expected_dir + assert os.path.basename(p1).startswith("mycase_") + assert p1.endswith(".log") + finally: + s2.close() + + +# --------------------------------------------------------------------------- # +# 8 & 9: precedence — env overrides ini, ini overrides defaults +# --------------------------------------------------------------------------- # +def test_ini_overrides_defaults(tmp_path): + case = make_case(tmp_path, logging_ini="[logging]\nlevel = WARNING\n") + s = configure_logging(case, file=False, console=False, write_startup=False) + try: + assert s.settings.level == "WARNING" # default would be INFO + assert s.used_ini is True + finally: + s.close() + + +def test_env_overrides_ini(tmp_path, monkeypatch): + case = make_case(tmp_path, logging_ini="[logging]\nlevel = ERROR\n") + monkeypatch.setenv("PYRPOD_LOG_LEVEL", "DEBUG") + s = configure_logging(case, file=False, console=False, write_startup=False) + try: + assert s.settings.level == "DEBUG" # env beats ini + finally: + s.close() + + +def test_explicit_argument_overrides_env(tmp_path, monkeypatch): + case = make_case(tmp_path) + monkeypatch.setenv("PYRPOD_LOG_LEVEL", "DEBUG") + s = configure_logging(case, level="ERROR", file=False, console=False, + write_startup=False) + try: + assert s.settings.level == "ERROR" # explicit beats env + finally: + s.close() + + +# --------------------------------------------------------------------------- # +# 10: input assets logged with absolute path, source, size, and SHA-256 +# --------------------------------------------------------------------------- # +def test_log_asset_records_provenance_and_checksum(tmp_path, caplog): + case = make_case(tmp_path) + case_dir = os.path.abspath(case) + asset_dir = os.path.join(case_dir, "stl") + os.makedirs(asset_dir) + asset_path = os.path.join(asset_dir, "plate.stl") + payload = b"solid test\nendsolid test\n" + with open(asset_path, "wb") as fh: + fh.write(payload) + + import hashlib + expected_sha = hashlib.sha256(payload).hexdigest() + + with caplog.at_level(logging.INFO, logger="pyrpod"): + log_asset("target STL", "plate.stl", asset_path, case_dir) + + messages = [r.getMessage() for r in caplog.records] + record = next(m for m in messages if "asset loaded" in m) + assert os.path.abspath(asset_path) in record + assert "source=case-local" in record + assert f"size_bytes={len(payload)}" in record + assert f"sha256={expected_sha}" in record + + +def test_log_asset_can_disable_checksums(tmp_path, caplog): + case = make_case(tmp_path) + case_dir = os.path.abspath(case) + asset_path = os.path.join(case_dir, "config.ini") + session = configure_logging(case, checksum_inputs=False, file=False, + console=False, write_startup=False) + try: + with caplog.at_level(logging.INFO, logger="pyrpod"): + log_asset("config", "config.ini", asset_path, case_dir) + record = next(m for m in (r.getMessage() for r in caplog.records) + if "asset loaded" in m) + assert "sha256=n/a" in record + finally: + session.close() + + +# --------------------------------------------------------------------------- # +# 11: configuration snapshots preserve exact contents +# --------------------------------------------------------------------------- # +def test_config_snapshot_preserves_contents(tmp_path): + logging_ini = "[logging]\nlevel = INFO\nconsole = false\n" + case = make_case(tmp_path, logging_ini=logging_ini) + session = configure_logging(case, console=False, snapshot_config=True) + try: + log_dir = os.path.dirname(session.log_path) + prefix = f"{session.case_name}_{session.timestamp}" + config_snap = os.path.join(log_dir, f"{prefix}_config.ini") + logging_snap = os.path.join(log_dir, f"{prefix}_logging.ini") + assert os.path.isfile(config_snap) + assert Path(config_snap).read_text(encoding="utf-8") == MINIMAL_CONFIG + assert os.path.isfile(logging_snap) + assert Path(logging_snap).read_text(encoding="utf-8") == logging_ini + finally: + session.close() + + +# --------------------------------------------------------------------------- # +# 12: array-summary helper handles normal, empty, integer, and NaN arrays +# --------------------------------------------------------------------------- # +def test_summarize_array_variants(): + normal = summarize_array("p", np.array([1.0, 2.0, 3.0, 0.0])) + assert "shape=(4,)" in normal and "nonzero=3" in normal and "zero=1" in normal + assert "nan=0" in normal + + empty = summarize_array("e", np.array([])) + assert "empty=True" in empty + + integers = summarize_array("i", np.array([0, 1, 2, 3], dtype=np.int64)) + assert "dtype=int64" in integers and "min=0" in integers and "max=3" in integers + + with_nan = summarize_array("n", np.array([1.0, np.nan, 3.0])) + assert "nan=1" in with_nan and "min=1" in with_nan and "max=3" in with_nan + + boolean = summarize_array("b", np.array([True, False, True])) + assert "dtype=bool" in boolean and "nonzero=2" in boolean + + non_array = summarize_array("o", object()) + assert "numeric=False" in non_array or "unsummarizable" in non_array + + +def test_disabled_logging_installs_no_console_or_file_handlers(tmp_path): + case = make_case(tmp_path) + session = configure_logging(case, enabled=False) + try: + assert session.log_path is None + stream_or_file = [h for h in owned_handlers(PKG_LOGGER) + if isinstance(h, logging.StreamHandler)] + assert stream_or_file == [] # only the (non-emitting) counter + finally: + session.close() + + +if __name__ == "__main__": + import pytest as _pytest + _pytest.main([__file__, "-v"]) diff --git a/tests/rpod/rpod_int_test_01_expected_strikes.log b/tests/rpod/rpod_int_test_01_expected_strikes.txt similarity index 100% rename from tests/rpod/rpod_int_test_01_expected_strikes.log rename to tests/rpod/rpod_int_test_01_expected_strikes.txt diff --git a/tests/rpod/rpod_int_test_02_expected_strikes.log b/tests/rpod/rpod_int_test_02_expected_strikes.txt similarity index 100% rename from tests/rpod/rpod_int_test_02_expected_strikes.log rename to tests/rpod/rpod_int_test_02_expected_strikes.txt diff --git a/tests/rpod/rpod_int_test_03_expected_strikes.log b/tests/rpod/rpod_int_test_03_expected_strikes.txt similarity index 100% rename from tests/rpod/rpod_int_test_03_expected_strikes.log rename to tests/rpod/rpod_int_test_03_expected_strikes.txt diff --git a/tests/rpod/rpod_int_test_04_expected_strikes.log b/tests/rpod/rpod_int_test_04_expected_strikes.txt similarity index 100% rename from tests/rpod/rpod_int_test_04_expected_strikes.log rename to tests/rpod/rpod_int_test_04_expected_strikes.txt diff --git a/tests/rpod/rpod_integration_test_01.py b/tests/rpod/rpod_integration_test_01.py index 93eca6a..e03ecb5 100644 --- a/tests/rpod/rpod_integration_test_01.py +++ b/tests/rpod/rpod_integration_test_01.py @@ -1,6 +1,3 @@ -import logging -logging.basicConfig(filename='rpod_integration_test_01.log', level=logging.INFO, format='%(message)s') - # Andy Torres, Nicholas Palumbo # Last Changed: 11-17-24 @@ -102,7 +99,7 @@ def test_base_case(self): } # Read in expected strikes from text file. - file_path = 'rpod/rpod_int_test_01_expected_strikes.log' + file_path = 'rpod/rpod_int_test_01_expected_strikes.txt' expected_strike_ids = {} with open(file_path, 'r') as file: file_content = file.readlines() @@ -127,9 +124,6 @@ def test_base_case(self): # logging.info(str(i)) self.assertIn(i, expected_strike_ids[n_firing]) - # Development statements used to write comparison entries in expected_strikes - string = '\''+str(n_firing)+'\': ' + ' ' +str(strikes[n_firing]['cum_strikes'].sum()) +',' - logging.info(string) # Number of strikes for a given time step. n_strikes = strikes[n_firing]['strikes'].sum() diff --git a/tests/rpod/rpod_integration_test_02.py b/tests/rpod/rpod_integration_test_02.py index f8a60c2..d176cdc 100644 --- a/tests/rpod/rpod_integration_test_02.py +++ b/tests/rpod/rpod_integration_test_02.py @@ -1,6 +1,3 @@ -import logging -logging.basicConfig(filename='rpod_integration_test_02.log', level=logging.INFO, format='%(message)s') - # Andy Torres, Nicholas Palumbo # Last Changed: 11-10-24 @@ -101,7 +98,7 @@ def test_1d_approach(self): } # Read in expected strikes from text file. - file_path = 'rpod/rpod_int_test_02_expected_strikes.log' + file_path = 'rpod/rpod_int_test_02_expected_strikes.txt' expected_strike_ids = {} with open(file_path, 'r') as file: file_content = file.readlines() diff --git a/tests/rpod/rpod_integration_test_03.py b/tests/rpod/rpod_integration_test_03.py index c11ae77..701a16c 100644 --- a/tests/rpod/rpod_integration_test_03.py +++ b/tests/rpod/rpod_integration_test_03.py @@ -8,10 +8,6 @@ # ======================== # Test case to analyze Keep Out Zone Impingement. (WIP) -import logging -logging.basicConfig(filename='rpod_integration_test_03.log', level=logging.INFO, format='%(message)s') - - import unittest, os, sys from pyrpod.vehicle import LogisticsModule, TargetVehicle @@ -83,7 +79,7 @@ def test_keep_out_zone(self): '10': 538.0 } - file_path = 'rpod/rpod_int_test_03_expected_strikes.log' + file_path = 'rpod/rpod_int_test_03_expected_strikes.txt' expected_strike_ids = {} with open(file_path, 'r') as file: file_content = file.readlines() diff --git a/tests/rpod/rpod_integration_test_04.py b/tests/rpod/rpod_integration_test_04.py index 406065c..9de942a 100644 --- a/tests/rpod/rpod_integration_test_04.py +++ b/tests/rpod/rpod_integration_test_04.py @@ -1,6 +1,3 @@ -import logging -logging.basicConfig(filename='rpod_integration_test_04.log', level=logging.INFO, format='%(message)s') - # Andy Torres, Nicholas A. Palumbo # Last Changed: 03-16-24 @@ -51,7 +48,7 @@ def test_hollow_cube(self): # 3. Assert # Read in expected strikes from text file. - file_path = 'rpod/rpod_int_test_04_expected_strikes.log' + file_path = 'rpod/rpod_int_test_04_expected_strikes.txt' expected_strikes = {} with open(file_path, 'r') as file: file_content = file.readlines()