ChannesLiveServerTestcase hanging

[dgilge]

Here's another issue I encountered...

What I expected to happen vs. what actually happened

This test should pass:

from channels.testing.live import ChannelsLiveServerTestCase
from selenium.webdriver.firefox.webdriver import WebDriver

class LiveTests(ChannelsLiveServerTestCase):
    @classmethod
    def setUpClass(cls):
        super().setUpClass()
        cls.selenium = WebDriver()
        cls.selenium.implicitly_wait(5)

    @classmethod
    def tearDownClass(cls):
        cls.selenium.quit()
        super().tearDownClass()

    def test_pass(self):
        pass

But it is hanging. Firefox opens and then nothing happens. In my "real" test it shows no URL and no content. I have to cancel the test.

You can even remove the selenium code showing the same behavior:

from channels.testing.live import ChannelsLiveServerTestCase

class LiveTests(ChannelsLiveServerTestCase):
    def test_pass(self):
        pass

It works with Channels 2.0.2 though. Therefore I think the issue is related to Channels somehow.

OS and runtime environment, and browser

MacOS Sierra 10.12.6, Firefox 58.0.2

The versions of Channels, Daphne, Django, Twisted, and your ASGI backend (channels_redis normally)

my-app==0.0.0
  - channels [required: ~=2.0, installed: 2.0.2] - Using the newest code base from GitHub
    - asgiref [required: ~=2.1, installed: 2.2.0] - Using the newest code base from GitHub
      - async-timeout [required: ~=2.0, installed: 2.0.0]
    - daphne [required: ~=2.0, installed: 2.1.0]
      - autobahn [required: >=0.18, installed: 18.3.1]
        - six [required: >=1.10.0, installed: 1.11.0]
        - txaio [required: >=2.7.0, installed: 2.9.0]
          - six [required: Any, installed: 1.11.0]
      - twisted [required: >=17.5, installed: 17.9.0]
        - Automat [required: >=0.3.0, installed: 0.6.0]
          - attrs [required: Any, installed: 17.4.0]
          - six [required: Any, installed: 1.11.0]
        - constantly [required: >=15.1, installed: 15.1.0]
        - hyperlink [required: >=17.1.1, installed: 18.0.0]
          - idna [required: >=2.5, installed: 2.6]
        - incremental [required: >=16.10.1, installed: 17.5.0]
        - zope.interface [required: >=4.0.2, installed: 4.4.3]
          - setuptools [required: Any, installed: 38.5.2]
    - Django [required: >=1.11, installed: 2.0.3]
      - pytz [required: Any, installed: 2018.3]
  - django [required: ~=2.0, installed: 2.0.3]
    - pytz [required: Any, installed: 2018.3]
psycopg2==2.7.4
pytest-asyncio==0.8.0
  - pytest [required: >=3.0.6, installed: 3.4.2]
    - attrs [required: >=17.2.0, installed: 17.4.0]
    - pluggy [required: >=0.5,<0.7, installed: 0.6.0]
    - py [required: >=1.5.0, installed: 1.5.2]
    - setuptools [required: Any, installed: 38.5.2]
    - six [required: >=1.10.0, installed: 1.11.0]
pytest-django==3.1.2
  - pytest [required: >=2.9, installed: 3.4.2]
    - attrs [required: >=17.2.0, installed: 17.4.0]
    - pluggy [required: >=0.5,<0.7, installed: 0.6.0]
    - py [required: >=1.5.0, installed: 1.5.2]
    - setuptools [required: Any, installed: 38.5.2]
    - six [required: >=1.10.0, installed: 1.11.0]
selenium==3.10.0

How I'm running Channels

pytest

Console logs and full tracebacks of any errors

pipenv run pytest tests/tests_selenium.py  --fulltrace
======================================= test session starts ========================================
platform darwin -- Python 3.6.4, pytest-3.4.2, py-1.5.2, pluggy-0.6.0
Django settings: tests.settings (from ini file)
rootdir: /Users/Daniel/git/my-app, inifile: setup.cfg
plugins: django-3.1.2, asyncio-0.8.0
collected 1 item                                                                                   

tests/tests_selenium.py ^C

!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!! KeyboardInterrupt !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!

config = <_pytest.config.Config object at 0x10d803c18>, doit = <function _main at 0x10d744620>

    def wrap_session(config, doit):
        """Skeleton command line program"""
        session = Session(config)
        session.exitstatus = EXIT_OK
        initstate = 0
        try:
            try:
                config._do_configure()
                initstate = 1
                config.hook.pytest_sessionstart(session=session)
                initstate = 2
