local tests failing, but succeed in travis

[lgpage]

$ invoke tests --group=python
COVERAGE_PROCESS_START=/media/logan/External/Code_Dev/nbgrader/.coveragerc py.test --cov nbgrader --no-cov-on-fail -v -x -m "not formgrader and not nbextensions"
======================================================= test session starts ========================================================
platform linux -- Python 3.5.1, pytest-2.9.1, py-1.4.31, pluggy-0.3.1 -- /home/logan/.virtualenvs/nbgrader-py35/bin/python3.5
cachedir: .cache
rootdir: /media/logan/External/Code_Dev/nbgrader, inifile: 
plugins: cov-2.2.1
collected 494 items 
.
.
.
nbgrader/tests/apps/test_nbgrader.py::TestNbGrader::test_check_version FAILED

============================================================= FAILURES =============================================================
_________________________________________________ TestNbGrader.test_check_version __________________________________________________

self = <nbgrader.tests.apps.test_nbgrader.TestNbGrader object at 0x7ff06e067898>
capfd = <_pytest.capture.CaptureFixture object at 0x7ff06e04f320>

    def test_check_version(self, capfd):
        """Is the version the same regardless of how we run nbgrader?"""
        if sys.platform == 'win32':
            out1 = "\r\n".join(run_command(["nbgrader.cmd", "--version"]).split("\r\n")[2:])
        else:
>           out1 = run_command(["nbgrader", "--version"])

/media/logan/External/Code_Dev/nbgrader/nbgrader/tests/apps/test_nbgrader.py:36: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
/media/logan/External/Code_Dev/nbgrader/nbgrader/tests/__init__.py:124: in run_command
    copy_coverage_files()
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

    def copy_coverage_files():
        root = os.path.dirname(os.path.dirname(os.path.dirname(__file__)))
        if os.getcwd() != root:
            coverage_files = glob.glob(".coverage.*")
            if len(coverage_files) == 0 and 'COVERAGE_PROCESS_START' in os.environ:
>               raise RuntimeError("No coverage files produced")
E               RuntimeError: No coverage files produced

/media/logan/External/Code_Dev/nbgrader/nbgrader/tests/__init__.py:107: RuntimeError
------------------------------------------------------- Captured stdout call -------------------------------------------------------
Python version 3.5.1 (default, Dec 18 2015, 00:00:00) 
[GCC 4.8.4]
nbgrader version 0.3.0.dev

!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!! Interrupted: stopping after 1 failures !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
================================ 122 tests deselected by "-m 'not formgrader and not nbextensions'" ================================
================================= 1 failed, 104 passed, 1 skipped, 122 deselected in 11.28 seconds =================================

This was run on a clean virtualenv on the master branch without any changes.
Am I doing something wrong?

[lgpage]

Running py.test directly on nbgrader/tests/apps/:

$ py.test -x -vv --cov nbgrader nbgrader/tests/apps/
========================================================================================================================== test session starts ==========================================================================================================================
platform linux -- Python 3.5.1, pytest-2.9.1, py-1.4.31, pluggy-0.3.1 -- /home/logan/.virtualenvs/nbgrader-py35/bin/python3.5
cachedir: .cache
rootdir: /media/logan/External/Code_Dev/nbgrader, inifile: 
plugins: cov-2.2.1
collected 102 items 
.
.
.
nbgrader/tests/apps/test_nbgrader.py::TestNbGrader::test_check_version PASSED
.
.
.
nbgrader/tests/apps/test_nbgrader_submit.py::TestNbGraderSubmit::test_submit FAILED

=============================================================================================================================== FAILURES ================================================================================================================================
____________________________________________________________________________________________________________________ TestNbGraderSubmit.test_submit _____________________________________________________________________________________________________________________

