Sanic: Random Failures during tox run on Mac

[harshanarayana]

Describe the bug
When running Unit Test in local machine (mac), few test cases randomly fail and re-cover during re-run.

Error Output

# Test session starts (platform: darwin, Python 3.5.6, pytest 3.3.2, pytest-sugar 0.9.1)
    def test_default_server_error_request_timeout():
        client = DelayableSanicTestClient(request_timeout_default_app, None, 3)
        request, response = client.get('/1')
>       assert response.status == 408
E       assert 200 == 408
E        +  where 200 = <test_request_timeout.DelayableTCPConnector.RequestContextManager object at 0x10723ccf8>.status
tests/test_request_timeout.py:194: AssertionError

# Test session starts (platform: darwin, Python 3.7.0, pytest 3.3.2, pytest-sugar 0.9.1)
    def test_default_server_error_request_timeout():
        client = DelayableSanicTestClient(request_timeout_default_app, None, 3)
        request, response = client.get('/1')
>       assert response.status == 408
E       assert 200 == 408
E        +  where 200 = <test_request_timeout.DelayableTCPConnector.RequestContextManager object at 0x112d87470>.status
tests/test_request_timeout.py:194: AssertionError

# py37-no-ext develop-inst-nodeps: <path>
# py37-no-ext installed: aiofiles==0.4.0,aiohttp==3.2.1,async-generator==1.10,async-timeout==3.0.1,attrs==18.2.0,beautifulsoup4==4.6.3,chardet==2.3.0,coverage==4.5.1,gunicorn==19.9.0,httptools==0.0.11,idna==2.7,multidict==4.4.2,pluggy==0.6.0,py==1.7.0,pytest==3.3.2,pytest-cov==2.6.0,pytest-sanic==0.1.13,pytest-sugar==0.9.1,-e [email protected]:harshanarayana/sanic.git@e3a27c2cc485d57aa1ff87d9f69098e4ab12727e#egg=sanic,six==1.11.0,termcolor==1.1.0,websockets==6.0,yarl==1.2.6
# py37-no-ext run-test-pre: PYTHONHASHSEED='27345397'
# py37-no-ext runtests: commands[0] | pytest tests --cov sanic --cov-report=
# Test session starts (platform: darwin, Python 3.7.0, pytest 3.3.2, pytest-sugar 0.9.1)E       AssertionError: assert {'Connection'...p-Alive': '2'} == {'Connection':...p-Alive': '2'}
E         Omitting 3 identical items, use -vv to show
E         Differing items:
E         {'Content-Length': '12'} != {'Content-Length': '11'}

Code snippet
NA

Expected behavior
Existing Unit Tests to pass in all Virtual env during tox execution.

Environment (please complete the following information):

• OS: macOS Mojave
• Version 10.14 (18A391)

Additional context
NA

[vltr]

This happens on my system too, exactly the same error - and I use Arch Linux, so it's not an OS problem :unamused:

[harshanarayana]

@vltr Well, good to know that I am not the only one who runs into this issue. Btw, can we tweak the test that checks the Content-Length a bit to avoid getting the last error? We can see if it exists in a range of values as well. right ?

[yunstanford]

Yeah, these tests are pretty flakey. @ashleysommer may have more context.

[ashleysommer]

Is there any way to reliably make them fail?

I've run them a few times on my main PC (Ubuntu 18.10), my work PC (Ubuntu 18.04) and my Laptop (Fedora 27), but I can't get them to fail at all.

[harshanarayana]

@ashleysommer
The only issue I can consistently reproduce in my machine is the one where it tries to match the Content-Length. (i.e. {'Content-Length': '12'} != {'Content-Length': '11'})

But this happens only in case of py37-no-ext env and not in py37. Which is surprising to me. Wonder if it has anything to do with the missing ujson installation in py37-no-ext

[ashleysommer]

Ah, I only have python 3.6 (not 3.7) so my system doesn't run the py37 tests.

