DM-31355: Switch from log.getName() to log.name

[laurenam]

The former is now deprecated

[timj]

This change has uncovered a couple of issues that might need a little extra thought.

[timj]

This one should be written as something like

logger = self.log.getChild("Piff")

I'm a bit surprised that this is needed since doesn't it imply that this Task is not being given a piff specific name itself?

[laurenam]

I'm not sure...I was just trying to fix up the log.getName() calls. I'll again ask if @jmeyers314 has any comments.

[timj]

The line as written should definitely use getChild. There is no debate about that. The debate is over why this task seemingly has an incorrect logger name to start with.

[timj]

This line doesn't seem like it should be here. A task should not be configuring additional log handlers itself. The LSST.log import needs to be removed.

[laurenam]

Hmm...ok, I think we need to get input from @jmeyers314 on this. I don't know enough about logging nuances to understand the motivation/need.

[timj]

This handler is already added by command line task and pipetask infrastructure. All it is doing is adding an additional unnecessary handler.

[laurenam]

Any option I try without including that handler line, the messages in the test lose the psfDeterminer.Piff WARN: prefix, e.g., with:

logger = logging.getLogger(self.log.getChild("Piff").name)
logger.addHandler(lsst.log.LogHandler())

I get:

$ python tests/test_psf.py 
psfDeterminer.Piff WARN: Iteration 1: Fitting 12 stars
psfDeterminer.Piff WARN:              Total chisq = 309.98 / 5292 dof
psfDeterminer.Piff WARN: Iteration 2: Fitting 12 stars
psfDeterminer.Piff WARN:              Total chisq = 309.42 / 5292 dof
-4.7232456 4.0207148

but with

logger = logging.getLogger(self.log.getChild("Piff").name)

or

logger = self.log.getChild("Piff")

I get:

$ python tests/test_psf.py 
Iteration 1: Fitting 12 stars
             Total chisq = 309.98 / 5292 dof
Iteration 2: Fitting 12 stars
             Total chisq = 309.42 / 5292 dof
-4.7232456 4.0207148

Also, the two versions have different types (<class 'logging.Logger'> vs. <class 'lsst.pipe.base.task_logging.TaskLogAdapter'>) and, again, I don't know what nuances may be involved in the logging to know if there is a specific reason to prefer the former (especially given that the logger is sent to the piff package...)

I've left it as my first example above for now, but will wait for @jmeyers314 to weigh in here before merging.

[timj]

logger = logging.getLogger(self.log.getChild("Piff").name)

is a very long winded way of doing:

logger = self.log.getChild("Piff")

the latter is the correct way of writing it. The former creates lots of indirection to get to the right answer.

The lsst.log.LogHandler() forces all the log messages back to lsst.log and we are trying to do the exact opposite of that with all my recent changes. The reason why the log messages appear without the handler is that they are proper log messages that are not being sent to lsst.log. We do not want lsst.log to be involved (those log messages aren't captured by pytest as logs). The default python log handler (without --long-log) won't include the logger name. This is absolutely fine.

The change of type is expected and that's why the logging.getLogger() line is wrong. You want to use getChild() to give you the logger directly in a class that matches the logging class that Task is using. This is the logging class that gives you .verbose() and .trace() methods as described in my community post last week.

If you want the log messages captured for now in pytest for analysis you need to do something like:

with self.assertLogs(logging.DEBUG):
    # run the code

otherwise pytest will capture them as logs and report them at the end.

[timj]

I've had a quick look at the code and I think this entire section seems to be trying to create a python logger to pass to the piff class that is configured to allow those piff log messages to be forwarded on to lsst.log. The recent changes to logging in pipe_base mean that none of this is necessary. I think something like this is closer to what we want to be doing:

diff --git a/python/lsst/meas/extensions/piff/piffPsfDeterminer.py b/python/lsst/meas/extensions/piff/piffPsfDeterminer.py
index c71c90b..ebc5391 100644
--- a/python/lsst/meas/extensions/piff/piffPsfDeterminer.py
+++ b/python/lsst/meas/extensions/piff/piffPsfDeterminer.py
@@ -21,13 +21,10 @@
 
 __all__ = ["PiffPsfDeterminerConfig", "PiffPsfDeterminerTask"]
 
-import logging
-
 import numpy as np
 import piff
 import galsim
 
-import lsst.log
 import lsst.pex.config as pexConfig
 import lsst.meas.algorithms as measAlg
 from lsst.meas.algorithms.psfDeterminer import BasePsfDeterminerTask
@@ -175,6 +172,7 @@ class PiffPsfDeterminerTask(BasePsfDeterminerTask):
     """A measurePsfTask PSF estimator using Piff as the implementation.
     """
     ConfigClass = PiffPsfDeterminerConfig
+    _DefaultName = "psfDeterminer.Piff"
 
     def determinePsf(
         self, exposure, psfCandidateList, metadata=None, flagKey=None
@@ -255,10 +253,7 @@ class PiffPsfDeterminerTask(BasePsfDeterminerTask):
         wcs = {0: galsim.PixelScale(1.0)}
         pointing = None
 
-        logger = logging.getLogger(self.log.getName()+".Piff")
-        logger.addHandler(lsst.log.LogHandler())
-
-        piffResult.fit(stars, wcs, pointing, logger=logger)
+        piffResult.fit(stars, wcs, pointing, logger=self.log)
         psf = PiffPsf(kernelSize, kernelSize, piffResult)
 
         used_image_pos = [s.image_pos for s in piffResult.stars]

Give the Task a name with piff in it and use that Task logger directly. The self.log logger is now a python compatible logger.

[jmeyers314]

Hmm...ok, I think we need to get input from @jmeyers314 on this. I don't know enough about logging nuances to understand the motivation/need.

I'm sure I don't understand logging nuances either. As long as @timj 's suggestions leave "Piff" somewhere in the log messages to enable easy grepping, I'm happy.

[timj]

With my diff above and if I configure the python logging format, you get output like:

$ python tests/test_psf.py 
WARNING 2021-08-09 09:12:31,240 psfDeterminer.Piff util.py:297 - Iteration 1: Fitting 12 stars
WARNING 2021-08-09 09:12:31,505 psfDeterminer.Piff util.py:297 -              Total chisq = 309.98 / 5292 dof
WARNING 2021-08-09 09:12:31,505 psfDeterminer.Piff util.py:297 - Iteration 2: Fitting 12 stars
WARNING 2021-08-09 09:12:31,736 psfDeterminer.Piff util.py:297 -              Total chisq = 309.42 / 5292 dof

so yes, Piff is in the log message so long as the log format is defined (which is done for you by pipetask and command line tasks -- but not when you run tests).

[timj]

@laurenam would you like me to force push my suggested change onto this branch (or if you prefer, I can apply my change as an additional commit to this branch).

[laurenam]

Heh...I think I was making the change as you were typing that! I've pushed your suggested changeset and am about to kick off another Jenkins before merging. Thank you so much for your detailed explanations...I'm getting closer to actually understanding what's going on here!