>               session.exitstatus = doit(config, session) or 0

/Users/daniel/.local/share/virtualenvs/env/lib/python3.6/site-packages/_pytest/main.py:100: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

config = <_pytest.config.Config object at 0x10d803c18>
session = <Session 'my-app'>

    def _main(config, session):
        """ default command line protocol for initialization, session,
        running tests and reporting. """
        config.hook.pytest_collection(session=session)
>       config.hook.pytest_runtestloop(session=session)

/Users/daniel/.local/share/virtualenvs/env/lib/python3.6/site-packages/_pytest/main.py:138: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

self = <_HookCaller 'pytest_runtestloop'>, args = ()
kwargs = {'session': <Session 'my-app'>}, notincall = set()

    def __call__(self, *args, **kwargs):
        if args:
            raise TypeError("hook calling supports only keyword arguments")
        assert not self.is_historic()
        if self.argnames:
            notincall = set(self.argnames) - set(['__multicall__']) - set(
                kwargs.keys())
            if notincall:
                warnings.warn(
                    "Argument(s) {} which are declared in the hookspec "
                    "can not be found in this hook call"
                    .format(tuple(notincall)),
                    stacklevel=2,
                )
>       return self._hookexec(self, self._nonwrappers + self._wrappers, kwargs)

/Users/daniel/.local/share/virtualenvs/env/lib/python3.6/site-packages/pluggy/__init__.py:617: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

self = <_pytest.config.PytestPluginManager object at 0x10d0c0f60>
hook = <_HookCaller 'pytest_runtestloop'>
methods = [<pluggy.HookImpl object at 0x10d815748>, <pluggy.HookImpl object at 0x10f4e47f0>]
kwargs = {'session': <Session 'my-app'>}

    def _hookexec(self, hook, methods, kwargs):
        # called from all hookcaller instances.
        # enable_tracing will set its own wrapping function at self._inner_hookexec
>       return self._inner_hookexec(hook, methods, kwargs)

/Users/daniel/.local/share/virtualenvs/env/lib/python3.6/site-packages/pluggy/__init__.py:222: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

hook = <_HookCaller 'pytest_runtestloop'>
methods = [<pluggy.HookImpl object at 0x10d815748>, <pluggy.HookImpl object at 0x10f4e47f0>]
kwargs = {'session': <Session 'my-app'>}

    self._inner_hookexec = lambda hook, methods, kwargs: \
        hook.multicall(
            methods, kwargs,
>           firstresult=hook.spec_opts.get('firstresult'),
        )

/Users/daniel/.local/share/virtualenvs/env/lib/python3.6/site-packages/pluggy/__init__.py:216: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

session = <Session 'my-app'>

    def pytest_runtestloop(session):
        if (session.testsfailed and
                not session.config.option.continue_on_collection_errors):
            raise session.Interrupted(
                "%d errors during collection" % session.testsfailed)
    
        if session.config.option.collectonly:
            return True
    
        for i, item in enumerate(session.items):
            nextitem = session.items[i + 1] if i + 1 < len(session.items) else None
>           item.config.hook.pytest_runtest_protocol(item=item, nextitem=nextitem)

/Users/daniel/.local/share/virtualenvs/env/lib/python3.6/site-packages/_pytest/main.py:161: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

self = <_HookCaller 'pytest_runtest_protocol'>, args = ()
kwargs = {'item': <TestCaseFunction 'test_pass'>, 'nextitem': None}, notincall = set()

    def __call__(self, *args, **kwargs):
        if args:
            raise TypeError("hook calling supports only keyword arguments")
        assert not self.is_historic()
        if self.argnames:
            notincall = set(self.argnames) - set(['__multicall__']) - set(
                kwargs.keys())
            if notincall:
                warnings.warn(
                    "Argument(s) {} which are declared in the hookspec "
                    "can not be found in this hook call"
                    .format(tuple(notincall)),
                    stacklevel=2,
                )
>       return self._hookexec(self, self._nonwrappers + self._wrappers, kwargs)

/Users/daniel/.local/share/virtualenvs/env/lib/python3.6/site-packages/pluggy/__init__.py:617: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

self = <_pytest.config.PytestPluginManager object at 0x10d0c0f60>
hook = <_HookCaller 'pytest_runtest_protocol'>
methods = [<pluggy.HookImpl object at 0x10d826518>, <pluggy.HookImpl object at 0x10d826e80>, <pluggy.HookImpl object at 0x10d90e7f0>]
kwargs = {'item': <TestCaseFunction 'test_pass'>, 'nextitem': None}

    def _hookexec(self, hook, methods, kwargs):
        # called from all hookcaller instances.
        # enable_tracing will set its own wrapping function at self._inner_hookexec
