Paul Price added a comment - 14/Jul/15 3:07 PM Russell, would you mind reviewing this please? There are two commits on meas_astrom and one on meas_algorithms (see below for details). Here's the output from processCcd.py with the fixes. The chatter is much reduced. $ processCcd.py /tigress/HSC/HSC --output /tigress/pprice/lsst --id visit=904020 ccd=49 --clobber-config : Loading config overrride file '/home/pprice/LSST/obs/subaru/config/processCcd.py' WARNING: Unable to use psfex: No module named extensions.psfex.psfexPsfDeterminer hscAstrom is not setup; using LSST's meas_astrom instead Cannot import lsst.meas.multifit: disabling CModel measurements Cannot import lsst.meas.extensions.photometryKron: disabling Kron measurements Cannot enable shapeHSM ('MEAS_EXTENSIONS_SHAPEHSM_DIR'): disabling HSM shape measurements Cannot import lsst.meas.extensions.photometryKron: disabling Kron measurements Cannot enable shapeHSM ('MEAS_EXTENSIONS_SHAPEHSM_DIR'): disabling HSM shape measurements : Loading config overrride file '/home/pprice/LSST/obs/subaru/config/hsc/processCcd.py' : input=/tigress/HSC/HSC : calib=None : output=/tigress/pprice/lsst CameraMapper: Loading registry registry from /tigress/pprice/lsst/_parent/registry.sqlite3 CameraMapper: Loading calibRegistry registry from /tigress/HSC/HSC/CALIB/calibRegistry.sqlite3 processCcd: Processing {'taiObs': '2013-11-02', 'pointing': 671, 'visit': 904020, 'dateObs': '2013-11-02', 'filter': 'HSC-I', 'field': 'STRIPE82L', 'ccd': 49, 'expTime': 30.0} processCcd.isr: Performing ISR on sensor {'taiObs': '2013-11-02', 'pointing': 671, 'visit': 904020, 'dateObs': '2013-11-02', 'filter': 'HSC-I', 'field': 'STRIPE82L', 'ccd': 49, 'expTime': 30.0} processCcd.isr WARNING: Cannot write thumbnail image; hsc.fitsthumb could not be imported. afw.image.MaskedImage WARNING: Expected extension type not found: IMAGE processCcd.isr: Applying linearity corrections to Ccd 49 processCcd.isr.crosstalk: Applying crosstalk correction afw.image.MaskedImage WARNING: Expected extension type not found: IMAGE : Empty WCS extension, using FITS header processCcd.isr: Set 0 BAD pixels to 647.04 processCcd.isr WARNING: There were 6192 unmasked NaNs processCcd.isr WARNING: Cannot write thumbnail image; hsc.fitsthumb could not be imported. processCcd.isr: Flattened sky level: 647.130493 +/- 12.733898 processCcd.isr: Measuring sky levels in 8x16 grids: 648.106765 processCcd.isr: Sky flatness in 8x16 grids - pp: 0.024087 rms: 0.006057 processCcd.calibrate: installInitialPsf fwhm=5.88235294312 pixels; size=15 pixels processCcd.calibrate.repair: Identified 80 cosmic rays. processCcd.calibrate.detection: Detected 303 positive sources to 5 sigma. processCcd.calibrate.detection: Resubtracting the background after object detection processCcd.calibrate.initialMeasurement: Measuring 303 sources (303 parents, 0 children) processCcd.calibrate.astrometry: Applying distortion correction processCcd.calibrate.astrometry: Solving astrometry processCcd.calibrate.astrometry.solver: Number of selected sources for astrometry : 258 processCcd.calibrate.astrometry.solver: Got astrometric solution from Astrometry.net LoadReferenceObjects: Loading reference objects using center (1023.5, 2084.5) pix = Fk5Coord(320.3431396, 0.5002365, 2000.00) sky and radius 0.111667372351 deg LoadReferenceObjects: Loaded 238 reference objects processCcd.calibrate.astrometry: 186 astrometric matches processCcd.calibrate.astrometry: Refitting WCS processCcd.calibrate.astrometry: Astrometric scatter: 0.047945 arcsec (with non-linear terms, 174 matches, 12 rejected) processCcd.calibrate.measurePsf: Measuring PSF /tigress/HSC/LSST/stack10_1/Linux64/anaconda/2.1.0-4-g35ca374/lib/python2.7/site-packages/numpy/core/_methods.py:59: RuntimeWarning: Mean of empty slice. warnings.warn("Mean of empty slice.", RuntimeWarning) /tigress/HSC/LSST/stack10_1/Linux64/anaconda/2.1.0-4-g35ca374/lib/python2.7/site-packages/numpy/core/_methods.py:71: RuntimeWarning: invalid value encountered in double_scalars ret = ret.dtype.type(ret / rcount) /home/pprice/LSST/meas/algorithms/python/lsst/meas/algorithms/objectSizeStarSelector.py:143: RuntimeWarning: invalid value encountered in less update = dist < minDist processCcd.calibrate.measurePsf: PSF star selector found 163 candidates processCcd.calibrate.measurePsf: PSF determination using 114/163 stars. processCcd.calibrate.repair: Identified 92 cosmic rays. processCcd.calibrate: Fit and subtracted background processCcd.calibrate.measurement: Measuring 303 sources (303 parents, 0 children) processCcd.calibrate.astrometry: Applying distortion correction processCcd.calibrate.astrometry: Solving astrometry processCcd.calibrate.astrometry.solver: Number of selected sources for astrometry : 258 processCcd.calibrate.astrometry.solver: Got astrometric solution from Astrometry.net LoadReferenceObjects: Loading reference objects using center (1023.5, 2084.5) pix = Fk5Coord(320.3431396, 0.5002365, 2000.00) sky and radius 0.111667328272 deg LoadReferenceObjects: Loaded 238 reference objects processCcd.calibrate.astrometry: 186 astrometric matches processCcd.calibrate.astrometry: Refitting WCS processCcd.calibrate.astrometry: Astrometric scatter: 0.048271 arcsec (with non-linear terms, 174 matches, 12 rejected) processCcd.calibrate.photocal: Not applying color terms because config.applyColorTerms is False processCcd.calibrate.photocal: Magnitude zero point: 30.685281 +/- 0.058711 from 173 stars processCcd.calibrate: Photometric zero-point: 30.685281 processCcd.detection: Detected 1194 positive sources to 5 sigma. processCcd.detection: Resubtracting the background after object detection processCcd.deblend: Deblending 1194 sources processCcd.deblend: Deblended: of 1194 sources, 143 were deblended, creating 358 children, total 1552 sources processCcd.measurement: Measuring 1552 sources (1194 parents, 358 children) processCcd WARNING: Persisting background models processCcd: Matching icSource and Source catalogs to propagate flags. processCcd: Matching src to reference catalogue LoadReferenceObjects: Loading reference objects using center (1023.5, 2087.5) pix = Fk5Coord(320.3429016, 0.5001781, 2000.00) sky and radius 0.112109149864 deg LoadReferenceObjects: Loaded 238 reference objects Commits for review: pprice@tiger-sumire:~/LSST/meas/astrom (tickets/DM-3141=) $ git --no-pager log --stat --reverse origin/master.. commit ba83b876f2781efcbf996ed0ec232b87eb0ab2f5 Author: Paul Price <price@astro.princeton.edu> Date: Tue Jul 14 17:45:18 2015 -0400   reduce verbosity in astrometric solution Downgraded several detail-oriented messages from "info" log level to "debug" log level.   python/lsst/meas/astrom/anetBasicAstrometry.py | 4 ++-- python/lsst/meas/astrom/loadAstrometryNetObjects.py | 6 +++--- 2 files changed, 5 insertions(+), 5 deletions(-)   commit 32b101e61c452d61222c1c6e3f4fba843ab5c05c Author: Paul Price <price@astro.princeton.edu> Date: Tue Jul 14 17:48:46 2015 -0400   LoadMultiIndexes: remove call to finalize astrometry.net interface Calling lsst.meas.astrom.astrometry_net.finalize() removes the layer placed over astrometry.net to map log levels. Without this layer, we get a lot of detail printed which can overwhelm the user. The LoadMultiIndexes context manager doesn't set up logging, so shouldn't tear it down.   python/lsst/meas/astrom/loadAstrometryNetObjects.py | 3 +-- 1 file changed, 1 insertion(+), 2 deletions(-)     pprice@tiger-sumire:~/LSST/meas/algorithms (tickets/DM-3141=) $ git --no-pager log --stat --reverse origin/master.. commit 5413a96bb6e7497d2814819f5c10ad15585b4177 Author: Paul Price <price@astro.princeton.edu> Date: Tue Jul 14 17:42:54 2015 -0400   LoadReferenceObjectsTask: reduce logging verbosity Converted message with details from "info" level to "debug" level, and cleaned up other log messages.   python/lsst/meas/algorithms/loadReferenceObjects.py | 7 ++++--- 1 file changed, 4 insertions(+), 3 deletions(-)