self = <nbgrader.tests.apps.test_nbgrader_submit.TestNbGraderSubmit object at 0x7f2b9f939828>, exchange = '/tmp/tmpttcirnu7', cache = '/tmp/tmpo0ygn6y5', course_dir = '/tmp/tmpjq63dfpt'

    def test_submit(self, exchange, cache, course_dir):
        self._release_and_fetch("ps1", exchange, cache, course_dir)
        now = datetime.datetime.now()

        time.sleep(1)
        self._submit("ps1", exchange, cache)

        filename, = os.listdir(join(exchange, "abc101", "inbound"))
        username, assignment, timestamp1 = filename.split("+")
        assert username == os.environ["USER"]
        assert assignment == "ps1"
>       assert parse_utc(timestamp1) > now
E       assert datetime.datetime(2016, 4, 30, 13, 7, 24) > datetime.datetime(2016, 4, 30, 15, 7, 23, 47171)
E        +  where datetime.datetime(2016, 4, 30, 13, 7, 24) = parse_utc('2016-04-30 13:07:24 UTC')

/media/logan/External/Code_Dev/nbgrader/nbgrader/tests/apps/test_nbgrader_submit.py:70: AssertionError
------------------------------------------------------------------------------------------------------------------------- Captured stderr call --------------------------------------------------------------------------------------------------------------------------
[ReleaseApp | INFO] Source: /tmp/tmpjq63dfpt/release/./ps1
[ReleaseApp | INFO] Destination: /tmp/tmpttcirnu7/abc101/outbound/ps1
[ReleaseApp | INFO] Released as: abc101 ps1
[FetchApp | INFO] Source: /tmp/tmpttcirnu7/abc101/outbound/ps1
[FetchApp | INFO] Destination: /tmp/tmp84n05cwt/ps1
[FetchApp | INFO] Fetched as: abc101 ps1
[SubmitApp | INFO] Source: /tmp/tmp84n05cwt/ps1
[SubmitApp | INFO] Destination: /tmp/tmpttcirnu7/abc101/inbound/logan+ps1+2016-04-30 13:07:24 UTC
[SubmitApp | INFO] Submitted as: abc101 ps1 2016-04-30 13:07:24 UTC
!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!! Interrupted: stopping after 1 failures !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
================================================================================================================= 1 failed, 84 passed in 242.09 seconds =================================================================================================================

[jhamrick]

Hmm, that's odd. Thanks for reporting these. What version of linux are you running?

For the first issue, there are some dirty hacks in place to get it to capture coverage data when running subprocesses, so it's possible that your system is configured in a way that is making that not work. I know you said you installed this on a clean VM, but just to be extra sure you have the most up-to-date versions of everything, can you try running pip install -U -r dev-requirements -e . from the root of the repo and then trying to run the tests again?

For the second issue, that's a bizarre error. It's failling on:

assert datetime.datetime(2016, 4, 30, 13, 7, 24) > datetime.datetime(2016, 4, 30, 15, 7, 23, 47171)

Note that the second one (which is supposed to be an earlier date) is 15:7:23 while the first one is 13:7:24. I am not sure how it is possible that those dates are off by two hours. Can you rerun that test and let me know again:

1. What the dates it is comparing that it fails on
2. What the actual date and time it is when you run the test

I have heard that sometimes VMs have issues with the system clock running too fast or two slow. I don't know how that could cause issues with time going backwards, but maybe it's related?

[lgpage]

I'm running Ubuntu 14.04

For the first issue:
pip install -U -r dev-requirements.txt -e . does not update any packages.

For the second issue, i'm pretty sure this line:
now = datetime.datetime.now()
should be
now = datetime.datetime.utcnow()

[jhamrick]

