jamessynge commented 5 years ago

This was failing at develop:HEAD with a KeyError: 'fileline' exception, so I modified to remove the fileline from the formatting of log messages, which then demonstrated that the error was really an assert failure in the test itself.

(panoptes-env) james@galago:/var/panoptes/POCS (fileline-issue-393)$ pytest -k test_autofocus_coarse_with_plots --color=yes pocs/tests/test_camera.py | tee /var/panoptes/logs/pytest-tee.log
============================= test session starts ==============================
platform linux -- Python 3.6.6, pytest-3.8.0, py-1.6.0, pluggy-0.7.1
rootdir: /home/james/git/panoptes/POCS, inifile: setup.cfg
plugins: xdist-1.23.0, repeat-0.7.0, forked-0.2, flakes-4.0.0
collected 90 items / 87 deselected

pocs/tests/test_camera.py Fss                                            [100%]

=================================== FAILURES ===================================
_________________ test_autofocus_coarse_with_plots[simulator] __________________

camera = <pocs.camera.simulator.Camera object at 0x7f77296f8cc0>
patterns = {'coarse_plot': '/tmp/pytest-of-james/pytest-40/images0/focus/SC9764/*/coarse_focus.png', 'final': '/tmp/pytest-of-jam...ges0/focus/SC9764/*/*_final.fits', 'fine_plot': '/tmp/pytest-of-james/pytest-40/images0/focus/SC9764/*/fine_focus.png'}
counter = {'value': 1}

    def test_autofocus_coarse_with_plots(camera, patterns, counter):
        autofocus_event = camera.autofocus(coarse=True, make_plots=True)
        autofocus_event.wait()
        counter['value'] += 1
        assert len(glob.glob(patterns['final'])) == counter['value']
>       assert len(glob.glob(patterns['fine_plot'])) == 1
E       AssertionError: assert 0 == 1
E        +  where 0 = len([])
E        +    where [] = <function glob at 0x7f775c419b70>('/tmp/pytest-of-james/pytest-40/images0/focus/SC9764/*/fine_focus.png')
E        +      where <function glob at 0x7f775c419b70> = glob.glob

pocs/tests/test_camera.py:352: AssertionError

wtgee commented 5 years ago

632

AnthonyHorton commented 5 years ago

Hmmm, well the test failure means that the expected focus plot file doesn't exist, at least not at the expected location. Is this consistently failing, or only sometimes? Wondering whether there's some sort of race condition here.

wtgee commented 5 years ago

I was hoping this would be fixed by #681, which made the image location consistent. So be aware that things may have changed this Issue was open.

jamessynge commented 5 years ago

This is still failing on my laptop (i.e. not saying that it is failing for everybody). Here is the pytest output:

________________________________________________ test_autofocus_coarse_with_plots[simulator] ________________________________________________
camera = <pocs.camera.simulator.Camera object at 0x7f54e5722908>
patterns = {'coarse_plot': '/tmp/pytest-of-james/pytest-1473/images0/focus/SC5597/*/coarse_focus.png', 'final': '/tmp/pytest-of-j...s0/focus/SC5597/*/*_final.fits', 'fine_plot': '/tmp/pytest-of-james/pytest-1473/images0/focus/SC5597/*/fine_focus.png'}
counter = {'value': 1}

    def test_autofocus_coarse_with_plots(camera, patterns, counter):
        autofocus_event = camera.autofocus(coarse=True, make_plots=True)
        autofocus_event.wait()
        counter['value'] += 1
        assert len(glob.glob(patterns['final'])) == counter['value']
>       assert len(glob.glob(patterns['fine_plot'])) == 1
E       AssertionError: assert 0 == 1
E        +  where 0 = len([])
E        +    where [] = <function glob at 0x7f55245bfb70>('/tmp/pytest-of-james/pytest-1473/images0/focus/SC5597/*/fine_focus.png')
E        +      where <function glob at 0x7f55245bfb70> = glob.glob

