diff --git a/RMS/ConfigReader.py b/RMS/ConfigReader.py index 47512c84b..61cb74067 100644 --- a/RMS/ConfigReader.py +++ b/RMS/ConfigReader.py @@ -21,6 +21,7 @@ import os import sys from RMS.CompileArgs import getCompileArgs +from RMS.Logger import installEarlyLogBuffer from RMS.Misc import getRmsRootDir from Utils.GenerateTimelapse import isFfmpegWorking import matplotlib.colors as mcolors @@ -737,6 +738,12 @@ def parse(path, strict=True): """ + # Buffer any warnings raised while parsing (clamped FPS, bad binning, upload disabled on the + # default station code, ...) so initLogging can replay them into the night log. Config parsing + # runs before logging is initialized in every entry point, and every config load funnels + # through here. Idempotent and a no-op once logging is up (see installEarlyLogBuffer). + installEarlyLogBuffer() + delimiter = ";" try: diff --git a/RMS/Logger.py b/RMS/Logger.py index 4ff3a6048..e6125cfb7 100644 --- a/RMS/Logger.py +++ b/RMS/Logger.py @@ -148,6 +148,109 @@ def filter(self, record): return any(_inside(p, root) for root in self.allowed_dirs) +class EarlyRecordBuffer(logging.Handler): + """ + Keep log records emitted before initLogging so they can be replayed into the night log. + + Every entry point loads the config before it initializes logging, so warnings raised while + parsing (clamped FPS, bad binning factor, upload disabled on the default station code) would + otherwise only ever reach the console and never the uploaded night log. + """ + + def __init__(self, capacity=200): + logging.Handler.__init__(self) + + self.capacity = capacity + self.records = [] + self.dropped = 0 + + + def emit(self, record): + + # A full buffer just stops collecting - a handler must never raise + if len(self.records) < self.capacity: + self.records.append(record) + + else: + self.dropped += 1 + + +class _SuppressReplayedOnConsole(logging.Filter): + """ + Drop records replayed from the early buffer so the console does not show a config warning + twice. Such a record was already printed to stderr by _default_handler before logging was + initialized; the replay exists only to get it into the night-log FILE. Applied to the console + handler only - the file handler still receives the replayed record. + """ + + def filter(self, record): + return not getattr(record, "replayed_from_early_buffer", False) + + +def installEarlyLogBuffer(level=logging.WARNING): + """ + Attach a record buffer to the root logger so records emitted before initLogging can be + replayed into the night log. Meant to be called at the start of config parsing (see + ConfigReader.parse) - the one path every entry point hits before it initializes logging. + + Idempotent and self-managing: + - a second call while still pre-init returns the existing buffer, + - once real logging is up (a QueueHandler on the root logger, installed by initLogging or + initChildProcess) it is a no-op, since records already reach the night log directly and a + buffer installed now would never be drained. + + The console side is already covered by _default_handler, installed on the root logger when + this module is imported. Only warnings and above are kept by default, so the buffer cannot + fill up with third-party chatter before the interesting records arrive. + + Return: + [EarlyRecordBuffer or None] The buffer on the root logger, or None if real logging is + already initialized. + """ + + root = logging.getLogger() + + # Real logging already up: records reach the night log directly, so a buffer installed now + # would only accumulate undrained. No-op. + for handler in root.handlers: + if isinstance(handler, logging.handlers.QueueHandler): + return None + + # Pre-init: reuse a buffer if one is already attached + for handler in root.handlers: + if isinstance(handler, EarlyRecordBuffer): + return handler + + buffer_handler = EarlyRecordBuffer() + buffer_handler.setLevel(level) + root.addHandler(buffer_handler) + + return buffer_handler + + +def _drainEarlyLogBuffer(): + """ + Take the records off any early buffer on the root logger. + + Return: + [tuple] (records, dropped) - the buffered records and the number that did not fit. + """ + + root = logging.getLogger() + + records = [] + dropped = 0 + + for handler in root.handlers: + if isinstance(handler, EarlyRecordBuffer): + records.extend(handler.records) + dropped += handler.dropped + handler.records = [] + handler.dropped = 0 + + return records, dropped + + # Reproduced from RMS.Misc due to circular import issue def getRmsRootDir(): """ @@ -485,6 +588,11 @@ def get_log_level(level_str, default=logging.INFO): if self.is_initialized: return + # Take anything logged before this point off the early buffer, so it can be replayed + # into the night log once the queue handler is up. Config parsing happens before + # initLogging in every entry point, so this is where its warnings come from. + early_records, early_dropped = _drainEarlyLogBuffer() + # Remove any default handlers from the root logger main_logger = logging.getLogger() for handler in main_logger.handlers[:]: @@ -504,6 +612,21 @@ def get_log_level(level_str, default=logging.INFO): main_logger.setLevel(min(console_level, file_level)) # Keep root logger permissive main_logger.propagate = False + # Replay the pre-init records into the night log. handle() skips the logger level + # check but still runs the handler filters, so InRmsFilter drops non-RMS records as + # usual, and each record keeps its original timestamp. Mark them so the listener's + # console handler can skip them: _default_handler already printed them to stderr + # before logging came up, so replaying to the console too would double them - the + # replay exists only to get them into the night-log file. + for record in early_records: + record.replayed_from_early_buffer = True + main_logger.handle(record) + + if early_dropped: + main_logger.warning( + "{:d} log record(s) emitted before logging was initialized were dropped".format( + early_dropped)) + # Redirect standard streams sys.stderr = LoggerWriter(main_logger, logging.WARNING, stdout_captured=config.log_stdout) if config.log_stdout: @@ -821,6 +944,10 @@ def _listener_configurer(config, log_file_prefix, safedir, console_level=logging handler.addFilter(InRmsFilter(config)) console.addFilter(InRmsFilter(config)) + # Config warnings replayed from the early buffer were already shown on the console before + # logging was initialized; keep them in the file but skip them on the console (no double print) + console.addFilter(_SuppressReplayedOnConsole()) + # Set common formatter for both handlers formatter = logging.Formatter( fmt='%(asctime)s-%(levelname)s-%(module)s-line:%(lineno)d - %(message)s', diff --git a/RMS/Reprocess.py b/RMS/Reprocess.py index dc106af6c..591cd7fe1 100644 --- a/RMS/Reprocess.py +++ b/RMS/Reprocess.py @@ -5,11 +5,9 @@ import os -import sys import glob import json import collections -import traceback import argparse import random import shutil @@ -291,9 +289,8 @@ def processNight(night_data_dir, config, detection_results=None, nodetect=False) try: generateCalibrationReport(config, night_data_dir, platepar=platepar) - except Exception as e: - log.warning('Generating calibration report failed with the message:\n' + repr(e)) - log.warning(repr(traceback.format_exception(*sys.exc_info()))) + except Exception: + log.warning('Generating calibration report failed', exc_info=True) @@ -304,9 +301,8 @@ def processNight(night_data_dir, config, detection_results=None, nodetect=False) save_plot=True, plot_activity=True, color_map=config.shower_color_map, sporadic_color=config.sporadic_color) - except Exception as e: - log.warning('Shower association failed with the message:\n' + repr(e)) - log.warning(repr(traceback.format_exception(*sys.exc_info()))) + except Exception: + log.warning('Shower association failed', exc_info=True) @@ -353,9 +349,8 @@ def processNight(night_data_dir, config, detection_results=None, nodetect=False) - except Exception as e: - log.warning("Generating a FOV KML file failed with the message:\n" + repr(e)) - log.warning(repr(traceback.format_exception(*sys.exc_info()))) + except Exception: + log.warning("Generating a FOV KML file failed", exc_info=True) @@ -365,9 +360,8 @@ def processNight(night_data_dir, config, detection_results=None, nodetect=False) prepareFluxFiles(config, night_data_dir, os.path.join(night_data_dir, ftpdetectinfo_name), mask=mask, platepar=platepar) - except Exception as e: - log.warning("Preparing flux files failed with the message:\n" + repr(e)) - log.warning(repr(traceback.format_exception(*sys.exc_info()))) + except Exception: + log.warning("Preparing flux files failed", exc_info=True) else: @@ -383,9 +377,8 @@ def processNight(night_data_dir, config, detection_results=None, nodetect=False) try: plotFieldsums(night_data_dir, config) - except Exception as e: - log.warning('Plotting field sums failed with message:\n' + repr(e)) - log.warning(repr(traceback.format_exception(*sys.exc_info()))) + except Exception: + log.warning('Plotting field sums failed', exc_info=True) @@ -426,7 +419,7 @@ def processNight(night_data_dir, config, detection_results=None, nodetect=False) tar_path = os.path.join(year_dir, '{}_{}_FT.tar.bz2'.format(config.stationID, day)) # Use the tarWithProgress function with removal of source - print("Creating archive for {} FT files...".format(day)) + log.info("Creating archive for {} FT files...".format(day)) archive_success = tarWithProgress( source_dir=day_dir, tar_path=tar_path, @@ -435,17 +428,17 @@ def processNight(night_data_dir, config, detection_results=None, nodetect=False) ) if archive_success: - print("Successfully created tar archive at: {}".format(tar_path)) + log.info("Successfully created tar archive at: {}".format(tar_path)) # Add to extra files for upload extra_files.append(tar_path) else: - print("Archive creation failed, keeping original directory: {}".format(day_dir)) - - except Exception as e: - print("Error in archiving process: {}".format(e)) - except Exception as e: - log.warning('Archiving FT files failed with message:\n' + repr(e)) - log.warning(repr(traceback.format_exception(*sys.exc_info()))) + log.warning("Archive creation failed, keeping original directory: {}".format( + day_dir)) + + except Exception: + log.warning("Error in archiving process for {}".format(day), exc_info=True) + except Exception: + log.warning('Archiving FT files failed', exc_info=True) log.info('Making a flat...') @@ -454,9 +447,8 @@ def processNight(night_data_dir, config, detection_results=None, nodetect=False) try: flat_img = makeFlat(night_data_dir, config) - except Exception as e: - log.warning('Making a flat failed with message:\n' + repr(e)) - log.warning(repr(traceback.format_exception(*sys.exc_info()))) + except Exception: + log.warning('Making a flat failed', exc_info=True) flat_img = None @@ -493,9 +485,8 @@ def processNight(night_data_dir, config, detection_results=None, nodetect=False) # Add the timelapse to the extra files extra_files.append(timelapse_path) - except Exception as e: - log.warning('Generating a timelapse failed with message:\n' + repr(e)) - log.warning(repr(traceback.format_exception(*sys.exc_info()))) + except Exception: + log.warning('Generating a timelapse failed', exc_info=True) log.info('Plotting timestamp intervals...') @@ -518,9 +509,8 @@ def processNight(night_data_dir, config, detection_results=None, nodetect=False) addObsParam(obs_dict,"dropped_frame_rate",dropped_frame_rate) - except Exception as e: - log.warning('Plotting timestamp interval failed with message:\n' + repr(e)) - log.warning(repr(traceback.format_exception(*sys.exc_info()))) + except Exception: + log.warning('Plotting timestamp interval failed', exc_info=True) # Generate a config audit report log.info('Generate config audit report') @@ -542,9 +532,8 @@ def processNight(night_data_dir, config, detection_results=None, nodetect=False) extra_files.append(audit_file_path) - except Exception as e: - log.warning('Generating config audit failed with message:\n' + repr(e)) - log.warning(repr(traceback.format_exception(*sys.exc_info()))) + except Exception: + log.warning('Generating config audit failed', exc_info=True) ### Add extra files to archive @@ -669,9 +658,8 @@ def processNight(night_data_dir, config, detection_results=None, nodetect=False) extra_files.append(observation_summary_json_path_file_name) - except Exception as e: - log.warning('Finalizing Observation Summary failed with message:\n' + repr(e)) - log.warning(repr(traceback.format_exception(*sys.exc_info()))) + except Exception: + log.warning('Finalizing Observation Summary failed', exc_info=True) obs_summary_to_log = serialize(config, night_directory=night_data_dir, final=True) log.info("\n\nObservation Summary\n===================\n\n" + obs_summary_to_log + "\n\n") diff --git a/Utils/FRbinViewer.py b/Utils/FRbinViewer.py index 754dd93ab..aba2421f0 100644 --- a/Utils/FRbinViewer.py +++ b/Utils/FRbinViewer.py @@ -260,9 +260,11 @@ def destroyWindow(self): self._mpl_ready = False -# On-screen key legend, toggled with the 'h' key while viewing +# On-screen key legend, toggled with the 'h' key while viewing. Off by default so it never covers +# the image unless it was asked for - KEY_BANNER is printed to the console when a file is opened. KEY_LEGEND = "Keys: SPACE pause | 1 prev file | 2 next line | q quit | h hide keys" -show_key_legend = True +KEY_BANNER = "Keys: SPACE pause | 1 prev file | 2 next line | q quit | h show/hide the on-screen legend" +show_key_legend = False def view(dir_path, ff_path, fr_path, config, save_frames=False, extract_format=None, hide=False, @@ -300,6 +302,9 @@ def view(dir_path, ff_path, fr_path, config, save_frames=False, extract_format=N print('------------------------') print('Showing file:', fr_path) + if not hide: + print(KEY_BANNER) + if ff_path is None: #background = np.zeros((config.height, config.width), np.uint8) diff --git a/Utils/README.md b/Utils/README.md index 6d168dc8c..93a499c30 100644 --- a/Utils/README.md +++ b/Utils/README.md @@ -95,7 +95,6 @@ The main pipeline modules live in the `RMS/` package and are run the same way, u - **`RMS.CaptureDuration`**: Prints the capture start time and duration for the night (given the station coordinates). - **`RMS.DeleteOldObservations`**: Frees up disk space by deleting old observation data. - **`RMS.MLFilter`**: Filters detections using the machine-learning meteor classifier. -- **`RMS.ClearSkyDetector`**: Estimates which parts of the night had clear skies. Other pipeline modules (e.g. `RMS.ArchiveDetections`, `RMS.UploadManager`, `RMS.DownloadPlatepar`, `RMS.CaptureModeSwitcher`) are internal - their `__main__` blocks are hardcoded test stubs, not user CLIs. They run as part of `RMS.StartCapture`/`RMS.Reprocess`.