>       return self._inner_hookexec(hook, methods, kwargs)

/Users/daniel/.local/share/virtualenvs/env/lib/python3.6/site-packages/pluggy/__init__.py:222: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

hook = <_HookCaller 'pytest_runtest_protocol'>
methods = [<pluggy.HookImpl object at 0x10d826518>, <pluggy.HookImpl object at 0x10d826e80>, <pluggy.HookImpl object at 0x10d90e7f0>]
kwargs = {'item': <TestCaseFunction 'test_pass'>, 'nextitem': None}

    self._inner_hookexec = lambda hook, methods, kwargs: \
        hook.multicall(
            methods, kwargs,
>           firstresult=hook.spec_opts.get('firstresult'),
        )

/Users/daniel/.local/share/virtualenvs/env/lib/python3.6/site-packages/pluggy/__init__.py:216: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

item = <TestCaseFunction 'test_pass'>, nextitem = None

    def pytest_runtest_protocol(item, nextitem):
        item.ihook.pytest_runtest_logstart(
            nodeid=item.nodeid, location=item.location,
        )
>       runtestprotocol(item, nextitem=nextitem)

/Users/daniel/.local/share/virtualenvs/env/lib/python3.6/site-packages/_pytest/runner.py:62: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

item = <TestCaseFunction 'test_pass'>, log = True, nextitem = None

    def runtestprotocol(item, log=True, nextitem=None):
        hasrequest = hasattr(item, "_request")
        if hasrequest and not item._request:
            item._initrequest()
        rep = call_and_report(item, "setup", log)
        reports = [rep]
        if rep.passed:
            if item.config.option.setupshow:
                show_test_item(item)
            if not item.config.option.setuponly:
>               reports.append(call_and_report(item, "call", log))

/Users/daniel/.local/share/virtualenvs/env/lib/python3.6/site-packages/_pytest/runner.py:79: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

item = <TestCaseFunction 'test_pass'>, when = 'call', log = True, kwds = {}

    def call_and_report(item, when, log=True, **kwds):
>       call = call_runtest_hook(item, when, **kwds)

/Users/daniel/.local/share/virtualenvs/env/lib/python3.6/site-packages/_pytest/runner.py:158: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

item = <TestCaseFunction 'test_pass'>, when = 'call', kwds = {}, hookname = 'pytest_runtest_call'

    def call_runtest_hook(item, when, **kwds):
        hookname = "pytest_runtest_" + when
        ihook = getattr(item.ihook, hookname)
>       return CallInfo(lambda: ihook(item=item, **kwds), when=when)

/Users/daniel/.local/share/virtualenvs/env/lib/python3.6/site-packages/_pytest/runner.py:178: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

self = <[AttributeError("'CallInfo' object has no attribute 'result'") raised in repr()] CallInfo object at 0x10f67b208>
func = <function call_runtest_hook.<locals>.<lambda> at 0x10f793ea0>, when = 'call'

    def __init__(self, func, when):
        #: context of invocation: one of "setup", "call",
        #: "teardown", "memocollect"
        self.when = when
        self.start = time()
        try:
>           self.result = func()

/Users/daniel/.local/share/virtualenvs/env/lib/python3.6/site-packages/_pytest/runner.py:192: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

>   return CallInfo(lambda: ihook(item=item, **kwds), when=when)

/Users/daniel/.local/share/virtualenvs/env/lib/python3.6/site-packages/_pytest/runner.py:178: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

self = <_HookCaller 'pytest_runtest_call'>, args = ()
kwargs = {'item': <TestCaseFunction 'test_pass'>}, notincall = set()

    def __call__(self, *args, **kwargs):
        if args:
            raise TypeError("hook calling supports only keyword arguments")
        assert not self.is_historic()
        if self.argnames:
            notincall = set(self.argnames) - set(['__multicall__']) - set(
                kwargs.keys())
            if notincall:
                warnings.warn(
                    "Argument(s) {} which are declared in the hookspec "
                    "can not be found in this hook call"
                    .format(tuple(notincall)),
                    stacklevel=2,
                )
>       return self._hookexec(self, self._nonwrappers + self._wrappers, kwargs)

/Users/daniel/.local/share/virtualenvs/env/lib/python3.6/site-packages/pluggy/__init__.py:617: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