[yunstanford]

These tests are also flakey with Python3.6 on MacOS

[harshanarayana]

@vltr @ashleysommer @yunstanford Pardon my silly question, but shouldn't the content length value be same irrespective of what platform you are running in?

[vltr]

I confirm the reports from @harshanarayana regarding py37-no-ext.

The problem is: under ujson, an object dumps doesn't create a space between colons :, while the Python json module does it (and after commas , too):

>>> import json
>>> import ujson
>>> json.dumps({"hello": "world", "foo": "bar"})
'{"hello": "world", "foo": "bar"}'
>>> ujson.dumps({"hello": "world", "foo": "bar"})
'{"hello":"world","foo":"bar"}'

To fix that, you just need to tell the json module to not add these spaces after colons:

>>> json.dumps({"hello": "world", "foo": "bar"}, separators=(',', ':'))
'{"hello":"world","foo":"bar"}'

I think a minor PR should fix that in responses.py using functools.partial :wink:, basically:

    from json import dumps as _json_dumps
    json_dumps = partial(_json_dumps, separators=(',', ':'))

[harshanarayana]

@vltr Creating a PR with modified Test cases in a while. Saved me the effort of debugging the issue. :)

[vltr]

@harshanarayana great! I'm glad to help, I'm just sorry I don't have the proper time right now to provide this PR myself ...

[harshanarayana]

@vltr

 py35: commands succeeded
  py36: commands succeeded
  py37: commands succeeded
  py35-no-ext: commands succeeded
  py36-no-ext: commands succeeded
  py37-no-ext: commands succeeded
  lint: commands succeeded
  check: commands succeeded
  congratulations :)

Looks so good 😀

[vltr]

Oh yeah! :metal:

[harshanarayana]

@vltr @ashleysommer Found another odd behavior with the tox env setup.
If you look at the setup.py, if SANIC_NO_UJSON is set, then the ujson module won't be installed.

setenv =
    {py35,py36,py37}-no-ext: SANIC_NO_UJSON=1
    {py35,py36,py37}-no-ext: SANIC_NO_UVLOOP=1

However, the ujson in available in py35-no-ext. Which shouldn't happen.

➜ .tox/py37-no-ext/bin/python
Python 3.7.0 (default, Aug 22 2018, 15:22:33)
[Clang 9.1.0 (clang-902.0.39.2)] on darwin
Type "help", "copyright", "credits" or "license" for more information.
>>> import ujson
Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
ModuleNotFoundError: No module named 'ujson'
>>>

➜ .tox/py36-no-ext/bin/python
Python 3.6.7 |Anaconda, Inc.| (default, Oct 23 2018, 14:01:38)
[GCC 4.2.1 Compatible Clang 4.0.1 (tags/RELEASE_401/final)] on darwin
Type "help", "copyright", "credits" or "license" for more information.
>>> import ujson
Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
ModuleNotFoundError: No module named 'ujson'
>>>

➜ .tox/py35-no-ext/bin/python
Python 3.5.6 (default, Sep 29 2018, 20:32:14)
[GCC 4.2.1 Compatible Apple LLVM 10.0.0 (clang-1000.11.45.2)] on darwin
Type "help", "copyright", "credits" or "license" for more information.
>>> import ujson
>>>

[vltr]

That's odd, but sort of explains why only Python 3.6 and 3.7 -no-ext were failing in tox ... Does it installs uvloop on Python 3.5 too?

[harshanarayana]

@vltr Yes, it does. Both uvloop and ujson are available under py35-no-ext

[vltr]

@harshanarayana perhaps this part of setup.py is not working as expected under Python 3.5?

[harshanarayana]

@vltr Nope. It's working exactly the same way across all 3 *-no-ext environments. However, I cleaned up the *-no-ext and re-ran the tox and now, ujson is missing in all 3 as expected but uvloop is in py35-no-ext but no in other two -no-ext environments

