Disentangling file and console logging

stellarphot/photometry/photometry.py

@@ -134,7 +134,8 @@ def single_image_photometry(
         photometry. See `stellarphot.settings.PhotometrySettings` for more information.
 
     fname : str, optional (Default: None)
-        Name of the image file on which photometry is being performed.
+        Name of the image file on which photometry is being performed, used for
+        logging and tracking purposes, the file is not accessed or modified.
 
     logline : str, optional (Default: "single_image_photometry:")
         String to prepend to all log messages.
@@ -209,28 +210,41 @@ def single_image_photometry(
             f"'{type(photometry_options)}'."
         )
 
+
     # Set up logging
     logfile = logging_options.logfile
     console_log = logging_options.console_log
+
+    # If we have no handlers, set up logging
     logger = logging.getLogger("single_image_photometry")
-    console_format = logging.Formatter("%(message)s")
+
+    # Use this to catch if logging was already set up by a call
+    # from multi_image_photometry before creating new log file handler
+    # (Warning: This actually just catches if the logger has any handlers.
+    # Probably not the best way to do this.)
+    fh_exists = False   # Default to filehandler not existing
     if logger.hasHandlers() is False:
         logger.setLevel(logging.INFO)
+        # Set up logging to a file (in addition to any logging below)
         if logfile is not None:
             # by default this appends to existing logfile
             fh = logging.FileHandler(logfile)
             log_format = logging.Formatter("%(levelname)s - %(message)s")
-            if console_log:
-                ch = logging.StreamHandler()
-                ch.setFormatter(console_format)
-                ch.setLevel(logging.INFO)
-                logger.addHandler(ch)
-        else:  # Log to console
-            fh = logging.StreamHandler()
-            log_format = console_format
-        fh.setFormatter(log_format)
-        fh.setLevel(logging.INFO)
-        logger.addHandler(fh)
+            fh.setFormatter(log_format)
+            fh.setLevel(logging.INFO)
+            logger.addHandler(fh)
+            fh_exists = True
+
+        # Set up logging to console if requested
+        if console_log:
+            ch = logging.StreamHandler()
+        else:  # otherwise effectively suppress output
+            ch = logging.NullHandler()
+        console_format = logging.Formatter("%(message)s")
+        ch.setFormatter(console_format)
+        ch.setLevel(logging.INFO)
+        logger.addHandler(ch)
+
 
     #
     # Check CCDData headers before proceeding
@@ -576,10 +590,11 @@ def single_image_photometry(
     msg += "DONE."
     logger.info(msg)
 
-    # Close logfile if it was opened
-    if logfile is not None:
+    # Close logfile if it was created
+    if fh_exists:
         fh.flush()
         fh.close()
+
     # Remove logger handler
     logger.handlers.clear()
 
@@ -661,30 +676,49 @@ def multi_image_photometry(
     multilogger = logging.getLogger("multi_image_photometry")
     multilogger.setLevel(logging.INFO)
     console_format = logging.Formatter("%(message)s")
+    # Remove all other existing handlers from the logger
+    # (Kind of brute force, but works for our purposes
     for handler in multilogger.handlers[:]:
         multilogger.removeHandler(handler)
 
     logfile = photometry_settings.logging_settings.logfile
     console_log = photometry_settings.logging_settings.console_log
 
+    # Set up logging:
+    # Check if logfile is not None, set up logging to be written to the logfile.
+    # Next check if console_log is True, if it is, set up logging to be written
+    #    to the console.
+    # If neither of these are true, set up logging to be written to NullHandler
+    #    which effectively suppresses the logging output.
+
+    # Set up logging to a file (in addition to any logging below)
     if logfile is not None:
-        # Keep original name without path
-        orig_logfile = logfile
+        # Get the name of the logfile without the path
+        logfile = Path(logfile).name
+        # Redirect the logfile to the directory_with_images
         logfile = Path(directory_with_images) / logfile
+        # Change the settings so when they are passed to single_image_photometry
+        # the logging will be written to the same logfile
+        photometry_settings.logging_settings.logfile = str(logfile)
+
+        # Keep original name without path
+        logfile_name = str(Path(logfile).name)
+
         # by default this appends to existing logfile
         fh = logging.FileHandler(logfile)
         log_format = logging.Formatter("%(levelname)s - %(message)s")
-        if console_log:
-            ch = logging.StreamHandler()
-            ch.setFormatter(console_format)
-            ch.setLevel(logging.INFO)
-            multilogger.addHandler(ch)
-    else:  # Log to console
-        fh = logging.StreamHandler()
-        log_format = console_format
-    fh.setFormatter(log_format)
-    fh.setLevel(logging.INFO)
-    multilogger.addHandler(fh)
+        fh.setFormatter(log_format)
+        fh.setLevel(logging.INFO)
+        multilogger.addHandler(fh)
+
+    # Set up logging to console if requested
+    if console_log:
+        ch = logging.StreamHandler()
+    else:  # otherwise effectively suppress output
+        ch = logging.NullHandler()
+    ch.setFormatter(console_format)
+    ch.setLevel(logging.INFO)
+    multilogger.addHandler(ch)
 
     ##
     ## Process all the individual files
@@ -703,7 +737,7 @@ def multi_image_photometry(
 
     msg = f"Starting photometry of files in {directory_with_images} ... "
     if logfile is not None:
-        msg += f"logging output to {orig_logfile}"
+        msg += f"logging output to {logfile_name}"
         # If not logging to console, print message here
         if not console_log:
             print(msg)

stellarphot/photometry/tests/test_photometry.py

@@ -1,3 +1,4 @@
+import logging
 import tempfile
 import warnings
 from copy import deepcopy
@@ -624,6 +625,173 @@ def test_invalid_path(self):
         with pytest.raises(ValueError, match="is not a valid file or directory"):
             ap("invalid_path")
 
+    # Checking logging for AperturePhotometry for single image photometry.
+    @pytest.mark.parametrize("logfile", ["test.log", None])
+    @pytest.mark.parametrize("console_log", [True, False])
+    def test_logging_single_image(self, capsys, logfile, console_log, tmp_path):
+        # Disable any root logger handlers that are active before using
+        # logging since that is expectation of single_image_photometry.
+        if logging.root.hasHandlers():
+            logging.root.handlers.clear()
+
+        # Create fake image
+        fake_CCDimage = deepcopy(FAKE_CCD_IMAGE)
+        image_file = tmp_path / "fake_image.fits"
+        fake_CCDimage.write(image_file, overwrite=True)
+        # Create source list from fake image
+        found_sources = source_detection(
+            fake_CCDimage, fwhm=fake_CCDimage.sources["x_stddev"].mean(), threshold=10
+        )
+        source_list_file = tmp_path / "source_list.ecsv"
+        found_sources.write(source_list_file, format="ascii.ecsv", overwrite=True)
+
+        # Make a copy of photometry options and modify them to match the
+        # test_aperture_photometry_no_outlier_rejection settings
+        phot_options = PhotometryOptionalSettings(**PHOTOMETRY_OPTIONS.model_dump())
+        phot_options.reject_background_outliers = False
+        phot_options.reject_too_close = False
+        phot_options.include_dig_noise = True
+
+        # Define the source locations settings
+        source_locations = DEFAULT_SOURCE_LOCATIONS.model_copy()
+        source_locations.source_list_file = str(source_list_file)
+
+        # Define the logging settings
+        logging_settings=DEFAULT_LOGGING_SETTINGS.model_copy()
+        if logfile:
+            # Define the log file and console log settings
+            # and make sure to set full path of log file.
+            logging_settings.logfile = str(tmp_path / logfile)
+            logging_settings.console_log = console_log
+            full_logfile = logging_settings.logfile
+
+        photometry_settings = PhotometrySettings(
+            camera=FAKE_CAMERA,
+            observatory=FAKE_OBS,
+            photometry_apertures=DEFAULT_PHOTOMETRY_APERTURES,
+            source_locations=source_locations,
+            photometry_optional_settings=phot_options,
+            passband_map=PASSBAND_MAP,
+            logging_settings=logging_settings,
+        )
+
+        # Call the AperturePhotometry class with a single image
+        ap_phot = AperturePhotometry(settings=photometry_settings)
+        phot, missing_sources = ap_phot(image_file)
+
+        #
+        # Test logging was consistent with settings
+        #
+        # Check and see if the output log file was created and contains the
+        # expected messages.
+        if logfile:
+            assert Path(full_logfile).exists()
+            with open(full_logfile) as f:
+                log_content = f.read()
+                # Confirm last log message written by single_image_photometry
+                # present.
+                assert "Calculating noise for all sources" in log_content
+
+        # If console logging is enabled then the stderr should contain the
+        # expected messages.
+        if console_log:
+            captured_stdout = capsys.readouterr()
+            # Confirm last log message written by single_image_photometry
+            # present.
+            assert "Calculating noise for all sources" in captured_stdout.err
+
+    # Checking logging for AperturePhotometry for multiple image photometry.
+    @pytest.mark.parametrize("logfile", ["test.log", None])
+    @pytest.mark.parametrize("console_log", [True, False])
+    def test_logging_multiple_image(self, capsys, logfile, console_log):
+        # Create list of fake CCDData objects
+        num_files = 5
+        fake_images = list_of_fakes(num_files)
+
+        # Write fake images to temporary directory and test
+        # multi_image_photometry on them.0
+        # NOTE: ignore_cleanup_errors=True is needed to avoid an error
+        #       when the temporary directory is deleted on Windows.
+        with tempfile.TemporaryDirectory(ignore_cleanup_errors=True) as temp_dir:
+            # Come up with Filenames
+            temp_file_names = [
+                Path(temp_dir) / f"tempfile_{i:02d}.fit"
+                for i in range(1, num_files + 1)
+            ]
+            # Write the CCDData objects to files
+            for i, image in enumerate(fake_images):
+                image.write(temp_file_names[i])
+            object_name = fake_images[0].header["OBJECT"]
+
+            # Generate the sourcelist
+            found_sources = source_detection(
+                fake_images[0],
+                fwhm=fake_images[0].sources["x_stddev"].mean(),
+                threshold=10,
+            )
+            source_list_file = Path(temp_dir) / "source_list.ecsv"
+            found_sources.write(source_list_file, format="ascii.ecsv", overwrite=True)
+
+            # Make a copy of photometry options based on those used in
+            # successful test_photometry_on_directory
+            phot_options = PhotometryOptionalSettings(**PHOTOMETRY_OPTIONS.model_dump())
+            phot_options.include_dig_noise = True
+            phot_options.reject_too_close = True
+            phot_options.reject_background_outliers = True
+            phot_options.fwhm_by_fit = True
+
+            photometry_settings = DEFAULT_PHOTOMETRY_SETTINGS.model_copy()
+            photometry_settings.photometry_optional_settings = phot_options
+            photometry_settings.source_locations.use_coordinates = "sky"
+            photometry_settings.source_locations.source_list_file = str(
+                source_list_file
+            )
+
+            # Define the logging settings
+            logging_settings=DEFAULT_LOGGING_SETTINGS.model_copy()
+            if logfile:
+                logging_settings.logfile = logfile
+                logging_settings.console_log = console_log
+                # log file should be written to image directory (tmp_dir)
+                # automtically, this ensures we know the path to the log file.
+                full_logfile = str(Path(temp_dir)  / logfile)
+                photometry_settings.logging_settings = logging_settings
+
+            with warnings.catch_warnings():
+                warnings.filterwarnings(
+                    "ignore",
+                    message="Cannot merge meta key",
+                    category=MergeConflictWarning,
+                )
+
+                ap_phot = AperturePhotometry(settings=photometry_settings)
+                _ = ap_phot(temp_dir, object_of_interest=object_name)
+
+                #
+                # Test logging was consistent with settings
+                #
+                # Check and see if the output log file was created and contains the
+                # expected messages.
+                if logfile:
+                    assert Path(full_logfile).exists()
+                    with open(full_logfile) as f:
+                        log_content = f.read()
+                        # Check for log messages output by multi_image_photometry
+                        assert "Starting photometry of files in" in log_content
+                        assert "DONE processing all matching images" in log_content
+                        # Check for last log message from single_image_photometry
+                        assert "Calculating noise for all sources" in log_content
+
+                # If console logging is enabled then the stderr should contain the
+                # expected messages.
+                if console_log:
+                    captured_stdout = capsys.readouterr()
+                    # Check for log messages output by multi_image_photometry
+                    assert "Starting photometry of files in" in captured_stdout.err
+                    assert "DONE processing all matching images" in captured_stdout.err
+                    # Check for last log message from single_image_photometry
+                    assert "Calculating noise for all sources" in captured_stdout.err
+
 
 def test_calc_noise_defaults():
     # If we put in nothing we should get an error about is missing camera

stellarphot/settings/models.py

@@ -882,12 +882,11 @@ class LoggingSettings(BaseModelWithTableRep):
     logfile : str, optional (Default: None)
         Name of the file to which log messages should be written.  It will
         be created in the `directory_with_images` directory.  If None,
-        all messages are logged to stdout.
+        no log file will be created.
 
     console_log: bool, optional (Default: True)
-        If ``True`` and `logfile` is set, log messages will also be written to
-        stdout.  If ``False``, log messages will not be written to stdout
-        if `logfile` is set.
+        If ``True``, log messages will be written to stdout.  If ``False``, log
+        messages will not be written to stdout.
 
     Examples
     --------