Merge pull request #360 from LCOGT/feature/logging-adapter

Migrated banzai logging to use a logging adapter pattern rather than overriding the default logger.

CHANGES.md

@@ -1,6 +1,9 @@
-1.10.1 (2023-05-31)
+1.11.0 (2023-08-10)
 -------------------
 - Updated the logging scheme
+
+1.10.1 (2023-05-31)
+-------------------
 - We now silently fix fits errors that can be repaired automatically
 
 1.10.0 (2023-02-15)

banzai/__init__.py

@@ -3,33 +3,10 @@
 # Packages may add whatever they like to this file, but
 # should keep this content at the top.
 # ----------------------------------------------------------------------------
-from ._astropy_init import *
-from banzai.logs import BanzaiLogger
-from lcogt_logging import LCOGTFormatter
-import logging
-
+from ._astropy_init import *  # noqa
+import banzai.logs  # noqa: F401
 # ----------------------------------------------------------------------------
 
-# Uncomment to enforce Python version check during package import.
-# This is the same check as the one at the top of setup.py
-import sys
-#class UnsupportedPythonError(Exception):
-#    pass
-#__minimum_python_version__ = '3.5'
-#if sys.version_info < tuple((int(val) for val in __minimum_python_version__.split('.'))):
-#    raise UnsupportedPythonError("{} does not support Python < {}".format(__package__, __minimum_python_version__))
-
-if not _ASTROPY_SETUP_:
+if not _ASTROPY_SETUP_:  # noqa
     from banzai import utils
 __all__ = ['utils']
-
-logging.setLoggerClass(BanzaiLogger)
-logging.captureWarnings(True)
-logger = logging.getLogger('banzai')
-
-handler = logging.StreamHandler(stream=sys.stdout)
-handler.setFormatter(LCOGTFormatter())
-logger.addHandler(handler)
-
-# Default the logger to INFO so that we actually get messages by default.
-logger.setLevel('INFO')

banzai/astrometry.py

@@ -1,4 +1,3 @@
-import logging
 import requests
 from requests import ConnectionError, HTTPError
 
@@ -8,8 +7,9 @@
 import numpy as np
 
 from banzai.stages import Stage
+from banzai.logs import get_logger
 
-logger = logging.getLogger('banzai')
+logger = get_logger()
 
 SOURCE_LIMIT = 50
 FAILED_WCS = (4, 'Error status of WCS fit. 0 for no error')

banzai/bias.py

@@ -1,11 +1,11 @@
-import logging
 import numpy as np
 
 from banzai.calibrations import CalibrationStacker, CalibrationUser, CalibrationComparer
 from banzai.stages import Stage
 from banzai.utils import stats
+from banzai.logs import get_logger
 
-logger = logging.getLogger('banzai')
+logger = get_logger()
 
 
 class BiasMaker(CalibrationStacker):

banzai/bpm.py

@@ -1,11 +1,10 @@
-import logging
 import numpy as np
 
 from banzai.calibrations import CalibrationUser
 from banzai.stages import Stage
-from banzai.logs import format_exception
+from banzai.logs import format_exception, get_logger
 
-logger = logging.getLogger('banzai')
+logger = get_logger()
 
 
 class BadPixelMaskLoader(CalibrationUser):

banzai/calibrations.py

@@ -1,4 +1,3 @@
-import logging
 import abc
 from datetime import datetime
 
@@ -8,7 +7,7 @@
 from banzai.data import stack
 from banzai.utils.image_utils import Section
 
-logger = logging.getLogger('banzai')
+logger = logs.get_logger()
 
 
 class CalibrationMaker(Stage):

banzai/celery.py

@@ -1,5 +1,4 @@
 import os
-import logging
 from datetime import datetime, timedelta
 from dateutil.parser import parse
 
@@ -14,16 +13,14 @@
 from banzai.utils.date_utils import get_stacking_date_range
 
 
-logger = logging.getLogger('banzai')
+logger = logs.get_logger()
 
 RETRY_DELAY = int(os.getenv('RETRY_DELAY', 600))
 
 
-# Celery sets up a logger on its own, which messes up the LCOGTFormatter that I want to use.
-# Using this disables celery's logging setup.
-@setup_logging.connect
-def setup_celery_logging(**kwargs):
-    pass
+# Celery sets up a logger on its own, which messes up the LCOGTFormatter that I want to use. Celery logging in general
+# is a nightmare. I read this as a reference:
+# https://distributedpython.com/posts/three-ideas-to-customise-celery-logging-handlers/
 
 
 @worker_process_init.connect
@@ -36,7 +33,8 @@ def configure_workers(**kwargs):
 
 app = Celery('banzai')
 app.config_from_object('banzai.celeryconfig')