[vltr]

@harshanarayana that's weird (and random). Tomorrow I'll take a look directly into some clean environments to check what may be happening with Python 3.5 ...

[vltr]

@harshanarayana somehow, if I execute only the -no-ext tests, uvloop and ujson end up being installed into the Python 3.5 environment (through tox). No matter what (and how) I call [tox], ujson and uvloop will be in that environment. I'm digging a little bit deeper now into what happens with tox and the environment variables set to not install these dependencies being ignored in Python 3.5.

$ TOXENV={py35,py36,py37}-no-ext tox -v

[ truncated ]

  py35-no-ext: commands succeeded
ERROR:   py36-no-ext: commands failed
ERROR:   py37-no-ext: commands failed

$ ./.tox/py37-no-ext/bin/python        
Python 3.7.1 (default, Oct 22 2018, 10:41:28) 
[GCC 8.2.1 20180831] on linux
Type "help", "copyright", "credits" or "license" for more information.
>>> import uvloop
Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
ModuleNotFoundError: No module named 'uvloop'
>>> import ujson
Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
ModuleNotFoundError: No module named 'ujson'
>>> exit()

$ ./.tox/py36-no-ext/bin/python
Python 3.6.7 (default, Nov  8 2018, 10:37:02) 
[GCC 8.2.1 20180831] on linux
Type "help", "copyright", "credits" or "license" for more information.
>>> import ujson
Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
ModuleNotFoundError: No module named 'ujson'
>>> import uvloop
Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
ModuleNotFoundError: No module named 'uvloop'
>>> exit()

$ ./.tox/py35-no-ext/bin/python        
Python 3.5.6 (default, Oct 13 2018, 16:17:36) 
[GCC 8.2.1 20180831] on linux
Type "help", "copyright", "credits" or "license" for more information.
>>> import uvloop
>>> import ujson
>>> exit()

$ ls -la .tox                          
total 28K
drwxr-xr-x  7 richard richard 4.0K Nov  8 13:48 ./
drwxr-xr-x 11 richard richard 4.0K Nov  8 13:49 ../
drwxr-xr-x  2 richard richard 4.0K Nov  8 13:47 log/
drwxr-xr-x  7 richard richard 4.0K Nov  8 13:47 py35-no-ext/
drwxr-xr-x  7 richard richard 4.0K Nov  8 13:48 py36-no-ext/
drwxr-xr-x  7 richard richard 4.0K Nov  8 13:48 py37-no-ext/
drwxr-xr-x  2 richard richard 4.0K Nov  8 13:47 .tmp/

[harshanarayana]

@vltr I did the same thing with no luck. I even tried the pipdeptree to analyze the dependencies of where the module comes by running the --reverse --packages mode, but uvloop just seems to appear out of nowhere. It doesn't come from any parent dependency!

[vltr]

@harshanarayana exactly. Something is not right and I'll find out soon :wink:

[harshanarayana]

@vltr Please do let me know if there is anything I can do to help your investigation into this criminal matter. 😉

[vltr]

Will do ... Because this is getting stranger and stranger ...

[ahopkins]

@vltr when in doubt.... blame it on the gremlins.

[vltr]

@ahopkins yeah, well, it's starting to rain in here, so ...

More fun stuff (inside the Sanic repository using pip-tools):

$ pip-compile -r
#
# This file is autogenerated by pip-compile
# To update, run:
#
#    pip-compile --output-file requirements.txt setup.py
#
aiofiles==0.4.0
httptools==0.0.11
multidict==4.4.2
ujson==1.35 ; sys_platform != "win32" and implementation_name == "cpython"
uvloop==0.11.3 ; sys_platform != "win32" and implementation_name == "cpython"
websockets==5.0.1

