Redundant log messages in tests, possibly elsewhere
- Dominant language
- Python
- Stars
- 42
- Forks
- 26
- Avg merge
- 1d 21h
- Merged PRs (30d)
- 15
Description
When running tests via `python setup.py test`, it appears that logging is being duplicated, possibly by additional handlers being attached to the standard `desiutil.log` logging object.
For example:
```
test_uniform_resolution (desispec.test.test_sky.TestSky) ... INFO:sky.py:152:compute_uniform_sky: starting
2020-05-19 15:43:19,321 desiutil.log.dlm58.info INFO : starting
INFO:sky.py:224:compute_uniform_sky: iter 0 sky fiber 0/10
2020-05-19 15:43:19,327 desiutil.log.dlm58.info INFO : iter 0 sky fiber 0/10
INFO:sky.py:234:compute_uniform_sky: iter 0 solving
2020-05-19 15:43:19,392 desiutil.log.dlm58.info INFO : iter 0 solving
```
Note how the same log message is written out twice with different formatting.
As far as I can tell, this multiple logging happens at the very start of the test, that is either this gets enabled by the very first test run, or it is an intrinsic feature of the test and/or desispec as a whole.
However, when unit tests run a command, this configuration is not passed to the script being run:
```
test_compute_fiberflat (desispec.test.test_binscripts.TestBinScripts) ... INFO:util.py:73:runcmd: Tue May 19 15:38:51 2020
2020-05-19 15:38:51,587 desiutil.log.dlm58.info INFO : Tue May 19 15:38:51 2020
INFO:util.py:74:runcmd: RUNNING: /Users/weaver/Documents/local/products/venv/desiconda/bin/python /Users/weaver/Documents/Code/git/desihub/desispec/bin/desi_compute_fiberflat --infile frame-909b88990aa04042ab3c8dfa228e4288.fits --outfile fiberflat-909b88990aa04042ab3c8dfa228e4288.fits --qafile qa-calib-909b88990aa04042ab3c8dfa228e4288.yaml --qafig qa-909b88990aa04042ab3c8dfa228e4288.pdf
2020-05-19 15:38:51,587 desiutil.log.dlm58.info INFO : RUNNING: /Users/weaver/Documents/local/products/venv/desiconda/bin/python /Users/weaver/Documents/Code/git/desihub/desispec/bin/desi_compute_fiberflat --infile frame-909b88990aa04042ab3c8dfa228e4288.fits --outfile fiberflat-909b88990aa04042ab3c8dfa228e4288.fits --qafile qa-calib-909b88990aa04042ab3c8dfa228e4288.yaml --qafig qa-909b88990aa04042ab3c8dfa228e4288.pdf
Inputs
frame-909b88990aa04042ab3c8dfa228e4288.fits
Outputs
fiberflat-909b88990aa04042ab3c8dfa228e4288.fits
qa-calib-909b88990aa04042ab3c8dfa228e4288.yaml
qa-909b88990aa04042ab3c8dfa228e4288.pdf
INFO:fiberflat.py:55:main: starting at Tue May 19 15:38:53 2020
INFO:fiberflat.py:68:compute_fiberflat: starting
INFO:fiberflat.py:196:compute_fiberflat: 1st pass iter #0 chi2=1.657125590933176e-27/7600 chi2pdf=2.1804284091226e-31 nout=0 (nsig=10)
INFO:fiberflat.py:213:compute_fiberflat: after 1st pass : nout = 0/12000
INFO:fiberflat.py:218:compute_fiberflat: 2nd pass, iter 0 : mean deconvolved spectrum
INFO:fiberflat.py:233:compute_fiberflat: 2nd pass, filling matrix, iter 0 fiber 0
INFO:fiberflat.py:244:compute_fiberflat: deconvolving
```
Here note how the duplicate log messages stop once we are receiving log output from the script.
Contributor guide
No contributing guide indexed for this repository
Research direction
Start by running the tests with `python setup.py test` and inspect how the test setup configures the `desiutil.log` logging object and its handlers. Compare in-process test output with output from the command invoked by `TestBinScripts`; done means each message is emitted once with the intended formatting in both cases.
Written by the indexing model from the issue text.
Assessment
- Tech stack
- python
- Domain
- observability, testing
- Issue type
- Bug
- Difficulty
- 4/5
- Estimated time
- 3-5 days
- Activity status
- Stale
- Clarity
- Needs clarification
- Newbie friendliness
- 35/100