self = <_pytest.config.PytestPluginManager object at 0x10d0c0f60>
hook = <_HookCaller 'pytest_runtest_call'>
methods = [<pluggy.HookImpl object at 0x10d8264a8>, <pluggy.HookImpl object at 0x10dfb0588>, <pluggy.HookImpl object at 0x10f4e4710>]
kwargs = {'item': <TestCaseFunction 'test_pass'>}

    def _hookexec(self, hook, methods, kwargs):
        # called from all hookcaller instances.
        # enable_tracing will set its own wrapping function at self._inner_hookexec
>       return self._inner_hookexec(hook, methods, kwargs)

/Users/daniel/.local/share/virtualenvs/env/lib/python3.6/site-packages/pluggy/__init__.py:222: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

hook = <_HookCaller 'pytest_runtest_call'>
methods = [<pluggy.HookImpl object at 0x10d8264a8>, <pluggy.HookImpl object at 0x10dfb0588>, <pluggy.HookImpl object at 0x10f4e4710>]
kwargs = {'item': <TestCaseFunction 'test_pass'>}

    self._inner_hookexec = lambda hook, methods, kwargs: \
        hook.multicall(
            methods, kwargs,
>           firstresult=hook.spec_opts.get('firstresult'),
        )

/Users/daniel/.local/share/virtualenvs/env/lib/python3.6/site-packages/pluggy/__init__.py:216: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

item = <TestCaseFunction 'test_pass'>

    def pytest_runtest_call(item):
        _update_current_test_var(item, 'call')
        try:
>           item.runtest()

/Users/daniel/.local/share/virtualenvs/env/lib/python3.6/site-packages/_pytest/runner.py:109: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

self = <TestCaseFunction 'test_pass'>

    def runtest(self):
        if self.config.pluginmanager.get_plugin("pdbinvoke") is None:
>           self._testcase(result=self)

/Users/daniel/.local/share/virtualenvs/env/lib/python3.6/site-packages/_pytest/unittest.py:174: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

self = <tests.tests_selenium.LiveTests testMethod=test_pass>
result = <TestCaseFunction 'test_pass'>

    def __call__(self, result=None):
        """
            Wrapper around default __call__ method to perform common Django test
            set up. This means that user-defined Test Cases aren't required to
            include a call to super().setUp().
            """
        testMethod = getattr(self, self._testMethodName)
        skipped = (
            getattr(self.__class__, "__unittest_skip__", False) or
            getattr(testMethod, "__unittest_skip__", False)
        )
    
        if not skipped:
            try:
>               self._pre_setup()

/Users/daniel/.local/share/virtualenvs/env/lib/python3.6/site-packages/django/test/testcases.py:202: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

self = <tests.tests_selenium.LiveTests testMethod=test_pass>

    def _pre_setup(self):
        for connection in connections.all():
            if self._is_in_memory_db(connection):
                raise ImproperlyConfigured(
                    "ChannelLiveServerTestCase can not be used with in memory databases"
                )
    
        super(ChannelsLiveServerTestCase, self)._pre_setup()
    
        self._server_process = self.ProtocolServerProcess(
            self.host,
            get_default_application(),
        )
        self._server_process.start()
>       self._server_process.ready.wait()

/Users/daniel/.local/share/virtualenvs/env/lib/python3.6/site-packages/channels/testing/live.py:43: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

self = <multiprocessing.synchronize.Event object at 0x10faa2f28>, timeout = None

    def wait(self, timeout=None):
        with self._cond:
            if self._flag.acquire(False):
                self._flag.release()
            else:
>               self._cond.wait(timeout)

/usr/local/Cellar/python/3.6.4_3/Frameworks/Python.framework/Versions/3.6/lib/python3.6/multiprocessing/synchronize.py:361: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

self = <Condition(<Lock(owner=unknown)>, unknown)>, timeout = None

    def wait(self, timeout=None):
        assert self._lock._semlock._is_mine(), \
               'must acquire() condition before using wait()'
    
        # indicate that this thread is going to sleep
        self._sleeping_count.release()
    
        # release lock
        count = self._lock._semlock._count()
        for i in range(count):
            self._lock.release()
    
        try:
            # wait for notification or timeout
>           return self._wait_semaphore.acquire(True, timeout)
E           KeyboardInterrupt

/usr/local/Cellar/python/3.6.4_3/Frameworks/Python.framework/Versions/3.6/lib/python3.6/multiprocessing/synchronize.py:262: KeyboardInterrupt
================================== no tests ran in 12.25 seconds ===================================

[andrewgodwin]

If the empty test case is hanging, then that's the actual fault here, so I will ignore Selenium for now. Locally, I can get a similar test to pass:

class SomeLiveTests(ChannelsLiveServerTestCase):

    def test_live_stuff(self):
        print(self.live_server_url)