Ah, that could very well be. That would explain why it passes on Travis (though it wouldn't explain why it passes on my laptop). I'll investigate...

[lgpage]

Unless your system is set to the same time zone as UTC.
I'm at a UTC+2 time zone.

[jhamrick]

Yeah, though my system isn't UTC. Anyway, I opened a PR to fix it (hopefully).

For the first issue still... I'm not sure, but let's try a few things. First, can you run the following in a python terminal (from the nbgrader directory in the virtualenv you're using):

import distutils.sysconfig, os
os.path.join(distutils.sysconfig.get_python_lib(), 'sitecustomize.py')

You should get something like '/Users/jhamrick/miniconda3/envs/nbgrader/lib/python3.5/site-packages/sitecustomize.py'. Then, can you let me know the contents of that file? Ideally, the should be:

### begin nbgrader changes
import coverage; coverage.process_startup()
### end nbgrader changes

[lgpage]

File location:
/home/logan/.virtualenvs/nbgrader-py35/lib/python3.5/site-packages/sitecustomize.py
Contents:

### begin nbgrader changes
import coverage; coverage.process_startup()
### end nbgrader changes

[lgpage]

Just an idea here, but would it not be a good idea to leverage tox to integrate local and travis testing?

[jhamrick]

Ok, so that's fine. Hrm.

Just an idea here, but would it not be a good idea to leverage tox to integrate local and travis testing?

Possibly; I haven't used tox before. I am not sure this issue would be resolved by something like that, though, since the command that is run on travis is exactly invoke tests (which is what you're running).

The issue here is that when you run a subprocess, coverage doesn't (by default) capture what lines are being executed in the subprocess. So, you have to configure python to run coverage with the subprocess, which involves a combination of ensuring it starts up (in the sitecustomize.py) and setting the COVERAGE_PROCESS_START environment variable. Both of those are setup correctly for you, so I'm a bit mystified why coverage doesn't seem to be running.

For the time being, I am going to at least just turn that error into a warning, because it doesn't make sense for the tests themselves to fail if coverage doesn't work (though the coverage tests should still fail -- which they will, if coverage is not being captured).

[lgpage]

Yeah this issue is rather weird. Travis == Ubuntu, so I would expect running the same set of command as travis should give the same results :P

From what I see, both methods
invoke tests and py.test -x -vv nbgrader/tests/apps/
start subprocesses, the only difference is invoke that sets the COVERAGE_PROCESS_START environment variable.

Also AFAIK pytest-cov already incorporates subprocess capturing. From the pytest-cov readme:

Centralised testing will report on the combined coverage of the main process and all of its subprocesses.

I also tested this and got coverage data even with the test failing:

$py.test -x -vv --cov nbgrader nbgrader/tests/apps/
.
.
.
Name                                                Stmts   Miss Branch BrPart  Cover
-------------------------------------------------------------------------------------
nbgrader/__init__.py                                    1      0      0      0   100%
nbgrader/__main__.py                                    2      2      0      0     0%
nbgrader/_version.py                                    2      0      0      0   100%
nbgrader/api.py                                       610    183     68      5    68%
nbgrader/apps/__init__.py                              16      0      0      0   100%
nbgrader/apps/assignapp.py                             76      3     26      4    93%
nbgrader/apps/autogradeapp.py                          98      2     26      1    98%
nbgrader/apps/baseapp.py                              347     30    126     21    88%
nbgrader/apps/collectapp.py                            76      4     34      5    92%
nbgrader/apps/extensionapp.py                         141     11     32     13    85%
nbgrader/apps/feedbackapp.py                           37      0      4      2    95%
nbgrader/apps/fetchapp.py                              34      2      8      2    90%
nbgrader/apps/formgradeapp.py                         103     55     16      0    40%
nbgrader/apps/listapp.py                              106      1     46      1    99%
nbgrader/apps/nbgraderapp.py                           54      0     14      2    97%
nbgrader/apps/quickstartapp.py                         55      0      6      0   100%
nbgrader/apps/releaseapp.py                            57      3     14      3    92%
nbgrader/apps/submitapp.py                             46      3     10      3    89%
nbgrader/apps/validateapp.py                           37      0      4      1    98%
nbgrader/auth/__init__.py                               4      0      0      0   100%
nbgrader/auth/base.py                                  22     12      0      0    45%
nbgrader/auth/hubauth.py                              143     99     44      0    24%
nbgrader/auth/noauth.py                                54     36     16      0    26%
nbgrader/formgrader/__init__.py                         0      0      0      0   100%
nbgrader/formgrader/apihandlers.py                     65     48      6      0    24%
nbgrader/formgrader/base.py                            54     35     12      0    29%
nbgrader/formgrader/handlers.py                       190    148     46      0    18%
nbgrader/nbextensions/__init__.py                       0      0      0      0   100%
nbgrader/nbextensions/assignment_list/__init__.py       1      1      0      0     0%
nbgrader/nbextensions/assignment_list/handlers.py      87     87     28      0     0%
nbgrader/preprocessors/__init__.py                     16      0      0      0   100%
nbgrader/preprocessors/base.py                          6      0      0      0   100%
nbgrader/preprocessors/checkcellmetadata.py            34      8     18      5    75%
nbgrader/preprocessors/clearoutput.py                   4      0      0      0   100%
nbgrader/preprocessors/clearsolutions.py               56      3     26      3    93%
nbgrader/preprocessors/computechecksums.py             10      0      4      0   100%
nbgrader/preprocessors/deduplicateids.py               18      2      4      1    86%
nbgrader/preprocessors/displayautogrades.py           113     57     62     10    41%
nbgrader/preprocessors/execute.py                      14      0      2      0   100%
nbgrader/preprocessors/getgrades.py                    30      0      4      0   100%
nbgrader/preprocessors/headerfooter.py                 23      6      4      2    70%
nbgrader/preprocessors/limitoutput.py                  40      9     18      3    79%
nbgrader/preprocessors/lockcells.py                    18      1      8      1    92%
nbgrader/preprocessors/overwritecells.py               64     25     26      4    54%
nbgrader/preprocessors/saveautogrades.py               36      0      8      0   100%
nbgrader/preprocessors/savecells.py                    92      3     28      3    95%
nbgrader/utils.py                                     125     16     72     14    83%
-------------------------------------------------------------------------------------
TOTAL                                                3217    895    870    109    69%

[lgpage]

Just an idea here, but would it not be a good idea to leverage tox to integrate local and travis testing?

Possibly; I haven't used tox before. I am not sure this issue would be resolved by something like that..

tox wont fix this problem, but it will allow for running the exact same commands locally as on travis for easier local testing, as well as allow for easier local testing on difference Python versions.

I would be happy to create a PR for this if you are interested.

[jhamrick]

From what I see, both methods invoke tests and py.test -x -vv nbgrader/tests/apps/ start subprocesses, the only difference is invoke that sets the COVERAGE_PROCESS_START environment variable.

Yep, that's right.

Also AFAIK pytest-cov already incorporates subprocess capturing. From the pytest-cov readme:

Yeah, that's what it says, but when I was setting it up I found it didn't work 😞 What I have set up is described here: http://coverage.readthedocs.io/en/coverage-4.0.3/subprocess.html

I also tested this and got coverage data even with the test failing

You'll definitely get some coverage, just not all coverage. Not all the code runs in subprocesses, so whatever is not in a subprocess will still get covered. You can compare your coverage results with for example what Travis gets, which is slightly higher: https://travis-ci.org/jupyter/nbgrader/jobs/126909947

tox wont fix this problem, but it will allow for running the exact same commands locally as on travis for easier local testing, as well as allow for easier local testing on difference Python versions.
I would be happy to create a PR for this if you are interested.

Well, the same commands are being run already (invoke tests --group="$GROUP" is what Travis runs) and there are only just some small differences in installation. I'm all for simplifying things, I just don't see at the moment how tox would simplify it much further than it already is. Also, do you know how tox will interact with conda envs? Conda is incompatible with virtualenv, so I don't want to introduce something that is going to require different workflows for people depending on whether they're using conda or not. That said, I am open to the idea, I just want to understand a bit better first what would change.