Found that cat and afw have hidden pex_logging dependency not specified in their ups tables and were shielded by daf_persistence
https://ci.lsst.codes/job/stack-os-matrix/compiler=gcc,label=centos-7,python=py2/13527//console
https://ci.lsst.codes/job/stack-os-matrix/compiler=gcc,label=centos-7,python=py2/13528//console

Yes, we have lots of implicit dependencies still. Please fix them up as you find them as part of other work.

Nate Pease [X] may I bother you to review this ticket? Should be quick. Some implicit dependencies are shown after removing pex_logging dependency in daf_persistence. So I converted cat as well, and made minor changes in afw and meas_astrom to make Jenkins happy: https://ci.lsst.codes/job/stack-os-matrix/compiler=gcc,label=centos-6,python=py2/13568//console

One thing I'm not completely sure is the use of pex.logging.BlockTimingLog that appears once in _read in python/lsst/daf/persistence/butler.py here. It was first introduced by this commit. With that commit I understand it's for timing the reading during debugging, so I replaced it with TRACE level logging, and timestamps can be printed. Kian-Tat Lim may you please confirm?

I don't think that's quite enough. First of all, I'd make the messages the same as were generated previously. Second, I'd make this DEBUG and not TRACE.

Third, the ability to capture system time, I/O information, and memory information can be important here (and potentially in other places). See https://github.com/lsst/pex_logging/blob/2d05c3d131fe4115b1ca6a7a949a5db84f405976/include/lsst/pex/logging/BlockTimingLog.h#L49-L59. We may want/need to write an equivalent wrapper. At least make this a future ticket.

Thanks Kian-Tat Lim.

(1) and (2): will do. Is there a unit test that you use to debug these? Or how do you use this debugging, so I can test as well? I have doubt whether the master is working as we think, but I'm not familiar with pex.logging.BlockTimingLog and hope can use some tests to understand it.

(3) Is there any feature in lsst.log that does what is wanted here?

Hsin-Fang Chiang I'm sorry; I didn't see until this morning that I was assigned as a reviewer for this. I'm not very familiar with our logging packages so I can't really check for correct use, but I've read through the pull requests and they all seem fine to me in terms of what is getting logged and code style. Let me know if you would like me to move the status to 'reviewed'. (I don't know if you'll be doing more work on this ticket per K-T's comments?

Thank you Nate Pease [X] for reviewing. I corrected the first two items K-T mentioned, however I did not test anything manually and may need a bit more time to understand the pex.logging.BlockTimingLog bit. I'm reassigning the reviewer to K-T and will check with him before merging.

Looks like the existing test just makes sure that the API can be called, not that it produces correct results. Of course checking the results of timing tests is hard. You can check the message syntax, and if you put a sleep call in, you can check that the time is greater than some minimum, but otherwise there's not a lot you can do.

In this case, since the original code didn't enable the detailed timing information anyway, I think the only thing is to make sure that the messages are "Starting foo" and "Ending foo". Later, when we reimplement the wrapper on top of lsst.log, we can add test cases.

Thank you Kian-Tat Lim. I corrected the messages to be "Starting foo" and "Ending foo". If you think the patch is good to go, may you please mark this as "Reviewed"? (Of course, pending Jenkins check. And I'll probably hold it off and wait for DM-6999 )

The wrapper you described sounds a bit similar to the timeMethod in pipe_base timer.py that reports resource usage through log for tasks. I don't know whether it's easy to reuse that for non-tasks.

Jenkins passed building (including lsst_distrib, lsst_sims, lsst_ci), but failed at the stack demo , because the default logging output is stdout in lsst.log instead of stderr in pex.logging, the demo script bin/export-results redirects its std output to make the "detected-sources(_small).txt" file, and there are a few debug messages from daf.persistence and daf.butlerUtils when running that script. For running command line tasks and unit tests, log has been configured to go to stderr. The standalone script bin/export-results needs to configure log as well. This is done in the ticket branch of lsst_dm_stack_demo, but Jenkins doesn't get that ticket branch. I've tested it on my machine, to reproduce the error with master and pass the demo with the ticket branch.

Looks OK. The BlockTimingLog replacement is not generating exactly the same message as before, but I don't think that's really a problem.

Now I see by the messages generated previously, you didn't mean the messages before this old daf_persistence commit but the pex.logging.BlockTimingLog messages. I corrected the messages to be exactly the same now (with format differences).

Use tests/butlerPickle.py as an example and set a low threshold/level, this is before the logging migration (pex_logging):

  daf.persistence.butler.read DEBUG: Starting read from None at PickleStorage(foo1.pickle)

  daf.persistence.butler.read DEBUG: Ending read from None at PickleStorage(foo1.pickle)

This is after the logging migration (lsst_log):

DEBUG daf.persistence.butler: Starting read from None at PickleStorage(foo1.pickle)

DEBUG daf.persistence.butler: Ending read from None at PickleStorage(foo1.pickle)

The master daf_persistence doesn't really use BlockTimingLog, so I added one commit to get the messages printed with pex.logging, before the logging migration. The effective changes are the same.

I merged the lsst_dm_stack_demo patch and am running Jenkins.

Jenkins and demo passed

The afw and meas_astrom patches are no longer needed because those minor dependency updates have been done in other tickets. So this ticket include daf_persistence, daf_butlerUtils, and cat.

daf_persistence, daf_butlerUtils, and cat are merged.