And this is, of course, on the newest master of all the packages. Did you say this only happens on channels master, not channels 2.0.2? If so, is it possible you could bisect and work out which commit does it?

[dgilge]

Yes, it's not Selenium. I don't know if you had seen that I updated my post to exclude it.

The empty test case (pass) is not the issue. It happens with any content (it is never called). I just wanted to make the test as simple as possible.

The first commit where the test doesn't pass any more is (as I assumed) 15f8b7d.

[andrewgodwin]

Alright, so it's likely something with the multiprocessing code that is failing under Mac OS. Can you try the following?

• Is there a second forked Python process running when it's hanging? (i.e. did multiprocessing at least make its new process?)
• If you can, does the exact same codebase + selenium-less test work under a Linux VM/on a Linux server?

[dgilge]

This is what I found out so far:

MacOS: I couldn't see that another python/pytest process was started during the test.

Ubuntu (17.10): I get the same error. But I see that another pytest process starts.

This is the codebase for my tests: https://github.com/dgilge/channels-tests. I also tried a non-empty test. I did some tests with both, Python 3.5 and 3.6.

[dgilge]

I don't know if this helps but on my computer both tests in test_liveserver.py fail:

========================================== test session starts ===========================================
platform darwin -- Python 3.5.3, pytest-3.4.2, py-1.5.2, pluggy-0.6.0
rootdir: /Users/Daniel/git/channels, inifile: setup.cfg
plugins: django-3.1.2, asyncio-0.8.0
collected 49 items                                                                                       

tests/test_generic_http.py .                                                                       [  2%]
tests/test_generic_websocket.py ......                                                             [ 14%]
tests/test_http.py ..........                                                                      [ 34%]
tests/test_inmemorychannel.py ......                                                               [ 46%]
tests/test_layers.py ....                                                                          [ 55%]
tests/test_routing.py ......                                                                       [ 67%]
tests/test_testing.py ......                                                                       [ 79%]
tests/security/test_auth.py .......                                                                [ 93%]
tests/security/test_websocket.py .                                                                 [ 95%]
tests/testing/test_liveserver.py EF                                                                [100%]

================================================= ERRORS =================================================
________________________ ERROR at setup of StaticLiveServerChecks.test_test_test _________________________

cls = <class 'test_liveserver.StaticLiveServerChecks'>

    @classmethod
    def setUpClass(cls):
        # If contrib.staticfiles isn't configured properly, the exception
        # should bubble up to the main thread.
        old_STATIC_URL = TEST_SETTINGS['STATIC_URL']
        TEST_SETTINGS['STATIC_URL'] = None
>       cls.raises_exception()

tests/testing/test_liveserver.py:51: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

cls = <class 'test_liveserver.StaticLiveServerChecks'>

    @classmethod
    def raises_exception(cls):
        try:
            super().setUpClass()
>           raise Exception("The line above should have raised an exception")
E           Exception: The line above should have raised an exception

tests/testing/test_liveserver.py:63: Exception
================================================ FAILURES ================================================
___________________________ StaticLiveServerView.test_collectstatic_emulation ____________________________

self = <test_liveserver.StaticLiveServerView testMethod=test_collectstatic_emulation>
result = <TestCaseFunction 'test_collectstatic_emulation'>

    def __call__(self, result=None):
        """
            Wrapper around default __call__ method to perform common Django test
            set up. This means that user-defined Test Cases aren't required to
            include a call to super().setUp().
            """
        testMethod = getattr(self, self._testMethodName)
        skipped = (
            getattr(self.__class__, "__unittest_skip__", False) or
            getattr(testMethod, "__unittest_skip__", False)
        )
    
        if not skipped:
            try:
>               self._pre_setup()

.venv/lib/python3.5/site-packages/django/test/testcases.py:202: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

self = <test_liveserver.StaticLiveServerView testMethod=test_collectstatic_emulation>

    def _pre_setup(self):
        for connection in connections.all():
            if self._is_in_memory_db(connection):
                raise ImproperlyConfigured(
>                   "ChannelLiveServerTestCase can not be used with in memory databases"
                )
E               django.core.exceptions.ImproperlyConfigured: ChannelLiveServerTestCase can not be used with in memory databases

channels/testing/live.py:33: ImproperlyConfigured
============================== 1 failed, 47 passed, 1 error in 3.27 seconds ==============================

[andrewgodwin]

It's likely related, but I unfortunately do not have a Mac OS computer to test on, so I'll have to rely on your or someone else to work out exactly what part of it is failing...

[dgilge]

I don't know if you had seen that it failed on Ubuntu, too.

Travis has the same issue: https://travis-ci.org/dgilge/channels-tests