$ SANIC_NO_UJSON=1 SANIC_NO_UVLOOP=1 pip-compile -r
Installing without uJSON
Installing without uvLoop
#
# This file is autogenerated by pip-compile
# To update, run:
#
#    pip-compile --output-file requirements.txt setup.py
#
aiofiles==0.4.0
httptools==0.0.11
multidict==4.4.2
websockets==5.0.1

$ python --version                         
Python 3.5.6

[vltr]

I finally found the problem :sweat:

$ TOXENV={py35,py36,py37}-no-ext tox -v
[ truncated ]
ERROR:   py35-no-ext: commands failed
ERROR:   py36-no-ext: commands failed
ERROR:   py37-no-ext: commands failed

$ ./.tox/py35-no-ext/bin/python    
Python 3.5.6 (default, Oct 13 2018, 16:17:36) 
[GCC 8.2.1 20180831] on linux
Type "help", "copyright", "credits" or "license" for more information.
>>> import ujson
Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
ImportError: No module named 'ujson'
>>> import uvloop
Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
ImportError: No module named 'uvloop'
>>> exit()

Even the full test is now reporting "correctly" (prior to PR #1403):

$ tox -v
[ truncated ]
  py35: commands succeeded
  py36: commands succeeded
  py37: commands succeeded
ERROR:   py35-no-ext: commands failed
ERROR:   py36-no-ext: commands failed
ERROR:   py37-no-ext: commands failed
ERROR:   flake8: commands failed
  check: commands succeeded

How? Dead simple. The problem is here. When installing pytest-sanic as a test dependency, it will try to install what? Sanic. For some reason, under Python 3.5, the SANIC_NO_UVLOOP and SANIC_NO_UJSON environment variables aren't broadcast when tox installs pytest-sanic ... So it ends up requiring Sanic, which requires and installs uvloop and ujson :unamused:

This is way too random. Maybe because pytest-sanic has Python 3.5 inside its setup classifiers? I don't really know :confused:

I tried to set passenv inside tox.ini, set with SANIC_NO_UJSON and SANIC_NO_UVLOOP, with no luck as well:

$ tox -v
[ truncated ]
  py35: commands succeeded
  py36: commands succeeded
  py37: commands succeeded
  py35-no-ext: commands succeeded
ERROR:   py36-no-ext: commands failed
ERROR:   py37-no-ext: commands failed
ERROR:   flake8: commands failed
  check: commands succeeded

Anyway, here's pip freeze under the tox environment with pytest-sanic in tox.ini (as it is today):

$ ./.tox/py35-no-ext/bin/pip freeze                                                 
aiofiles==0.4.0
aiohttp==3.2.1
async-generator==1.10
async-timeout==3.0.1
attrs==18.2.0
beautifulsoup4==4.6.3
chardet==2.3.0
coverage==4.5.1
gunicorn==19.9.0
httptools==0.0.11
idna==2.7
idna-ssl==1.1.0
multidict==4.4.2
pluggy==0.6.0
py==1.7.0
pytest==3.3.2
pytest-cov==2.6.0
pytest-sanic==0.1.13
pytest-sugar==0.9.1
-e [email protected]:vltr/sanic.git@1498baab0fd0e4799b228b32d73675848f0ac680#egg=sanic
six==1.11.0
termcolor==1.1.0
ujson==1.35
uvloop==0.11.3
websockets==5.0.1
yarl==1.2.6

And here's pip freeze under the tox environment without pytest-sanic (that's not even used in testing afaik):

$ ./.tox/py35-no-ext/bin/pip freeze                                                 
aiofiles==0.4.0
aiohttp==3.2.1
async-timeout==3.0.1
attrs==18.2.0
beautifulsoup4==4.6.3
chardet==2.3.0
coverage==4.5.1
gunicorn==19.9.0
httptools==0.0.11
idna==2.7
idna-ssl==1.1.0
multidict==4.4.2
pluggy==0.6.0
py==1.7.0
pytest==3.3.2
pytest-cov==2.6.0
pytest-sugar==0.9.1
-e [email protected]:vltr/sanic.git@1498baab0fd0e4799b228b32d73675848f0ac680#egg=sanic
six==1.11.0
termcolor==1.1.0
websockets==5.0.1
yarl==1.2.6