-app.conf.update(broker_url=os.getenv('TASK_HOST', 'redis://localhost:6379/0'))
+app.conf.update(broker_url=os.getenv('TASK_HOST', 'redis://localhost:6379/0'),
+                worker_hijack_root_logger=False)
 celery_task_queue_name = os.getenv('CELERY_TASK_QUEUE_NAME', 'celery')
 
 # Set up custom named celery task queue
@@ -51,10 +49,8 @@ def configure_workers(**kwargs):
 # Increase broker timeout to avoid re-scheduling tasks that aren't completed within an hour
 app.conf.broker_transport_options = {'visibility_timeout': 86400}
 
-logs.set_log_level(os.getenv('BANZAI_WORKER_LOGLEVEL', 'INFO'))
-# Calling setup() uses setup_celery_logging. Use redirect to get more celery logs to our logger.
 app.log.setup()
-app.log.redirect_stdouts_to_logger(logger, 'INFO')
+logs.set_log_level(os.getenv('BANZAI_WORKER_LOGLEVEL', 'INFO'))
 
 
 @app.task(name='celery.schedule_calibration_stacking', reject_on_worker_lost=True, max_retries=5)

banzai/cosmic.py

@@ -1,8 +1,8 @@
-import logging
 from banzai.stages import Stage
 from cosmic_conn import init_model
+from banzai.logs import get_logger
 
-logger = logging.getLogger('banzai')
+logger = get_logger()
 
 # initialize a Cosmic-CoNN model
 cr_model = init_model("ground_imaging")

banzai/crosstalk.py

@@ -1,10 +1,9 @@
-import logging
-
 import numpy as np
 
 from banzai.stages import Stage
+from banzai.logs import get_logger
 
-logger = logging.getLogger('banzai')
+logger = get_logger()
 
 
 class CrosstalkCorrector(Stage):

banzai/dark.py

@@ -1,12 +1,11 @@
-import logging
-
-import numpy as np
-
 from banzai.stages import Stage
 from banzai.calibrations import CalibrationStacker, CalibrationUser, CalibrationComparer
 from banzai.utils import qc
+from banzai.logs import get_logger
+import numpy as np
+
 
-logger = logging.getLogger('banzai')
+logger = get_logger()
 
 
 class DarkNormalizer(Stage):

banzai/data.py

@@ -189,7 +189,7 @@ def __isub__(self, value):
 
     def __sub__(self, other):
         uncertainty = np.sqrt(self.uncertainty * self.uncertainty + other.uncertainty * other.uncertainty)