In which test environment did your test work?

I think I was able to circumcribe the issue a bit. listen_success never gets called. I don't know if this is a result of the error below:

>>>>>>>>>>>>>>>>>>>>>>>> PDB set_trace (IO-capturing turned off) >>>>>>>>>>>>>>>>>>>>>>>>>
> /Users/Daniel/temp/channels/.venv/lib/python3.6/site-packages/daphne/server.py(111)run()
-> for socket_description in self.endpoints:
(Pdb) self.endpoints
['tcp:port=0:interface=localhost']
(Pdb) n
> /Users/Daniel/temp/channels/.venv/lib/python3.6/site-packages/daphne/server.py(112)run()
-> logger.info("Configuring endpoint %s", socket_description)
(Pdb) 
> /Users/Daniel/temp/channels/.venv/lib/python3.6/site-packages/daphne/server.py(113)run()
-> ep = serverFromString(reactor, str(socket_description))
(Pdb) 
> /Users/Daniel/temp/channels/.venv/lib/python3.6/site-packages/daphne/server.py(114)run()
-> listener = ep.listen(self.http_factory)
(Pdb) ep.__dict__
{'_reactor': <twisted.internet.asyncioreactor.AsyncioSelectorReactor object at 0x108e939b0>, '_port': 0, '_backlog': 50, '_interface': 'localhost'}
(Pdb) n
> /Users/Daniel/temp/channels/.venv/lib/python3.6/site-packages/daphne/server.py(115)run()
-> listener.addCallback(self.listen_success)
(Pdb) listener
<Deferred at 0x1092ad6a0 current result: <twisted.python.failure.Failure builtins.OSError: [Errno 9] Bad file descriptor>>

[andrewgodwin]

I am running it under an Ubuntu 16.04 environment inside of Windows Subsystem for Linux, so it may be that somehow the linux emulation layer fixes the file descriptor issue. The same code works fine for the Daphne test suite on Travis, though.

[meric]

The last released version without this issue on my macOS installation is pip install channels==2.0.2.

[davidfstr]

I'll second that I can reproduce this issue on macOS with a very minimal test case:

from channels.testing import ChannelsLiveServerTestCase

class ChatTests(ChannelsLiveServerTestCase):
    def test_do_nothing(self):
        pass

Running in console:

$ python3 manage.py test
Creating test database for alias 'default'...
Got an error creating the test database: (1007, "Can't create database 'test_mysite'; database exists")
Type 'yes' if you would like to try deleting the test database 'test_mysite', or 'no' to cancel: yes
Destroying old test database for alias 'default'...
System check identified no issues (0 silenced).
Listen failure: [Errno 9] Bad file descriptor

I've isolated the Channels code that is hanging by stepping through with a debugger:

class ChannelsLiveServerTestCase(TransactionTestCase):
    ...
    def _pre_setup(self):
        ...
        self._server_process = self.ProtocolServerProcess(
            self.host,
            get_default_application(),
        )
        self._server_process.start()
        self._server_process.ready.wait()  # <-- HANGS HERE
        self._port = self._server_process.port.value

As mentioned above, just before it hangs Listen failure: [Errno 9] Bad file descriptor is printed.

This bug implies that that Part 4 of the Channels Tutorial on automated testing no longer works on macOS.

I can provide more detailed repro instructions if it would help. I have a repository of the Channels tutorial with the bug visible in it.

[andrewgodwin]

It would be nice if you could play around with that line and see if there's anything we can do that can fix it? Daphne live tests have to run a subprocess, so we need some way to wait for it to be ready or we'll have to say you can't run these on OSX for whatever reason is blocking it...

[davidfstr]

Sure I’ll give it a harder look. I suspect it’ll be a week or so before I find a time window.

[davidfstr]

I've spent a couple more hours troubleshooting today.

Between Channels 2.0.2 and 2.1.x the implementation of ChannelsLiveServerTestCase was rewritten to use multiprocessing, so the implementation is fairly different.

The multiprocessing implementation crashes fairly deeply inside Twisted. It gets a "[Errno 9] Bad file descriptor" when trying to open a socket.

Failing code path:

ChannelsLiveServerTestCase._pre_setup()
  DaphneProcess.start()
    << forked process >>
      DaphneProcess.run()
        daphne.server.Server.run()
          ep = serverFromString(reactor, str(socket_description))
          listener = ep.listen(self.http_factory) --> twisted._TCPServerEndpoint.listen
            defer.execute(self._reactor.listenTCP, ...)
              twisted.AsyncioSelectorReactor.listenTCP(...)
                twisted.tcp.Port.startListening
                  twisted.FileDescriptor.startReading
                    twisted.AsyncioSelectorReactor.addReader(...)
                      asyncio._UnixSelectorEventLoop.add_reader(fd, ...)
                        ⚠️ Throws [Errno 9] Bad file descriptor
                      raise
                    implicit raise
                  implicit raise
                implicit raise
              return fail()
          listener.addErrback(self.listen_error)
            daphne.server.Server.listen_error(...)
              logger.critical("Listen failure: %s", failure.getErrorMessage())
                💬 Listen failure: [Errno 9] Bad file descriptor
              self.stop()

I'm not very familiar with Twisted, so I don't have a lot of ideas for efficiently proceeding in investigating.

I wonder if Twisted is having trouble running inside of a forked context, which sometimes does strange things to file descriptors.

[andrewgodwin]

I'm not super familiar with the interior of Twisted either, unfortunately. multiprocessing was much more reliable than the old way of using subprocess as it allows for easier communication out, but maybe that's what's messing with it.

[davidfstr]

Aye. I'll give it another hard look when I can next find a time block.

[davidfstr]

I've done some more experiments by writing a barebones program that interacts with Twisted in a similar manner as ChannelsLiveServerTestCase. The following sequence causes Twisted to crash with [Errno 9] Bad file descriptor:

Error: -- [Errno 9] Bad file descriptor
    setup_reactor('AsyncioSelectorReactor')  # use async reactor, just like daphne.server
    fork_and_continue_in_child()             # fork second, just like daphne.server
    run_server()

If I fork before setting up the reactor, the problem goes away:

OK:
    fork_and_continue_in_child()             # fork first
    setup_reactor('AsyncioSelectorReactor')
    run_server()

Also, If I switch to the default SelectReactor it doesn't matter what order I fork in

OK:
    setup_reactor('SelectReactor')  # use default SelectReactor
    fork_and_continue_in_child()    # fork second, just like daphne.server
    run_server()

OK:
    fork_and_continue_in_child()    # fork first
    setup_reactor('SelectReactor')
    run_server()

When running a ChannelsLiveServerTestCase, the sequence of events is:

• ChannelsLiveServerTestCase is imported, it imports daphne.server, which does setup_reactor('AsyncioSelectorReactor').
• ChannelsLiveServerTestCase is run, it uses multiprocessing to fork_and_continue_in_child() and then does run_server().

So that's the problem: Twisted's AsyncioSelectorReactor can't be forked after it is setup.

Maybe that's a bug on Twisted's end. Or maybe AsyncioSelectorReactor isn't designed to be used that way and Channels should instead be forking before trying to setup the AsyncioSelectorReactor.

[andrewgodwin]

Thanks for the investigation. It's very hard to fork before things get started in Twisted's reactor system, unfortunately, or I'd say that was the easier option. Maybe it can be done with a lot of code moving.

[davidfstr]

Running that Twisted test program above on Ubuntu 18 with the [Errno 9] Bad file descriptor configuration does not have an issue. So something is different about the macOS fork() call vs. Ubuntu, or (less likely) Twisted is doing something different on each operating system.

[dennishylau]

Sorry to interrupt the discussion. As a beginner trying to complete the tutorial, what is the suggested way to get around this issue? Thank you.

[davidfstr]

Assuming you are using macOS, downgrade Channels to 2.0.2. pip3 install channels==2.0.2 If you are using Linux or Windows you shouldn't need to take any special action.

I don't have enough bandwidth to fix this for probably a month or two, so I am planning on putting in a documentation change in the meantime giving similar advice.

[RalphCorderoy]

If Mac OS allows, I'd suggest tracing file descriptor activity in the first process and all threads/children, in particular I suspect something is closing the once-good file descriptor causing the EBADF from listen(2). Note, this doesn't have to be a close(2), other system calls can cause an FD to be closed too, e.g. O_CLOEXEC and an execve(2).

[shjohnson-pi]

So I thought I had a fix for this, but it fails in our project.

Here's some relevant documentation I've found while researching this issue:

• https://bugs.python.org/issue21998
  Python asyncio does not support fork()
• https://docs.python.org/3.4/library/multiprocessing.html#contexts-and-start-methods
  Here is where I saw I could create the process with 'spawn' or 'forkserver'. These allow daphne tests to run successfully on my Mac, (and remove the [Errno 9] Bad file descriptor error), but these don't play nice with django very well. Django triggers "django.core.exceptions.AppRegistryNotReady: Apps aren't loaded yet." while python is unpickling the new process. This error is also raised on my Linux machine.

I think the best option is to revert back to subprocess unfortunately.