That was a needle in a hay.

@yunstanford should we just remove pytest-sanic as a test dependency from Tox? IMHO it creates a circular dependency as well ...

[harshanarayana]

@vltr Wow. That's some detailed analysis. Thanks for doing this.

If we want to keep pytest-sanic but avoid the cyclic dependency, we just keep sanic as a dev dependency in pytest-sanic and the regular installation expects sanic to pre-exist. That way, it won't force install anything during the usage and if you are developing pytest-sanic you always use the latest stable sanic base.. Would that make more sense?

[vltr]

@harshanarayana Erm ... I might need to disagree. I think that no software should have a circular dependency in any stage, and I'm going to make a PR for that matter.

As for pytest-sanic, I think it is almost inherit that you should need Sanic to test your application, so you would probably already have Sanic as a dependency in your project. I see no need in adding Sanic as a install_dependency, using a warning or raising an error in case Sanic is not present, but ... That's just my two cents.

[vltr]

Removing pytest-sanic from tox.ini in the current master just unleashed hell. We need to address this another way. I'll update this issue on that matter as soon as I figure out something.

[harshanarayana]

@vltr Now that you found the root cause for the problem, let me see what we can do to fix the problem as well. I'm sure we can come up with something.

[vltr]

@harshanarayana don't worry, I already addressed the issue with the core-devs to find the best solution - IMO pytest-sanic should not be a dependency in Sanic in any way, but let's see what we can come out with.

[harshanarayana]

@vltr If we remove sanic as a dependency from pytest-sanic under it's install_requires, pytest-sanic will not bother about sanic during the installation. That should address the circular dependency issue you were talking about before.

So, now that we are only going to use the sanic we have in our cloned repo for everything, if the right env variables for SANIC_NO_UJSON and SANIC_NO_UVLOOP gets passed into tox that should fix our main problem.

[harshanarayana]

@vltr Great. Thank you very much for the help. 🏆

[vltr]

@harshanarayana it is I that should thank you for bringing this up, it really unfolded a very tricky situation that needs to be solved :wink:

[yunstanford]

pytest-sanic is not a direct dependency of Sanic, it's test dependency, it won't show up when anyone installs Sanic. Also Sanic test_client is error-prone and can't test multiple cases, e.g. It brings up a server and tears it down for each single request call, all requests are actually hitting "different" servers. If any test case need to involve two/or more consecutive requests and assert/verify some app related stuff, it'll not work.

[yunstanford]

But I don't have strong opinion here, i'm fine to remove pytest-sanic.

[vltr]

@yunstanford I know pytest-sanic is not a direct dependency of Sanic, but it's part of the development process (as being a test dependency). If Sanic test_client is error prone, then we should make it work or change pytest-sanic so it'll act as an utility tool (without explicitly requiring Sanic). Otherwise, we will not be able to guarantee our testing environments, and that's a big problem.

Since we are talking about this, why not bring pytest-sanic under the huge-success "umbrella"?

[yunstanford]

removing Sanic from pytest-sanic's install_requires sounds reasonable.

I'm fine with moving the repo when we come up a proposal for bringing up all Sanic related projects together and also how we maintains them.

[vltr]

@yunstanford great, we can sleep on that and think about proposals for the future :wink:

[vltr]

@yunstanford , thanks for "fixing" pytest-sanic regarding this issue. I'll bring up the matter for bringing some Sanic related projects (that are really a plus to have, like yours) into the huge-success umbrella :wink:

[vltr]

@sjsadowski @yunstanford I think we can close this issue by now.

[harshanarayana]

@vltr I can confirm that these random intermittent errors are seen no more. We can close this issue (The original issue I reported are all sorted). Thanks, everyone for the help :)