Russell Owen added a comment - 14/Jul/15 3:43 PM Can you please remind me where the "Solver..." text comes from? That seems to be the main source of unwanted chatter and I'm surprised to see that your changes got rid of it. I'm guessing that is due to removing astromNet.finalize() but I if so, I'm puzzled. It looks like diagnostic print output that should never have shown up in the first place (the kind of thing that a verbose argument is often used to enable in the HSC code that I ported over). I am not comfortable with your removing the call to astromNet.finalize() in LoadMultiIndexes context manager. Without the automatic call I think one has to finalize manually, which I feel is clumsy and error-prone. (And indeed I don't think finalize is ever called now.) The changes from log.info to log.logdebug are safe but they don't remove many log messages and I feel some are useful and in keeping with messages such as: processCcd.calibrate.measurePsf: PSF star selector found 163 candidates processCcd.calibrate.measurePsf: PSF determination using 114/163 stars. processCcd.calibrate.repair: Identified 92 cosmic rays. processCcd.calibrate: Fit and subtracted background processCcd.calibrate.measurement: Measuring 303 sources (303 parents, 0 children)

Paul Price added a comment - 14/Jul/15 3:57 PM The "Solver..." text comes from astrometry.net's logger. As the commit message says: Calling lsst.meas.astrom.astrometry_net.finalize() removes the layer placed over astrometry.net to map log levels. Without this layer, we get a lot of detail printed which can overwhelm the user. The LoadMultiIndexes context manager doesn't set up logging, so shouldn't tear it down. Note the definition of finalize in astrometry_net.i: void finalize() { stop_an_logging(); } Its only purpose is to tear down the logging layer. It is therefore not intended to be called by a context manager for loading index files. We never used to call it at all (it's never called on the HSC side, with no ill effects that we've noticed yet), and it's not clear what the purpose behind adding it was. If you're concerned that it must be called, it should probably be called via atexit .

