desihub / desihub/desispec

Redundant log messages in tests, possibly elsewhere

Open
#968 2 comments 0 reactions 0 assignees View on GitHub
bug
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

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.