-        return type(self)(data=self.data - other.data, meta=self.meta, mask=self.mask|other.mask,
+        return type(self)(data=self.data - other.data, meta=self.meta, mask=self.mask | other.mask,
                           uncertainty=uncertainty)
 
     def add_uncertainty(self, readnoise: np.array):

banzai/dbs.py

@@ -8,7 +8,6 @@
 October 2015
 """
 import os.path
-import logging
 import datetime
 from dateutil.parser import parse
 import numpy as np
@@ -19,10 +18,11 @@
 from sqlalchemy.ext.declarative import declarative_base
 from sqlalchemy.sql.expression import true
 from contextlib import contextmanager
+from banzai.logs import get_logger
 
 Base = declarative_base()
 
-logger = logging.getLogger('banzai')
+logger = get_logger()
 
 
 @contextmanager

banzai/flats.py

@@ -1,14 +1,12 @@
 import os.path
-import logging
 
 import numpy as np
-
 from banzai.utils import stats
 from banzai.stages import Stage
 from banzai.calibrations import CalibrationStacker, CalibrationUser, CalibrationComparer
-import numpy as np
+from banzai.logs import get_logger
 
-logger = logging.getLogger('banzai')
+logger = get_logger()
 
 
 class FlatSNRChecker(Stage):

banzai/frames.py

@@ -1,4 +1,3 @@
-import logging
 from banzai import dbs
 from banzai.data import HeaderOnly, CCDData
 from banzai.utils import fits_utils, file_utils
@@ -7,8 +6,9 @@
 import abc
 import os
 from typing import Optional
+from banzai.logs import get_logger
 
-logger = logging.getLogger('banzai')
+logger = get_logger()
 
 
 class ObservationFrame(metaclass=abc.ABCMeta):

banzai/gain.py

@@ -1,8 +1,7 @@
-import logging
-
+from banzai.logs import get_logger
 from banzai.stages import Stage
 
-logger = logging.getLogger('banzai')
+logger = get_logger()
 
 
 class GainNormalizer(Stage):

banzai/lco.py

@@ -2,7 +2,6 @@
 import os
 from fnmatch import fnmatch
 from typing import Optional
-from io import BytesIO
 
 import numpy as np
 from astropy.io import fits
@@ -222,7 +221,8 @@ def init_master_header(old_header, images):
         mean_dateobs = date_utils.mean_date(observation_dates)
 
         header['DATE-OBS'] = (date_utils.date_obs_to_string(mean_dateobs), '[UTC] Mean observation start time')
-        header['DAY-OBS'] = (max(images, key=lambda x: datetime.datetime.strptime(x.epoch, '%Y%m%d')).epoch, '[UTC] Date at start of local observing night')
+        header['DAY-OBS'] = (max(images, key=lambda x: datetime.datetime.strptime(x.epoch, '%Y%m%d')).epoch,
+                             '[UTC] Date at start of local observing night')
         header['ISMASTER'] = (True, 'Is this a master calibration frame')
 
         header.add_history("Images combined to create master calibration image:")
@@ -435,13 +435,13 @@ def open(self, file_info, runtime_context) -> Optional[ObservationFrame]:
                     for extension_name_to_condense in runtime_context.EXTENSION_NAMES_TO_CONDENSE:
                         condensed_name = condensed_name.replace(extension_name_to_condense, '')
                     for associated_extension in self.associated_extensions:
-                        associated_fits_extension_name = condensed_name + associated_extension['FITS_NAME']
-                        if associated_fits_extension_name in fits_hdu_list:
+                        associated_extension_name = condensed_name + associated_extension['FITS_NAME']
+                        if associated_extension_name in fits_hdu_list:
                             if hdu.header.get('EXTVER') == 0:
                                 extension_version = None
                             else:
                                 extension_version = hdu.header.get('EXTVER')
-                            associated_data[associated_extension['NAME']] = fits_hdu_list[associated_fits_extension_name,
+                            associated_data[associated_extension['NAME']] = fits_hdu_list[associated_extension_name,
                                                                                           extension_version].data
                         else:
                             associated_data[associated_extension['NAME']] = None
@@ -561,10 +561,12 @@ def _init_detector_sections(image):
             if hdu.meta.get('DETSEC', 'UNKNOWN') in ['UNKNOWN', 'N/A']:
                 # DETSEC missing?
                 binning = hdu.meta.get('CCDSUM', image.primary_hdu.meta.get('CCDSUM', '1 1'))
+                x_binning = int(binning[0])
+                y_binning = int(binning[2])
                 if hdu.data_section is not None:
                     # use binning from FITS header, bin_x is index 0, bin_y is index 2.
-                    detector_section = Section(1, max(hdu.data_section.x_start, hdu.data_section.x_stop) * int(binning[0]),
-                                               1, max(hdu.data_section.y_start, hdu.data_section.y_stop) * int(binning[2]))
+                    detector_section = Section(1, max(hdu.data_section.x_start, hdu.data_section.x_stop) * x_binning,
+                                               1, max(hdu.data_section.y_start, hdu.data_section.y_stop) * y_binning)
                     hdu.detector_section = detector_section
                 else:
                     logger.warning("Data and detector sections are both undefined for image.", image=image)

banzai/logs.py

@@ -3,17 +3,23 @@
 import traceback
 import sys
 import multiprocessing
+from lcogt_logging import LCOGTFormatter
 
 from banzai.utils import date_utils
 
+logging.captureWarnings(True)
+logging.basicConfig()
+logger = logging.getLogger()
+logger.handlers[0].setFormatter(LCOGTFormatter())
 
-class BanzaiLogger(logging.getLoggerClass()):
-    def __init__(self, name, level='NOTSET'):
-        super(BanzaiLogger, self).__init__(name, level)
+# Default the logger to INFO so that we actually get messages by default.
+logger.setLevel('INFO')
 
-    def _log(self, level, msg, *args, **kwargs):
+
+class BanzaiLogger(logging.LoggerAdapter):
+    def process(self, msg, kwargs):
         kwargs = _create_logging_tags_dictionary(kwargs)
-        super(BanzaiLogger, self)._log(level, msg, *args, **kwargs)
+        return msg, kwargs
 
 
 def _create_logging_tags_dictionary(kwargs):
@@ -47,10 +53,13 @@ def _image_to_tags(image):
 
 
 def set_log_level(log_level='INFO'):
-    root_logger = logging.getLogger('banzai')
-    root_logger.setLevel(log_level.upper())
+    logger.setLevel(log_level.upper())
 
 
 def format_exception():
     exc_type, exc_value, exc_tb = sys.exc_info()
     return traceback.format_exception(exc_type, exc_value, exc_tb)
+
+
+def get_logger():
+    return BanzaiLogger(logging.getLogger('banzai'), extra=None)