[shjohnson-pi]

I was finally able to write a fix, so that tests for our project work on Linux and Mac (Yosemite and Mojave). (And selenium works)

In summary, I changed ChannelsLiveServerTestCase to use a single (running for the duration of all tests) thread to run Daphne. I added some methods to Daphne to clear all running applications, and to change the application that is used for new connections.

The single thread prevents the ReactorNotRestartable errors if there is more than one Live TestCase.

Relevant commits are:

• shjohnson-pi/daphne@332930d
• shjohnson-pi@76f0b38

I don't know if my fix will fail for complex django tests with multiple or dynamic database connections. I am by no means an expert with threading, twisted, etc., so these changes should be looked over thoroughly.

I hope these commits can help someone else write a pull request for Channels and Daphne.

Some things that should be taken care of:

• This fix defaults to serving static files, and may fail if static_handler is set to None.
• Deciding if my first commit shjohnson-pi/daphne@1ba3acf should be included or not. I think it's necessary for Daphne tests to run on Macs, but is not currently necessary for Channels or library users.
• I ran tests with Postgres, but they may run fine with the in memory db now. The fix doesn't check if the db is in memory or not.
• Whether new function names are appropriate and/or need to be refactored further.

[joonhyungshin]

I took a look at this issue quite deeply, spending a day debugging and seeking for solutions. Then I thought this is a design issue rather than just fixing-a-bug, so I chose to post my result on Google Groups instead of here. But as @carltongibson replied, I think I should also leave a comment here.

In a nutshell, DaphneProcess should not register an asyncio event handler as long as it was fork()ed from a process with event loop opened. It is also related to what @shjohnson-pi mentioned above. This is especially dangerous in BSD-like systems such as MacOS, resulting in a weird "Bad file descriptor" error.

So, how to fix it? This is where a "design issue" comes in. In the big picture, there are three ways:

• Close the forked event loop and open a new one when DaphneProcess starts to run().
• Modify multiprocessing-based DaphneProcess to threading-based.
• Run tests in a single-process single-thread environment.

I am not sure which one is the best design. I've already opened a PR django/daphne#247 using the first solution (which I think is the easiest way to solve) even though I am not 100% satisfied because it looks like a cheating. I believe the third solution was (at least partially) implemented by @shjohnson-pi as he commented above. The second one? Hmm... I have no idea what advantages it has over the third one.

What is your opinion?

[davidfstr]

Hi @kuratowski I personally like your PR ( django/daphne#247 ) that implements the first solution. It's relatively concise.

Unfortunately that PR has been open for several months now with no comments on it. I've pinged it to hopefully give it some attention.

[carltongibson]

Yes. Somewhat complex issue. To which I’ve not yet had the time to look. Sorry about the delay there. (Although anyone is welcome to review...)

[shjohnson-pi]

I recently ran into a problem with my solution (singleton thread for Daphne) when run with pytest-xdist (parallel/multiprocess). Because of imports, twisted was using the asyncio event loop from the main thread, even though it was run in a subthread. This caused async_to_sync calls to fail in synchronous code because it thought the main event loop was being used (which it technically was by twisted).

After trial and error I figured out how to force twisted to use a new asyncio event loop for it's own thread. And, as a bonus, the thread no longer has to be a singleton, so it properly closes resources at the end of each TestCase.

New Summary of my Changes:
Daphne:

• Server now accepts a logger and a reactor.
• The logger is needed to support logging when used with multiprocessing.
• The reactor is needed to allow overriding which reactor to use.
• DaphneProcess uses spawn instead of fork to prevent [Errno 9] Bad file descriptor on Macs, and sets up logging.

Channels:

• ChannelsLiveServerTestCase does not use DaphneProcess anymore.
• DaphneLiveServerThread extends Django's LiveServerThread and creates a local asyncio reactor for twisted and Daphne that is separate from the main thread.

I feel more confident about this code than I did before. Do you want me to start a pull request with these changes? And, if so, should I squash the commits?

$ pytest passed for Daphne and Channels, on both Linux and Mac with Python 3.7.

[carltongibson]

@shjohnson-pi Yes please. Happy to review separate commits if that makes the changes clearer.

[carltongibson]

Ref this, django/daphne#247 looks to resolve the test hang/failures on macOS, which is django/daphne#179. I'm minded to bring that in. @shjohnson-pi fancy taking a quick look?

[shjohnson-pi]

@carltongibson I believe the other pull request will fix the immediate problem, but doesn't allow mocking files during the test (since there are multiple processes). I have been using my branch to run our own project tests with extensive mocking, so for my personal use cases that pull request won't work.