pocs/tests/test_camera.py:375: AssertionError
------------------------------------------------------------ Captured log setup -------------------------------------------------------------
focuser.py                 106 DEBUG    Focuser created: Simulated Focuser on /dev/ttyFAKE
simulator.py                17 DEBUG    Initialising simulator focuser
simulator.py                34 DEBUG    Connected to focuser SF1155
simulator.py                19 INFO     Simulated Focuser (SF1155) on /dev/ttyFAKE initialised
camera.py                   84 DEBUG    Camera created: Simulated Camera
simulator.py                20 DEBUG    Initializing simulated camera
simulator.py                32 DEBUG    Simulated Camera connected
------------------------------------------------------------- Captured log call -------------------------------------------------------------
focuser.py                 221 DEBUG    Starting autofocus
focuser.py                 333 DEBUG    Beginning coarse autofocus of Simulated Camera (SC5597) on None with Simulated Focuser - initial position: 20000
focuser.py                 347 DEBUG    Taking dark frame /tmp/pytest-of-james/pytest-1473/images0/focus/SC5597/20181016T235345/dark.fits on camera Simulated Camera (SC5597) on None with Simulated Focuser
simulator.py                65 DEBUG    Taking 0.1 second exposure on Simulated Camera: /tmp/pytest-of-james/pytest-1473/images0/focus/SC5597/20181016T235345/dark.fits
fits.py                    368 DEBUG    Image written to /tmp/pytest-of-james/pytest-1473/images0/focus/SC5597/20181016T235345/dark.fits
simulator.py                65 DEBUG    Taking 0.1 second exposure on Simulated Camera: /tmp/pytest-of-james/pytest-1473/images0/focus/SC5597/20181016T235345/20000_coarse_initial.fits
fits.py                    368 DEBUG    Image written to /tmp/pytest-of-james/pytest-1473/images0/focus/SC5597/20181016T235345/20000_coarse_initial.fits
simulator.py                38 DEBUG    Moving focuser SF1155 to 19960
simulator.py                65 DEBUG    Taking 0.1 second exposure on Simulated Camera: /tmp/pytest-of-james/pytest-1473/images0/focus/SC5597/20181016T235345/19960_00.fits
fits.py                    368 DEBUG    Image written to /tmp/pytest-of-james/pytest-1473/images0/focus/SC5597/20181016T235345/19960_00.fits
simulator.py                38 DEBUG    Moving focuser SF1155 to 19980
simulator.py                65 DEBUG    Taking 0.1 second exposure on Simulated Camera: /tmp/pytest-of-james/pytest-1473/images0/focus/SC5597/20181016T235345/19980_01.fits
fits.py                    368 DEBUG    Image written to /tmp/pytest-of-james/pytest-1473/images0/focus/SC5597/20181016T235345/19980_01.fits
simulator.py                38 DEBUG    Moving focuser SF1155 to 20000
simulator.py                65 DEBUG    Taking 0.1 second exposure on Simulated Camera: /tmp/pytest-of-james/pytest-1473/images0/focus/SC5597/20181016T235345/20000_02.fits
fits.py                    368 DEBUG    Image written to /tmp/pytest-of-james/pytest-1473/images0/focus/SC5597/20181016T235345/20000_02.fits
simulator.py                38 DEBUG    Moving focuser SF1155 to 20020
simulator.py                65 DEBUG    Taking 0.1 second exposure on Simulated Camera: /tmp/pytest-of-james/pytest-1473/images0/focus/SC5597/20181016T235345/20020_03.fits
fits.py                    368 DEBUG    Image written to /tmp/pytest-of-james/pytest-1473/images0/focus/SC5597/20181016T235345/20020_03.fits
simulator.py                38 DEBUG    Moving focuser SF1155 to 20040
simulator.py                65 DEBUG    Taking 0.1 second exposure on Simulated Camera: /tmp/pytest-of-james/pytest-1473/images0/focus/SC5597/20181016T235345/20040_04.fits
fits.py                    368 DEBUG    Image written to /tmp/pytest-of-james/pytest-1473/images0/focus/SC5597/20181016T235345/20040_04.fits
focuser.py                 421 WARNING  Best focus outside sweep range, aborting autofocus on Simulated Camera (SC5597) on None with Simulated Focuser!
simulator.py                38 DEBUG    Moving focuser SF1155 to 19960
simulator.py                65 DEBUG    Taking 0.1 second exposure on Simulated Camera: /tmp/pytest-of-james/pytest-1473/images0/focus/SC5597/20181016T235345/19960_coarse_final.fits
fits.py                    368 DEBUG    Image written to /tmp/pytest-of-james/pytest-1473/images0/focus/SC5597/20181016T235345/19960_coarse_final.fits
font_manager.py           1346 DEBUG    findfont: Matching :family=sans-serif:style=normal:variant=normal:weight=normal:stretch=normal:size=12.0 to DejaVu Sans ('/var/panoptes/miniconda/envs/panoptes-env/lib/python3.6/site-packages/matplotlib/mpl-data/fonts/ttf/DejaVuSans.ttf') with score of 0.050000
font_manager.py           1346 DEBUG    findfont: Matching :family=sans-serif:style=normal:variant=normal:weight=normal:stretch=normal:size=10.0 to DejaVu Sans ('/var/panoptes/miniconda/envs/panoptes-env/lib/python3.6/site-packages/matplotlib/mpl-data/fonts/ttf/DejaVuSans.ttf') with score of 0.050000
font_manager.py           1346 DEBUG    findfont: Matching :family=STIXGeneral:style=normal:variant=normal:weight=normal:stretch=normal:size=10.0 to STIXGeneral ('/var/panoptes/miniconda/envs/panoptes-env/lib/python3.6/site-packages/matplotlib/mpl-data/fonts/ttf/STIXGeneral.ttf') with score of 0.050000
font_manager.py           1346 DEBUG    findfont: Matching :family=STIXGeneral:style=italic:variant=normal:weight=normal:stretch=normal:size=10.0 to STIXGeneral ('/var/panoptes/miniconda/envs/panoptes-env/lib/python3.6/site-packages/matplotlib/mpl-data/fonts/ttf/STIXGeneralItalic.ttf') with score of 0.050000
font_manager.py           1346 DEBUG    findfont: Matching :family=STIXGeneral:style=normal:variant=normal:weight=bold:stretch=normal:size=10.0 to STIXGeneral ('/var/panoptes/miniconda/envs/panoptes-env/lib/python3.6/site-packages/matplotlib/mpl-data/fonts/ttf/STIXGeneralBol.ttf') with score of 0.000000
font_manager.py           1346 DEBUG    findfont: Matching :family=STIXNonUnicode:style=normal:variant=normal:weight=normal:stretch=normal:size=10.0 to STIXNonUnicode ('/var/panoptes/miniconda/envs/panoptes-env/lib/python3.6/site-packages/matplotlib/mpl-data/fonts/ttf/STIXNonUni.ttf') with score of 0.050000
font_manager.py           1346 DEBUG    findfont: Matching :family=STIXNonUnicode:style=italic:variant=normal:weight=normal:stretch=normal:size=10.0 to STIXNonUnicode ('/var/panoptes/miniconda/envs/panoptes-env/lib/python3.6/site-packages/matplotlib/mpl-data/fonts/ttf/STIXNonUniIta.ttf') with score of 0.050000
font_manager.py           1346 DEBUG    findfont: Matching :family=STIXNonUnicode:style=normal:variant=normal:weight=bold:stretch=normal:size=10.0 to STIXNonUnicode ('/var/panoptes/miniconda/envs/panoptes-env/lib/python3.6/site-packages/matplotlib/mpl-data/fonts/ttf/STIXNonUniBol.ttf') with score of 0.000000
font_manager.py           1346 DEBUG    findfont: Matching :family=STIXSizeOneSym:style=normal:variant=normal:weight=normal:stretch=normal:size=10.0 to STIXSizeOneSym ('/var/panoptes/miniconda/envs/panoptes-env/lib/python3.6/site-packages/matplotlib/mpl-data/fonts/ttf/STIXSizOneSymReg.ttf') with score of 0.050000
font_manager.py           1346 DEBUG    findfont: Matching :family=STIXSizeTwoSym:style=normal:variant=normal:weight=normal:stretch=normal:size=10.0 to STIXSizeTwoSym ('/var/panoptes/miniconda/envs/panoptes-env/lib/python3.6/site-packages/matplotlib/mpl-data/fonts/ttf/STIXSizTwoSymReg.ttf') with score of 0.050000
font_manager.py           1346 DEBUG    findfont: Matching :family=STIXSizeThreeSym:style=normal:variant=normal:weight=normal:stretch=normal:size=10.0 to STIXSizeThreeSym ('/var/panoptes/miniconda/envs/panoptes-env/lib/python3.6/site-packages/matplotlib/mpl-data/fonts/ttf/STIXSizThreeSymReg.ttf') with score of 0.050000
font_manager.py           1346 DEBUG    findfont: Matching :family=STIXSizeFourSym:style=normal:variant=normal:weight=normal:stretch=normal:size=10.0 to STIXSizeFourSym ('/var/panoptes/miniconda/envs/panoptes-env/lib/python3.6/site-packages/matplotlib/mpl-data/fonts/ttf/STIXSizFourSymReg.ttf') with score of 0.050000
font_manager.py           1346 DEBUG    findfont: Matching :family=STIXSizeFiveSym:style=normal:variant=normal:weight=normal:stretch=normal:size=10.0 to STIXSizeFiveSym ('/var/panoptes/miniconda/envs/panoptes-env/lib/python3.6/site-packages/matplotlib/mpl-data/fonts/ttf/STIXSizFiveSymReg.ttf') with score of 0.050000
font_manager.py           1346 DEBUG    findfont: Matching :family=cmsy10:style=normal:variant=normal:weight=normal:stretch=normal:size=10.0 to cmsy10 ('/var/panoptes/miniconda/envs/panoptes-env/lib/python3.6/site-packages/matplotlib/mpl-data/fonts/ttf/cmsy10.ttf') with score of 0.050000
font_manager.py           1346 DEBUG    findfont: Matching :family=cmr10:style=normal:variant=normal:weight=normal:stretch=normal:size=10.0 to cmr10 ('/var/panoptes/miniconda/envs/panoptes-env/lib/python3.6/site-packages/matplotlib/mpl-data/fonts/ttf/cmr10.ttf') with score of 0.050000
font_manager.py           1346 DEBUG    findfont: Matching :family=cmtt10:style=normal:variant=normal:weight=normal:stretch=normal:size=10.0 to cmtt10 ('/var/panoptes/miniconda/envs/panoptes-env/lib/python3.6/site-packages/matplotlib/mpl-data/fonts/ttf/cmtt10.ttf') with score of 0.050000
font_manager.py           1346 DEBUG    findfont: Matching :family=cmmi10:style=normal:variant=normal:weight=normal:stretch=normal:size=10.0 to cmmi10 ('/var/panoptes/miniconda/envs/panoptes-env/lib/python3.6/site-packages/matplotlib/mpl-data/fonts/ttf/cmmi10.ttf') with score of 0.050000
font_manager.py           1346 DEBUG    findfont: Matching :family=cmb10:style=normal:variant=normal:weight=normal:stretch=normal:size=10.0 to cmb10 ('/var/panoptes/miniconda/envs/panoptes-env/lib/python3.6/site-packages/matplotlib/mpl-data/fonts/ttf/cmb10.ttf') with score of 0.050000
font_manager.py           1346 DEBUG    findfont: Matching :family=cmss10:style=normal:variant=normal:weight=normal:stretch=normal:size=10.0 to cmss10 ('/var/panoptes/miniconda/envs/panoptes-env/lib/python3.6/site-packages/matplotlib/mpl-data/fonts/ttf/cmss10.ttf') with score of 0.050000
font_manager.py           1346 DEBUG    findfont: Matching :family=cmex10:style=normal:variant=normal:weight=normal:stretch=normal:size=10.0 to cmex10 ('/var/panoptes/miniconda/envs/panoptes-env/lib/python3.6/site-packages/matplotlib/mpl-data/fonts/ttf/cmex10.ttf') with score of 0.050000
font_manager.py           1346 DEBUG    findfont: Matching :family=DejaVu Sans:style=normal:variant=normal:weight=normal:stretch=normal:size=10.0 to DejaVu Sans ('/var/panoptes/miniconda/envs/panoptes-env/lib/python3.6/site-packages/matplotlib/mpl-data/fonts/ttf/DejaVuSans.ttf') with score of 0.050000
font_manager.py           1346 DEBUG    findfont: Matching :family=DejaVu Sans:style=italic:variant=normal:weight=normal:stretch=normal:size=10.0 to DejaVu Sans ('/var/panoptes/miniconda/envs/panoptes-env/lib/python3.6/site-packages/matplotlib/mpl-data/fonts/ttf/DejaVuSans-Oblique.ttf') with score of 0.150000
font_manager.py           1346 DEBUG    findfont: Matching :family=DejaVu Sans:style=normal:variant=normal:weight=bold:stretch=normal:size=10.0 to DejaVu Sans ('/var/panoptes/miniconda/envs/panoptes-env/lib/python3.6/site-packages/matplotlib/mpl-data/fonts/ttf/DejaVuSans-Bold.ttf') with score of 0.000000
font_manager.py           1346 DEBUG    findfont: Matching :family=DejaVu Sans Mono:style=normal:variant=normal:weight=normal:stretch=normal:size=10.0 to DejaVu Sans Mono ('/var/panoptes/miniconda/envs/panoptes-env/lib/python3.6/site-packages/matplotlib/mpl-data/fonts/ttf/DejaVuSansMono.ttf') with score of 0.050000
font_manager.py           1346 DEBUG    findfont: Matching :family=DejaVu Sans Display:style=normal:variant=normal:weight=normal:stretch=normal:size=10.0 to DejaVu Sans Display ('/var/panoptes/miniconda/envs/panoptes-env/lib/python3.6/site-packages/matplotlib/mpl-data/fonts/ttf/DejaVuSansDisplay.ttf') with score of 0.050000
focuser.py                 529 INFO     Coarse focus plot for camera Simulated Camera (SC5597) on None with Simulated Focuser written to /tmp/pytest-of-james/pytest-1473/images0/focus/SC5597/20181016T235345/coarse_focus.png
focuser.py                 532 DEBUG    Autofocus of Simulated Camera (SC5597) on None with Simulated Focuser complete - final focus position: 19960

jamessynge commented 5 years ago

I should clarify that I'm testing this with the latest commit as of an hour ago:

commit 7703e5a9ba5afef9dc98a3fb59a71215942c1495 (HEAD -> develop, upstream/develop)
Author: Wilfred Tyler Gee <wtylergee@gmail.com>
Date:   Tue Oct 16 14:07:27 2018 +1100

    Quick Camera fix (#694)

    * Skip gphoto2 camera if it doesn't respond to request for serialnumber

wtgee commented 5 years ago

Two things going on here:

The check for the fine focus should be removed (from #659).
The counter fixture has module level scope. It appears that if we remove the check for the fine plots in this failing test then the test will work, however, it would be easy for it to get screwed up in the future as it's not totally obvious that the counter is not resetting.

I'll put in a fix for the first point, which should get it passing.

panoptes / POCS

test_autofocus_coarse_with_plots[simulator] fails #677

632