Paul Price added a comment - 14/Jul/15 4:05 PM If it helps, note that the corresponding function, start_an_logging is called at module initialisation time: %init %{ // Astrometry.net logging fits_use_error_system(); start_an_logging(); %} The call to finalize , which only calls stop_an_logging , is intended to finalize use of the python module , not of the index files.

Paul Price added a comment - 14/Jul/15 4:19 PM Regarding downgrading log.info to log.debug , in the first iteration I've reduced 11 lines of output (once we remove the logging directly from astrometry.net due to the finalize issue) to 9. I don't think this is a great loss, given that the only things that have gone are the details on the reference objects (reading, found XXX in the circle, reduced to YYY in the box). Ooh, just remembered that the LoadReferenceObjects aren't being printed in the usual hierarchy. I'll see if I can fix that too. Original: LoadReferenceObjects: read index files processCcd.calibrate.astrometry.solver: Number of selected sources for astrometry : 258 processCcd.calibrate.astrometry.solver: Got astrometric solution from Astrometry.net LoadReferenceObjects: getting reference objects using center (1023.5, 2084.5) pix = Fk5Coord(320.3431396, 0.5002365, 2000.00) sky and radius 0.00194896 rad LoadReferenceObjects: search for objects at Fk5Coord(320.3431396, 0.5002365, 2000.00) with radius 0.111667372351 deg LoadReferenceObjects: found 495 objects LoadReferenceObjects: trimmed 257 out-of-bbox objects, leaving 238 processCcd.calibrate.astrometry.solver: Fit WCS: use iter 2 because it had less linear scatter than the next iter: 0.307471 vs. 0.320229 pixels processCcd.calibrate.astrometry: 186 astrometric matches processCcd.calibrate.astrometry: Refitting WCS processCcd.calibrate.astrometry: Astrometric scatter: 0.047945 arcsec (with non-linear terms, 174 matches, 12 rejected) Mine: processCcd.calibrate.astrometry: Applying distortion correction processCcd.calibrate.astrometry: Solving astrometry processCcd.calibrate.astrometry.solver: Number of selected sources for astrometry : 258 processCcd.calibrate.astrometry.solver: Got astrometric solution from Astrometry.net LoadReferenceObjects: Loading reference objects using center (1023.5, 2084.5) pix = Fk5Coord(320.3431396, 0.5002365, 2000.00) sky and radius 0.111667372351 deg LoadReferenceObjects: Loaded 238 reference objects processCcd.calibrate.astrometry: 186 astrometric matches processCcd.calibrate.astrometry: Refitting WCS processCcd.calibrate.astrometry: Astrometric scatter: 0.047945 arcsec (with non-linear terms, 174 matches, 12 rejected)

Russell Owen added a comment - 14/Jul/15 4:53 PM Thank you for the clarification of finalize(). The LSST code I started from called finalize() all over the place (e.g. in unit tests and such), so I thought it was necessary and felt it should be called automatically if possible. Adding finalize() to the context manager seemed like the obvious solution, but not having to call it at all is even better. I would prefer to retain the other messages, but am willing to be overruled.

Paul Price added a comment - 14/Jul/15 6:19 PM One more commit on meas_astrom to review, please: pprice@tiger-sumire:~/LSST/meas/astrom (tickets/DM-3141=) $ git --no-pager log --patch -1 commit 356dcf06308add871058e8bad51cf9df412eac06 Author: Paul Price <price@astro.princeton.edu> Date: Tue Jul 14 21:13:42 2015 -0400   ANetBasicAstrometryTask: set name and log for ref loader The LoadAstrometryNetObjectsTask is not a subtask, so wasn't a proper part of the log hierarchy --- log messages were being printed with only the Task's _DefaultName. Adding the log and a name to the constructor puts it in the usual log hierarchy.   diff --git a/python/lsst/meas/astrom/anetBasicAstrometry.py b/python/lsst/meas/astrom/anetBasicAstrometry.py index c4ff217..95df12c 100644 --- a/python/lsst/meas/astrom/anetBasicAstrometry.py +++ b/python/lsst/meas/astrom/anetBasicAstrometry.py @@ -217,7 +217,8 @@ class ANetBasicAstrometryTask(pipeBase.Task): pipeBase.Task.__init__(self, config=config, **kwargs) self.config = config # this is not a subtask because it cannot safely be retargeted - self.refObjLoader = LoadAstrometryNetObjectsTask(config=self.config, andConfig=andConfig) + self.refObjLoader = LoadAstrometryNetObjectsTask(config=self.config, andConfig=andConfig, log=self.log, + name="loadAN") self.refObjLoader._readIndexFiles() def memusage(self, prefix=''):

Russell Owen added a comment - 15/Jul/15 10:05 AM Your change to how you call the LoadAstrometryNetObjectsTask looks like a good improvement. This is presumably outside the scope of this ticket, but is finalize() is even a useful method? The name is deceptive and it just calls stop_an_logging, which has a very clear name, so I wonder if it should be ditched.

Paul Price added a comment - 15/Jul/15 10:52 AM I agree about finalize() , but there's an awful lot of work that needs to be done in cleaning up the astrometry.net stuff, so I would just group it in with that. I don't know what the plans are for improving that code, but given we'll be moving to a different matcher and reference catalog, it's probably not a high priority. Going to merge soon.

Paul Price added a comment - 15/Jul/15 12:23 PM Thanks! Merged to master.