Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Using channels_rabbitmq makes group_send non-reenterable #14

Closed
nnseva opened this issue Jun 21, 2019 · 9 comments
Closed

Using channels_rabbitmq makes group_send non-reenterable #14

nnseva opened this issue Jun 21, 2019 · 9 comments

Comments

@nnseva
Copy link
Contributor

nnseva commented Jun 21, 2019

When:

  • the group consumer is present
  • several concurrent coroutines await layer.group_send() simultaneously

there is a high probability that some of these concurrent awaits never finished.

I have a JsonWebsocketConsumer like this (some details are removed):

class WebsocketClient(JsonWebsocketConsumer):
    groups = ['simulation_event']

    def simulation_event(self, message):
        message = message['data']           
        self.send_json(message)

To reproduce an issue I wrote code like this:

class SpamGenerator:
    def __init__(self):
        self.counters = {}
        self.running = True

    async def test_event_generator(self, id):
        """(async) Spam thread sending an event to the group every second"""
        while self.running:
            self.counters[id] = self.counters.get(id, 0) + 1
            await self.async_group_send('simulation_event', {'Hello': 'World!'})
            self.counters[id] = self.counters.get(id, 0) - 1
            await asyncio.sleep(1)

    async def test_time_print(self, seconds):
        """(async) Spam thread printing time every second and finishing loop"""
        ts = timezone.now()
        while timezone.now() - ts < timezone.timedelta(0, seconds):
            print(">>>%s" % timezone.now())
            await asyncio.sleep(1)
        self.running = False
        await asyncio.sleep(2)
        for id, c in self.counters.items():
            if c:
                raise Exception("Something went wrong!")

    async def async_group_send(self, kind, data):
        """(async) Function sending a message to the group"""
        from channels.layers import get_channel_layer
        layer = get_channel_layer()
        await layer.group_send(
            kind,
            {
                'type': kind,
                'data': data
            }
        )

    def test_spam_generator(self):
        """Spam generator getting loop and starting spam threads simultaneously"""
        loop = asyncio.get_event_loop()
        jobs = list(self.test_event_generator('!%03d' % i) for i in range(10)) + [self.test_time_print(30)]
        tasks = asyncio.gather(*jobs)
        try:
            loop.run_until_complete(tasks)
        except Exception as ex:
            print("???", ex)
        print("COUNTERS", self.counters)

I've started a daphne server and connected to the websocket from the browser.

Then I've started my test code:

In [1]: from simulation.agents.simulation_runner import SpamGenerator
In [2]: SpamGenerator().test_spam_generator()
>>>2019-06-21 16:19:09.847049+00:00
only PLAIN login_method is supported, falling back to AMQPLAIN
>>>2019-06-21 16:19:10.848471+00:00
>>>2019-06-21 16:19:11.850630+00:00
>>>2019-06-21 16:19:12.852616+00:00
>>>2019-06-21 16:19:13.854819+00:00
>>>2019-06-21 16:19:14.856361+00:00
>>>2019-06-21 16:19:15.857986+00:00
>>>2019-06-21 16:19:16.859830+00:00
>>>2019-06-21 16:19:17.861564+00:00
>>>2019-06-21 16:19:18.863144+00:00
>>>2019-06-21 16:19:19.864516+00:00
>>>2019-06-21 16:19:20.866418+00:00
>>>2019-06-21 16:19:21.868187+00:00
>>>2019-06-21 16:19:22.870140+00:00
>>>2019-06-21 16:19:23.871783+00:00
>>>2019-06-21 16:19:24.873361+00:00
>>>2019-06-21 16:19:25.874938+00:00
>>>2019-06-21 16:19:26.876385+00:00
>>>2019-06-21 16:19:27.877719+00:00
>>>2019-06-21 16:19:28.878705+00:00
>>>2019-06-21 16:19:29.880829+00:00
>>>2019-06-21 16:19:30.881456+00:00
>>>2019-06-21 16:19:31.882706+00:00
>>>2019-06-21 16:19:32.884342+00:00
>>>2019-06-21 16:19:33.886145+00:00
>>>2019-06-21 16:19:34.887756+00:00
>>>2019-06-21 16:19:35.889362+00:00
>>>2019-06-21 16:19:36.890672+00:00
>>>2019-06-21 16:19:37.892218+00:00
>>>2019-06-21 16:19:38.893993+00:00
??? Something went wrong!
COUNTERS {'!006': 1, '!008': 1, '!009': 1, '!005': 1, '!007': 1, '!001': 1, '!002': 1, '!003': 1, '!004': 1, '!000': 0}

As you can see in the code, all counters should be 0 at the end.

It's interesting that if I disconnect the browser from the websocket (so the consumer is unregistered), the issue disappears.

Some other tests showed me that the await group_send is really stunned for some concurrent calls.

The (upd) channels_redis backend works fine in the same circumstances.

Software versions:

(py3.6) seva@SEVA:~/swat/sgerp$ pip freeze | grep -i rabbit
channels-rabbitmq==1.1.2
(py3.6) seva@SEVA:~/swat/sgerp$ pip freeze | grep -i amqp
aioamqp==0.13.0
amqp==2.4.2
pamqp==2.3.0
(py3.6) seva@SEVA:~/swat/sgerp$ pip freeze | grep -i channels
channels==2.2.0
channels-rabbitmq==1.1.2
channels-redis==2.4.0
(py3.6) seva@SEVA:~/swat/sgerp$ python --version
Python 3.6.8
(py3.6) seva@SEVA:~/swat/sgerp$ django-admin --version
2.0
@adamhooper
Copy link
Contributor

I'm on vacation, so this will take until July to fix. In the meantime, we can debug a bit:

Is your Websockets client actually consuming the messages?

... I'm developing a hunch. I suspect the send is stalling because no consumers are consuming the messages. That's a bug, and I'll look into it after vacation. In the meantime, v1.1.3 should "fix" this by discarding stale messages. (It'll warn when it does.)

Do you experience this with 1.1.3?

Aside from discarding stale messages, 1.1.3 also adds a config param and more docs that can help you avoid issues on production. (To be clear: send() should never stall. But with 1.1.3, if my hunch is correct, the stall will clear up once messages expire.)

@nnseva
Copy link
Contributor Author

nnseva commented Jun 22, 2019

Hi @adamhooper,

Is your Websockets client actually consuming the messages?

I've started a daphne server and connected to the websocket from the browser, so the consumer is present. Moreover, when I disconnect websocket client, the issue disappears.

Do you experience this with 1.1.3?

Not tested yet, 1.1.2 is installed now, will try.

@nnseva
Copy link
Contributor Author

nnseva commented Jun 22, 2019

Tested against 1.1.3 and found the same issue. Lowering the expiry parameter doesn't help.

I've changed the code for stress test slightly to be more intuitive.

from channels.layers import get_channel_layer
import asyncio
from django.utils import timezone

class SpamGenerator:
    def __init__(self):
        self.counter = 0
        self.running = True

    async def test_event_generator(self, id):
        """(async) Spam thread sending an event to the group every second"""
        while self.running:
            self.counter += 1
            print("!" + ">" * self.counter)
            await self.async_group_send('simulation_event', {'Hello': 'World!'})
            self.counter -= 1
            print("!" + "<" * self.counter)
            await asyncio.sleep(1)

    async def test_time_print(self, seconds):
        """(async) Spam thread printing time every second and finishing loop"""
        ts = timezone.now()
        while timezone.now() - ts < timezone.timedelta(0, seconds):
            print(">>>%s" % timezone.now())
            await asyncio.sleep(1)
        self.running = False
        await asyncio.sleep(2)
        if self.counter:
            raise Exception("Something went wrong!")

    async def async_group_send(self, kind, data):
        """(async) Function sending a message to the group"""
        layer = get_channel_layer()
        await layer.group_send(
            kind,
            {
                'type': kind,
                'data': data
            }
        )

    def test_spam_generator(self):
        """Spam generator getting loop and starting spam threads simultaneously"""
        loop = asyncio.get_event_loop()
        jobs = list(self.test_event_generator('!%03d' % i) for i in range(10)) + [self.test_time_print(30)]
        tasks = asyncio.gather(*jobs)
        try:
            loop.run_until_complete(tasks)
        except Exception as ex:
            print("???", ex)
        print("COUNTER:", self.counter)

That's the result (consumer is connected):

In [1]: from simulation import spam                                                                                                                                                                                                          

In [2]: spam.SpamGenerator().test_spam_generator()                                                                                                                                                                                           
!>
!>>
!>>>
!>>>>
!>>>>>
!>>>>>>
!>>>>>>>
!>>>>>>>>
!>>>>>>>>>
!>>>>>>>>>>
>>>2019-06-22 09:42:43.919290+00:00
only PLAIN login_method is supported, falling back to AMQPLAIN
!<<<<<<<<<
!<<<<<<<<
!<<<<<<<
!<<<<<<
!<<<<<
!<<<<
>>>2019-06-22 09:42:44.922501+00:00
!>>>>>
!<<<<
!>>>>>
!>>>>>>
!>>>>>>>
!>>>>>>>>
!>>>>>>>>>
!<<<<<<<<
!<<<<<<<
!<<<<<<
!<<<<<
!<<<<
>>>2019-06-22 09:42:45.925408+00:00
!>>>>>
!<<<<
!>>>>>
!>>>>>>
!>>>>>>>
!>>>>>>>>
!>>>>>>>>>
!<<<<<<<<
!<<<<<<<
!<<<<<<
!<<<<<
!<<<<
>>>2019-06-22 09:42:46.928140+00:00
!>>>>>
!<<<<
!>>>>>
!>>>>>>
!>>>>>>>
!>>>>>>>>
!>>>>>>>>>
!<<<<<<<<
!<<<<<<<
!<<<<<<
!<<<<<
!<<<<
>>>2019-06-22 09:42:47.930299+00:00
!>>>>>
!<<<<
!>>>>>
!>>>>>>
!>>>>>>>
!>>>>>>>>
!>>>>>>>>>
!<<<<<<<<
!<<<<<<<
!<<<<<<
!<<<<<
!<<<<
>>>2019-06-22 09:42:48.932305+00:00
!>>>>>
!<<<<
!>>>>>
!>>>>>>
!>>>>>>>
!>>>>>>>>
!>>>>>>>>>
!<<<<<<<<
!<<<<<<<
!<<<<<<
!<<<<<
!<<<<
>>>2019-06-22 09:42:49.934459+00:00
!>>>>>
!<<<<
!>>>>>
!>>>>>>
!>>>>>>>
!>>>>>>>>
!>>>>>>>>>
!<<<<<<<<
!<<<<<<<
!<<<<<<
!<<<<<
!<<<<
>>>2019-06-22 09:42:50.936304+00:00
!>>>>>
!<<<<
!>>>>>
!>>>>>>
!>>>>>>>
!>>>>>>>>
!>>>>>>>>>
!<<<<<<<<
!<<<<<<<
!<<<<<<
!<<<<<
!<<<<
>>>2019-06-22 09:42:51.937855+00:00
!>>>>>
!<<<<
!>>>>>
!>>>>>>
!>>>>>>>
!>>>>>>>>
!>>>>>>>>>
!<<<<<<<<
!<<<<<<<
!<<<<<<
!<<<<<
!<<<<
>>>2019-06-22 09:42:52.938632+00:00
!>>>>>
!<<<<
!>>>>>
!>>>>>>
!>>>>>>>
!>>>>>>>>
!>>>>>>>>>
!<<<<<<<<
!<<<<<<<
!<<<<<<
!<<<<<
!<<<<
>>>2019-06-22 09:42:53.940311+00:00
!>>>>>
!<<<<
!>>>>>
!>>>>>>
!>>>>>>>
!>>>>>>>>
!>>>>>>>>>
!<<<<<<<<
!<<<<<<<
!<<<<<<
>>>2019-06-22 09:42:54.941823+00:00
!>>>>>>>
!<<<<<<
!>>>>>>>
!>>>>>>>>
!>>>>>>>>>
!<<<<<<<<
!<<<<<<<
!<<<<<<
>>>2019-06-22 09:42:55.943499+00:00
!>>>>>>>
!<<<<<<
!>>>>>>>
!>>>>>>>>
!>>>>>>>>>
!<<<<<<<<
!<<<<<<<
!<<<<<<
>>>2019-06-22 09:42:56.945476+00:00
!>>>>>>>
!<<<<<<
!>>>>>>>
!>>>>>>>>
!>>>>>>>>>
!<<<<<<<<
!<<<<<<<
!<<<<<<
>>>2019-06-22 09:42:57.946924+00:00
!>>>>>>>
!<<<<<<
!>>>>>>>
!>>>>>>>>
!>>>>>>>>>
!<<<<<<<<
!<<<<<<<
!<<<<<<
>>>2019-06-22 09:42:58.948168+00:00
!>>>>>>>
!<<<<<<
!>>>>>>>
!>>>>>>>>
!>>>>>>>>>
!<<<<<<<<
!<<<<<<<
!<<<<<<
>>>2019-06-22 09:42:59.950013+00:00
!>>>>>>>
!<<<<<<
!>>>>>>>
!>>>>>>>>
!>>>>>>>>>
!<<<<<<<<
!<<<<<<<
!<<<<<<
>>>2019-06-22 09:43:00.951410+00:00
!>>>>>>>
!<<<<<<
!>>>>>>>
!>>>>>>>>
!>>>>>>>>>
!<<<<<<<<
!<<<<<<<
!<<<<<<
>>>2019-06-22 09:43:01.953539+00:00
!>>>>>>>
!<<<<<<
!>>>>>>>
!>>>>>>>>
!>>>>>>>>>
!<<<<<<<<
!<<<<<<<
!<<<<<<
>>>2019-06-22 09:43:02.955026+00:00
!>>>>>>>
!<<<<<<
!>>>>>>>
!>>>>>>>>
!>>>>>>>>>
!<<<<<<<<
!<<<<<<<
!<<<<<<
>>>2019-06-22 09:43:03.956301+00:00
!>>>>>>>
!<<<<<<
!>>>>>>>
!>>>>>>>>
!>>>>>>>>>
!<<<<<<<<
!<<<<<<<
!<<<<<<
>>>2019-06-22 09:43:04.957599+00:00
!>>>>>>>
!<<<<<<
!>>>>>>>
!>>>>>>>>
!>>>>>>>>>
!<<<<<<<<
!<<<<<<<
!<<<<<<
>>>2019-06-22 09:43:05.959077+00:00
!>>>>>>>
!<<<<<<
!>>>>>>>
!>>>>>>>>
!>>>>>>>>>
!<<<<<<<<
!<<<<<<<
!<<<<<<
>>>2019-06-22 09:43:06.960291+00:00
!>>>>>>>
!<<<<<<
!>>>>>>>
!>>>>>>>>
!>>>>>>>>>
!<<<<<<<<
!<<<<<<<
>>>2019-06-22 09:43:07.961637+00:00
!>>>>>>>>
!<<<<<<<
!>>>>>>>>
!>>>>>>>>>
!<<<<<<<<
!<<<<<<<
>>>2019-06-22 09:43:08.963673+00:00
!>>>>>>>>
!<<<<<<<
!>>>>>>>>
!>>>>>>>>>
!<<<<<<<<
!<<<<<<<
>>>2019-06-22 09:43:09.965667+00:00
!>>>>>>>>
!<<<<<<<
!>>>>>>>>
!>>>>>>>>>
!<<<<<<<<
!<<<<<<<
>>>2019-06-22 09:43:10.967064+00:00
!>>>>>>>>
!<<<<<<<
!>>>>>>>>
!>>>>>>>>>
!<<<<<<<<
!<<<<<<<
>>>2019-06-22 09:43:11.968307+00:00
!>>>>>>>>
!<<<<<<<
!>>>>>>>>
!>>>>>>>>>
!<<<<<<<<
!<<<<<<<
>>>2019-06-22 09:43:12.969981+00:00
!>>>>>>>>
!<<<<<<<
!>>>>>>>>
!>>>>>>>>>
!<<<<<<<<
!<<<<<<<
??? Something went wrong!
COUNTER: 7

@adamhooper
Copy link
Contributor

Thanks for testing! With 1.1.3 and local_expiry=2s, does this still happen?

Separate test: if you make your Websockets client print each message as it's received, does this still happen?

@nnseva
Copy link
Contributor Author

nnseva commented Jun 22, 2019

Thanks for testing! With 1.1.3 and local_expiry=2s, does this still happen?

The same

In [3]: spam.SpamGenerator().test_spam_generator()                                                                                                                                                                                           
!>
!>>
!>>>
!>>>>
!>>>>>
!>>>>>>
!>>>>>>>
!>>>>>>>>
>>>2019-06-22 13:35:13.688450+00:00
!>>>>>>>>>
!>>>>>>>>>>
only PLAIN login_method is supported, falling back to AMQPLAIN
!<<<<<<<<<
!<<<<<<<<
!<<<<<<<
!<<<<<<
!<<<<<
!<<<<
!<<<
!<<
>>>2019-06-22 13:35:14.689664+00:00
!>>>
!<<
!>>>
!>>>>
!>>>>>
!>>>>>>
!>>>>>>>
!>>>>>>>>
!>>>>>>>>>
!<<<<<<<<
>>>2019-06-22 13:35:15.691272+00:00
!>>>>>>>>>
!<<<<<<<<
!>>>>>>>>>
!<<<<<<<<
>>>2019-06-22 13:35:16.692324+00:00
!>>>>>>>>>
!<<<<<<<<
!>>>>>>>>>
!<<<<<<<<
>>>2019-06-22 13:35:17.694059+00:00
!>>>>>>>>>
!<<<<<<<<
!>>>>>>>>>
!<<<<<<<<
>>>2019-06-22 13:35:18.695711+00:00
!>>>>>>>>>
!<<<<<<<<
!>>>>>>>>>
!<<<<<<<<
>>>2019-06-22 13:35:19.697312+00:00
!>>>>>>>>>
!<<<<<<<<
!>>>>>>>>>
!<<<<<<<<
>>>2019-06-22 13:35:20.699167+00:00
!>>>>>>>>>
!<<<<<<<<
!>>>>>>>>>
!<<<<<<<<
>>>2019-06-22 13:35:21.701114+00:00
!>>>>>>>>>
!<<<<<<<<
!>>>>>>>>>
!<<<<<<<<
>>>2019-06-22 13:35:22.702789+00:00
!>>>>>>>>>
!<<<<<<<<
!>>>>>>>>>
!<<<<<<<<
>>>2019-06-22 13:35:23.703568+00:00
!>>>>>>>>>
!<<<<<<<<
!>>>>>>>>>
!<<<<<<<<
>>>2019-06-22 13:35:24.705586+00:00
!>>>>>>>>>
!<<<<<<<<
!>>>>>>>>>
!<<<<<<<<
>>>2019-06-22 13:35:25.707092+00:00
!>>>>>>>>>
!<<<<<<<<
!>>>>>>>>>
!<<<<<<<<
>>>2019-06-22 13:35:26.708857+00:00
!>>>>>>>>>
!<<<<<<<<
!>>>>>>>>>
!<<<<<<<<
>>>2019-06-22 13:35:27.710555+00:00
!>>>>>>>>>
!<<<<<<<<
!>>>>>>>>>
!<<<<<<<<
>>>2019-06-22 13:35:28.712314+00:00
!>>>>>>>>>
!<<<<<<<<
!>>>>>>>>>
!<<<<<<<<
>>>2019-06-22 13:35:29.713764+00:00
!>>>>>>>>>
!<<<<<<<<
!>>>>>>>>>
!<<<<<<<<
>>>2019-06-22 13:35:30.715868+00:00
!>>>>>>>>>
!<<<<<<<<
!>>>>>>>>>
!<<<<<<<<
>>>2019-06-22 13:35:31.717715+00:00
!>>>>>>>>>
!<<<<<<<<
!>>>>>>>>>
!<<<<<<<<
>>>2019-06-22 13:35:32.719535+00:00
!>>>>>>>>>
!<<<<<<<<
!>>>>>>>>>
!<<<<<<<<
>>>2019-06-22 13:35:33.720351+00:00
!>>>>>>>>>
!<<<<<<<<
!>>>>>>>>>
!<<<<<<<<
>>>2019-06-22 13:35:34.722509+00:00
!>>>>>>>>>
!<<<<<<<<
!>>>>>>>>>
!<<<<<<<<
>>>2019-06-22 13:35:35.724318+00:00
!>>>>>>>>>
!<<<<<<<<
!>>>>>>>>>
!<<<<<<<<
>>>2019-06-22 13:35:36.727186+00:00
!>>>>>>>>>
!<<<<<<<<
!>>>>>>>>>
!<<<<<<<<
>>>2019-06-22 13:35:37.730270+00:00
!>>>>>>>>>
!<<<<<<<<
!>>>>>>>>>
!<<<<<<<<
>>>2019-06-22 13:35:38.732315+00:00
!>>>>>>>>>
!<<<<<<<<
!>>>>>>>>>
!<<<<<<<<
>>>2019-06-22 13:35:39.734557+00:00
!>>>>>>>>>
!<<<<<<<<
!>>>>>>>>>
!<<<<<<<<
>>>2019-06-22 13:35:40.736325+00:00
!>>>>>>>>>
!<<<<<<<<
!>>>>>>>>>
!<<<<<<<<
>>>2019-06-22 13:35:41.739189+00:00
!>>>>>>>>>
!<<<<<<<<
!>>>>>>>>>
!<<<<<<<<
>>>2019-06-22 13:35:42.741470+00:00
!>>>>>>>>>
!<<<<<<<<
!>>>>>>>>>
!<<<<<<<<
??? Something went wrong!
COUNTER: 8

if you make your Websockets client print each message as it's received

I am using some chrome extension to test websockets chrome://extensions/?id=omalebghpgejjiaoknljcfmglgbpocdp

It receives a message and outputs it on the screen in the special widget. I am also looking to the chrome network journal and see packets received. Should note that number of received packets corresponds to non-stalled send calls.

There also some daphne debug output while processing messages above:

2019-06-22 13:35:13,787 DEBUG    Received message 1 on ASGI channel/group simulation_event
2019-06-22 13:35:13,788 DEBUG    Received message 2 on ASGI channel/group simulation_event
2019-06-22 13:35:13,789 DEBUG    Received message 3 on ASGI channel/group simulation_event
2019-06-22 13:35:13,791 DEBUG    Received message 4 on ASGI channel/group simulation_event
2019-06-22 13:35:13,792 DEBUG    Received message 5 on ASGI channel/group simulation_event
2019-06-22 13:35:13,793 DEBUG    Received message 6 on ASGI channel/group simulation_event
2019-06-22 13:35:13,794 DEBUG    Received message 7 on ASGI channel/group simulation_event
2019-06-22 13:35:13,797 DEBUG    Received message 8 on ASGI channel/group simulation_event
2019-06-22 13:35:13,799 DEBUG    Received message 9 on ASGI channel/group simulation_event
2019-06-22 13:35:13,800 DEBUG    Received message 10 on ASGI channel/group simulation_event
2019-06-22 13:35:13,802 DEBUG    Acked delivery 1
2019-06-22 13:35:13,804 DEBUG    Acked delivery 2
2019-06-22 13:35:13,805 DEBUG    Acked delivery 3
2019-06-22 13:35:13,806 DEBUG    Acked delivery 4
2019-06-22 13:35:13,807 DEBUG    Acked delivery 5
2019-06-22 13:35:13,809 DEBUG    Acked delivery 6
2019-06-22 13:35:13,810 DEBUG    Acked delivery 7
2019-06-22 13:35:13,811 DEBUG    Acked delivery 8
2019-06-22 13:35:13,812 DEBUG    Acked delivery 9
2019-06-22 13:35:13,813 DEBUG    Acked delivery 10
2019-06-22 13:35:13,818 DEBUG    Sent WebSocket packet to client for ['::1', 39328]
2019-06-22 13:35:13,818 DEBUG    poll 546.405 ms took 0.020 ms: 1 events
2019-06-22 13:35:13,824 DEBUG    Sent WebSocket packet to client for ['::1', 39328]
2019-06-22 13:35:13,824 DEBUG    poll 540.206 ms took 0.016 ms: 1 events
2019-06-22 13:35:13,826 DEBUG    poll 539.796 ms took 1.776 ms: 1 events
2019-06-22 13:35:13,832 DEBUG    Sent WebSocket packet to client for ['::1', 39328]
2019-06-22 13:35:13,832 DEBUG    poll 532.403 ms took 0.019 ms: 1 events
2019-06-22 13:35:13,836 DEBUG    Sent WebSocket packet to client for ['::1', 39328]
2019-06-22 13:35:13,836 DEBUG    poll 528.243 ms took 0.163 ms: 2 events
2019-06-22 13:35:13,841 DEBUG    Sent WebSocket packet to client for ['::1', 39328]
2019-06-22 13:35:13,841 DEBUG    poll 523.376 ms took 0.019 ms: 1 events
2019-06-22 13:35:13,845 DEBUG    poll 520.453 ms took 0.678 ms: 1 events
2019-06-22 13:35:13,846 DEBUG    Sent WebSocket packet to client for ['::1', 39328]
2019-06-22 13:35:13,847 DEBUG    poll 517.453 ms took 0.022 ms: 1 events
2019-06-22 13:35:13,853 DEBUG    Sent WebSocket packet to client for ['::1', 39328]
2019-06-22 13:35:13,854 DEBUG    poll 510.814 ms took 0.018 ms: 1 events
2019-06-22 13:35:13,857 DEBUG    Sent WebSocket packet to client for ['::1', 39328]
2019-06-22 13:35:13,858 DEBUG    poll 507.066 ms took 0.116 ms: 1 events
2019-06-22 13:35:13,861 DEBUG    Sent WebSocket packet to client for ['::1', 39328]
2019-06-22 13:35:13,861 DEBUG    poll 503.139 ms took 0.152 ms: 1 events
2019-06-22 13:35:13,869 DEBUG    Sent WebSocket packet to client for ['::1', 39328]
2019-06-22 13:35:13,874 DEBUG    poll 490.668 ms took 0.209 ms: 2 events
2019-06-22 13:35:14,784 DEBUG    poll 567.636 ms took 417.539 ms: 1 events
2019-06-22 13:35:14,785 DEBUG    Received message 11 on ASGI channel/group simulation_event
2019-06-22 13:35:14,788 DEBUG    Acked delivery 11
2019-06-22 13:35:14,790 DEBUG    Sent WebSocket packet to client for ['::1', 39328]
2019-06-22 13:35:14,791 DEBUG    poll 143.025 ms took 0.025 ms: 1 events
2019-06-22 13:35:14,801 DEBUG    Received message 12 on ASGI channel/group simulation_event
2019-06-22 13:35:14,802 DEBUG    Received message 13 on ASGI channel/group simulation_event
2019-06-22 13:35:14,803 DEBUG    Received message 14 on ASGI channel/group simulation_event
2019-06-22 13:35:14,805 DEBUG    Received message 15 on ASGI channel/group simulation_event
2019-06-22 13:35:14,806 DEBUG    Received message 16 on ASGI channel/group simulation_event
2019-06-22 13:35:14,807 DEBUG    Received message 17 on ASGI channel/group simulation_event
2019-06-22 13:35:14,809 DEBUG    Received message 18 on ASGI channel/group simulation_event
2019-06-22 13:35:14,822 DEBUG    Acked delivery 12
2019-06-22 13:35:14,825 DEBUG    Acked delivery 13
2019-06-22 13:35:14,826 DEBUG    Acked delivery 14
2019-06-22 13:35:14,828 DEBUG    Acked delivery 15
2019-06-22 13:35:14,829 DEBUG    Acked delivery 16
2019-06-22 13:35:14,831 DEBUG    Acked delivery 17
2019-06-22 13:35:14,832 DEBUG    Acked delivery 18
2019-06-22 13:35:14,834 DEBUG    poll 100.037 ms took 0.057 ms: 1 events
2019-06-22 13:35:14,834 DEBUG    Sent WebSocket packet to client for ['::1', 39328]
2019-06-22 13:35:14,835 DEBUG    poll 99.001 ms took 0.017 ms: 1 events
2019-06-22 13:35:14,838 DEBUG    Sent WebSocket packet to client for ['::1', 39328]
2019-06-22 13:35:14,839 DEBUG    poll 95.276 ms took 0.275 ms: 2 events
2019-06-22 13:35:14,842 DEBUG    poll 92.296 ms took 0.414 ms: 1 events
2019-06-22 13:35:14,842 DEBUG    Sent WebSocket packet to client for ['::1', 39328]
2019-06-22 13:35:14,843 DEBUG    poll 90.944 ms took 0.017 ms: 1 events
2019-06-22 13:35:14,848 DEBUG    Sent WebSocket packet to client for ['::1', 39328]
2019-06-22 13:35:14,848 DEBUG    poll 85.502 ms took 0.156 ms: 2 events
2019-06-22 13:35:14,851 DEBUG    Sent WebSocket packet to client for ['::1', 39328]
2019-06-22 13:35:14,852 DEBUG    poll 82.079 ms took 0.017 ms: 1 events
2019-06-22 13:35:14,854 DEBUG    poll 79.587 ms took 0.046 ms: 1 events
2019-06-22 13:35:14,855 DEBUG    Sent WebSocket packet to client for ['::1', 39328]
2019-06-22 13:35:14,855 DEBUG    poll 78.653 ms took 0.016 ms: 1 events
2019-06-22 13:35:14,857 DEBUG    poll 76.365 ms took 0.189 ms: 1 events
2019-06-22 13:35:14,858 DEBUG    Sent WebSocket packet to client for ['::1', 39328]
2019-06-22 13:35:14,858 DEBUG    poll 75.422 ms took 0.014 ms: 1 events
2019-06-22 13:35:15,785 DEBUG    poll 999.643 ms took 417.749 ms: 1 events
2019-06-22 13:35:15,787 DEBUG    Received message 19 on ASGI channel/group simulation_event
2019-06-22 13:35:15,789 DEBUG    Acked delivery 19
2019-06-22 13:35:15,792 DEBUG    Sent WebSocket packet to client for ['::1', 39328]
2019-06-22 13:35:15,792 DEBUG    poll 574.706 ms took 0.025 ms: 1 events
2019-06-22 13:35:15,807 DEBUG    poll 572.097 ms took 12.013 ms: 1 events
2019-06-22 13:35:15,809 DEBUG    Received message 20 on ASGI channel/group simulation_event
2019-06-22 13:35:15,811 DEBUG    Acked delivery 20
2019-06-22 13:35:15,813 DEBUG    Sent WebSocket packet to client for ['::1', 39328]
2019-06-22 13:35:15,815 DEBUG    poll 551.914 ms took 0.022 ms: 1 events
2019-06-22 13:35:16,787 DEBUG    poll 565.550 ms took 418.546 ms: 1 events
2019-06-22 13:35:16,789 DEBUG    Received message 21 on ASGI channel/group simulation_event
2019-06-22 13:35:16,792 DEBUG    Acked delivery 21
2019-06-22 13:35:16,794 DEBUG    Sent WebSocket packet to client for ['::1', 39328]
2019-06-22 13:35:16,795 DEBUG    poll 139.657 ms took 0.025 ms: 1 events
2019-06-22 13:35:16,802 DEBUG    poll 136.935 ms took 4.179 ms: 1 events
2019-06-22 13:35:16,803 DEBUG    Received message 22 on ASGI channel/group simulation_event
2019-06-22 13:35:16,806 DEBUG    Acked delivery 22
2019-06-22 13:35:16,808 DEBUG    Sent WebSocket packet to client for ['::1', 39328]
2019-06-22 13:35:16,809 DEBUG    poll 125.663 ms took 0.115 ms: 1 events
2019-06-22 13:35:17,790 DEBUG    poll 999.550 ms took 418.825 ms: 1 events
2019-06-22 13:35:17,792 DEBUG    Received message 23 on ASGI channel/group simulation_event
2019-06-22 13:35:17,794 DEBUG    Acked delivery 23
2019-06-22 13:35:17,797 DEBUG    Sent WebSocket packet to client for ['::1', 39328]
2019-06-22 13:35:17,797 DEBUG    poll 573.543 ms took 0.025 ms: 1 events
2019-06-22 13:35:17,812 DEBUG    poll 570.758 ms took 11.982 ms: 1 events
2019-06-22 13:35:17,814 DEBUG    Received message 24 on ASGI channel/group simulation_event
2019-06-22 13:35:17,816 DEBUG    Acked delivery 24
2019-06-22 13:35:17,819 DEBUG    Sent WebSocket packet to client for ['::1', 39328]
2019-06-22 13:35:17,819 DEBUG    poll 551.547 ms took 0.190 ms: 2 events
2019-06-22 13:35:18,792 DEBUG    poll 562.312 ms took 419.156 ms: 1 events
2019-06-22 13:35:18,793 DEBUG    Received message 25 on ASGI channel/group simulation_event
2019-06-22 13:35:18,796 DEBUG    Acked delivery 25
2019-06-22 13:35:18,798 DEBUG    Sent WebSocket packet to client for ['::1', 39328]
2019-06-22 13:35:18,799 DEBUG    poll 136.012 ms took 0.025 ms: 1 events
2019-06-22 13:35:18,811 DEBUG    poll 133.303 ms took 9.828 ms: 1 events
2019-06-22 13:35:18,813 DEBUG    Received message 26 on ASGI channel/group simulation_event
2019-06-22 13:35:18,815 DEBUG    Acked delivery 26
2019-06-22 13:35:18,817 DEBUG    poll 118.125 ms took 0.075 ms: 1 events
2019-06-22 13:35:18,817 DEBUG    Sent WebSocket packet to client for ['::1', 39328]
2019-06-22 13:35:18,818 DEBUG    poll 117.184 ms took 0.016 ms: 1 events
2019-06-22 13:35:19,795 DEBUG    poll 999.657 ms took 421.647 ms: 1 events
2019-06-22 13:35:19,796 DEBUG    Received message 27 on ASGI channel/group simulation_event
2019-06-22 13:35:19,798 DEBUG    Acked delivery 27
2019-06-22 13:35:19,799 DEBUG    poll 573.464 ms took 0.064 ms: 1 events
2019-06-22 13:35:19,800 DEBUG    Sent WebSocket packet to client for ['::1', 39328]
2019-06-22 13:35:19,800 DEBUG    poll 572.560 ms took 0.017 ms: 1 events
2019-06-22 13:35:19,816 DEBUG    poll 569.702 ms took 12.519 ms: 1 events
2019-06-22 13:35:19,817 DEBUG    Received message 28 on ASGI channel/group simulation_event
2019-06-22 13:35:19,821 DEBUG    Acked delivery 28
2019-06-22 13:35:19,824 DEBUG    Sent WebSocket packet to client for ['::1', 39328]
2019-06-22 13:35:19,825 DEBUG    poll 548.404 ms took 0.019 ms: 1 events
2019-06-22 13:35:19,827 DEBUG    poll 547.992 ms took 2.357 ms: 1 events
2019-06-22 13:35:20,797 DEBUG    poll 561.750 ms took 422.971 ms: 1 events
2019-06-22 13:35:20,799 DEBUG    Received message 29 on ASGI channel/group simulation_event
2019-06-22 13:35:20,801 DEBUG    Acked delivery 29
2019-06-22 13:35:20,804 DEBUG    Sent WebSocket packet to client for ['::1', 39328]
2019-06-22 13:35:20,804 DEBUG    poll 131.634 ms took 0.025 ms: 1 events
2019-06-22 13:35:20,819 DEBUG    poll 128.906 ms took 12.089 ms: 1 events
2019-06-22 13:35:20,821 DEBUG    Received message 30 on ASGI channel/group simulation_event
2019-06-22 13:35:20,823 DEBUG    Acked delivery 30
2019-06-22 13:35:20,825 DEBUG    Sent WebSocket packet to client for ['::1', 39328]
2019-06-22 13:35:20,827 DEBUG    poll 110.784 ms took 1.854 ms: 1 events
2019-06-22 13:35:21,799 DEBUG    poll 999.643 ms took 423.905 ms: 1 events
2019-06-22 13:35:21,801 DEBUG    Received message 31 on ASGI channel/group simulation_event
2019-06-22 13:35:21,804 DEBUG    Acked delivery 31
2019-06-22 13:35:21,806 DEBUG    Sent WebSocket packet to client for ['::1', 39328]
2019-06-22 13:35:21,807 DEBUG    poll 568.649 ms took 0.025 ms: 1 events
2019-06-22 13:35:21,813 DEBUG    poll 564.506 ms took 2.049 ms: 1 events
2019-06-22 13:35:21,821 DEBUG    poll 557.716 ms took 3.801 ms: 1 events
2019-06-22 13:35:21,823 DEBUG    Received message 32 on ASGI channel/group simulation_event
2019-06-22 13:35:21,825 DEBUG    Acked delivery 32
2019-06-22 13:35:21,827 DEBUG    Sent WebSocket packet to client for ['::1', 39328]
2019-06-22 13:35:21,827 DEBUG    poll 548.018 ms took 0.200 ms: 2 events
2019-06-22 13:35:22,802 DEBUG    poll 558.928 ms took 424.306 ms: 1 events
2019-06-22 13:35:22,804 DEBUG    Received message 33 on ASGI channel/group simulation_event
2019-06-22 13:35:22,807 DEBUG    Acked delivery 33
2019-06-22 13:35:22,809 DEBUG    Sent WebSocket packet to client for ['::1', 39328]
2019-06-22 13:35:22,809 DEBUG    poll 127.017 ms took 0.025 ms: 1 events
2019-06-22 13:35:22,820 DEBUG    poll 126.328 ms took 9.702 ms: 1 events
2019-06-22 13:35:22,826 DEBUG    Received message 34 on ASGI channel/group simulation_event
2019-06-22 13:35:22,830 DEBUG    Acked delivery 34
2019-06-22 13:35:22,832 DEBUG    Sent WebSocket packet to client for ['::1', 39328]
2019-06-22 13:35:22,844 DEBUG    poll 91.960 ms took 0.021 ms: 1 events
2019-06-22 13:35:22,847 DEBUG    poll 91.245 ms took 2.297 ms: 1 events
2019-06-22 13:35:23,804 DEBUG    poll 999.555 ms took 424.825 ms: 1 events
2019-06-22 13:35:23,805 DEBUG    Received message 35 on ASGI channel/group simulation_event
2019-06-22 13:35:23,808 DEBUG    Acked delivery 35
2019-06-22 13:35:23,812 DEBUG    Sent WebSocket packet to client for ['::1', 39328]
2019-06-22 13:35:23,813 DEBUG    poll 565.446 ms took 0.018 ms: 1 events
2019-06-22 13:35:23,827 DEBUG    poll 563.552 ms took 12.335 ms: 1 events
2019-06-22 13:35:23,829 DEBUG    Received message 36 on ASGI channel/group simulation_event
2019-06-22 13:35:23,831 DEBUG    Acked delivery 36
2019-06-22 13:35:23,833 DEBUG    Sent WebSocket packet to client for ['::1', 39328]
2019-06-22 13:35:23,834 DEBUG    poll 544.546 ms took 0.145 ms: 1 events
2019-06-22 13:35:24,806 DEBUG    poll 557.203 ms took 426.162 ms: 1 events
2019-06-22 13:35:24,808 DEBUG    Received message 37 on ASGI channel/group simulation_event
2019-06-22 13:35:24,811 DEBUG    Acked delivery 37
2019-06-22 13:35:24,813 DEBUG    Sent WebSocket packet to client for ['::1', 39328]
2019-06-22 13:35:24,814 DEBUG    poll 123.685 ms took 0.025 ms: 1 events
2019-06-22 13:35:24,831 DEBUG    poll 119.905 ms took 13.885 ms: 1 events
2019-06-22 13:35:24,833 DEBUG    Received message 38 on ASGI channel/group simulation_event
2019-06-22 13:35:24,849 DEBUG    Acked delivery 38
2019-06-22 13:35:24,851 DEBUG    Sent WebSocket packet to client for ['::1', 39328]
2019-06-22 13:35:24,851 DEBUG    poll 86.092 ms took 0.019 ms: 1 events
2019-06-22 13:35:24,939 DEBUG    poll 440.436 ms took 0.022 ms: 1 events
2019-06-22 13:35:24,940 DEBUG    poll 439.882 ms took 0.063 ms: 1 events
2019-06-22 13:35:25,808 DEBUG    poll 999.551 ms took 426.853 ms: 1 events
2019-06-22 13:35:25,811 DEBUG    Received message 39 on ASGI channel/group simulation_event
2019-06-22 13:35:25,814 DEBUG    Acked delivery 39
2019-06-22 13:35:25,818 DEBUG    Sent WebSocket packet to client for ['::1', 39328]
2019-06-22 13:35:25,818 DEBUG    poll 562.714 ms took 0.018 ms: 1 events
2019-06-22 13:35:25,839 DEBUG    poll 560.824 ms took 19.469 ms: 1 events
2019-06-22 13:35:25,841 DEBUG    Received message 40 on ASGI channel/group simulation_event
2019-06-22 13:35:25,844 DEBUG    Acked delivery 40
2019-06-22 13:35:25,845 DEBUG    poll 536.021 ms took 0.510 ms: 1 events
2019-06-22 13:35:25,846 DEBUG    Sent WebSocket packet to client for ['::1', 39328]
2019-06-22 13:35:25,846 DEBUG    poll 534.494 ms took 0.016 ms: 1 events
2019-06-22 13:35:25,847 DEBUG    poll 534.088 ms took 0.174 ms: 1 events
2019-06-22 13:35:26,810 DEBUG    poll 556.491 ms took 427.307 ms: 1 events
2019-06-22 13:35:26,812 DEBUG    Received message 41 on ASGI channel/group simulation_event
2019-06-22 13:35:26,814 DEBUG    Acked delivery 41
2019-06-22 13:35:26,818 DEBUG    Sent WebSocket packet to client for ['::1', 39328]
2019-06-22 13:35:26,818 DEBUG    poll 120.638 ms took 0.018 ms: 1 events
2019-06-22 13:35:26,838 DEBUG    poll 118.753 ms took 18.175 ms: 1 events
2019-06-22 13:35:26,842 DEBUG    Received message 42 on ASGI channel/group simulation_event
2019-06-22 13:35:26,863 DEBUG    Acked delivery 42
2019-06-22 13:35:26,866 DEBUG    Sent WebSocket packet to client for ['::1', 39328]
2019-06-22 13:35:26,867 DEBUG    poll 72.359 ms took 0.160 ms: 2 events
2019-06-22 13:35:27,812 DEBUG    poll 999.555 ms took 427.375 ms: 1 events
2019-06-22 13:35:27,813 DEBUG    Received message 43 on ASGI channel/group simulation_event
2019-06-22 13:35:27,816 DEBUG    Acked delivery 43
2019-06-22 13:35:27,819 DEBUG    Sent WebSocket packet to client for ['::1', 39328]
2019-06-22 13:35:27,819 DEBUG    poll 564.574 ms took 0.025 ms: 1 events
2019-06-22 13:35:27,846 DEBUG    poll 561.356 ms took 23.218 ms: 1 events
2019-06-22 13:35:27,847 DEBUG    Received message 44 on ASGI channel/group simulation_event
2019-06-22 13:35:27,853 DEBUG    Acked delivery 44
2019-06-22 13:35:27,855 DEBUG    Sent WebSocket packet to client for ['::1', 39328]
2019-06-22 13:35:27,855 DEBUG    poll 528.393 ms took 0.164 ms: 2 events
2019-06-22 13:35:28,813 DEBUG    poll 555.173 ms took 427.699 ms: 1 events
2019-06-22 13:35:28,815 DEBUG    Received message 45 on ASGI channel/group simulation_event
2019-06-22 13:35:28,818 DEBUG    Acked delivery 45
2019-06-22 13:35:28,820 DEBUG    Sent WebSocket packet to client for ['::1', 39328]
2019-06-22 13:35:28,820 DEBUG    poll 120.356 ms took 0.025 ms: 1 events
2019-06-22 13:35:28,849 DEBUG    poll 117.345 ms took 25.532 ms: 1 events
2019-06-22 13:35:28,850 DEBUG    Received message 46 on ASGI channel/group simulation_event
2019-06-22 13:35:28,853 DEBUG    Acked delivery 46
2019-06-22 13:35:28,854 DEBUG    Sent WebSocket packet to client for ['::1', 39328]
2019-06-22 13:35:28,855 DEBUG    poll 85.759 ms took 0.158 ms: 2 events
2019-06-22 13:35:29,816 DEBUG    poll 999.666 ms took 429.271 ms: 1 events
2019-06-22 13:35:29,817 DEBUG    Received message 47 on ASGI channel/group simulation_event
2019-06-22 13:35:29,819 DEBUG    Acked delivery 47
2019-06-22 13:35:29,820 DEBUG    Sent WebSocket packet to client for ['::1', 39328]
2019-06-22 13:35:29,821 DEBUG    poll 565.229 ms took 0.017 ms: 1 events
2019-06-22 13:35:29,851 DEBUG    poll 563.345 ms took 28.586 ms: 1 events
2019-06-22 13:35:29,853 DEBUG    Received message 48 on ASGI channel/group simulation_event
2019-06-22 13:35:29,854 DEBUG    Acked delivery 48
2019-06-22 13:35:29,855 DEBUG    poll 530.443 ms took 0.055 ms: 1 events
2019-06-22 13:35:29,856 DEBUG    Sent WebSocket packet to client for ['::1', 39328]
2019-06-22 13:35:29,856 DEBUG    poll 529.544 ms took 0.017 ms: 1 events
2019-06-22 13:35:30,818 DEBUG    poll 553.709 ms took 430.518 ms: 1 events
2019-06-22 13:35:30,820 DEBUG    Received message 49 on ASGI channel/group simulation_event
2019-06-22 13:35:30,822 DEBUG    Acked delivery 49
2019-06-22 13:35:30,826 DEBUG    Sent WebSocket packet to client for ['::1', 39328]
2019-06-22 13:35:30,826 DEBUG    poll 114.742 ms took 0.018 ms: 1 events
2019-06-22 13:35:30,862 DEBUG    poll 112.823 ms took 32.580 ms: 1 events
2019-06-22 13:35:30,864 DEBUG    Received message 50 on ASGI channel/group simulation_event
2019-06-22 13:35:30,866 DEBUG    Acked delivery 50
2019-06-22 13:35:30,868 DEBUG    Sent WebSocket packet to client for ['::1', 39328]
2019-06-22 13:35:30,869 DEBUG    poll 72.075 ms took 0.118 ms: 1 events
2019-06-22 13:35:31,820 DEBUG    poll 999.555 ms took 431.411 ms: 1 events
2019-06-22 13:35:31,821 DEBUG    Received message 51 on ASGI channel/group simulation_event
2019-06-22 13:35:31,824 DEBUG    Acked delivery 51
2019-06-22 13:35:31,826 DEBUG    Sent WebSocket packet to client for ['::1', 39328]
2019-06-22 13:35:31,827 DEBUG    poll 561.076 ms took 0.025 ms: 1 events
2019-06-22 13:35:31,859 DEBUG    poll 558.214 ms took 29.008 ms: 1 events
2019-06-22 13:35:31,860 DEBUG    Received message 52 on ASGI channel/group simulation_event
2019-06-22 13:35:31,862 DEBUG    Acked delivery 52
2019-06-22 13:35:31,864 DEBUG    Sent WebSocket packet to client for ['::1', 39328]
2019-06-22 13:35:31,864 DEBUG    poll 523.450 ms took 0.019 ms: 1 events
2019-06-22 13:35:32,822 DEBUG    poll 552.627 ms took 432.519 ms: 1 events
2019-06-22 13:35:32,824 DEBUG    Received message 53 on ASGI channel/group simulation_event
2019-06-22 13:35:32,826 DEBUG    Acked delivery 53
2019-06-22 13:35:32,830 DEBUG    Sent WebSocket packet to client for ['::1', 39328]
2019-06-22 13:35:32,830 DEBUG    poll 111.591 ms took 0.019 ms: 1 events
2019-06-22 13:35:32,861 DEBUG    poll 107.879 ms took 27.356 ms: 1 events
2019-06-22 13:35:32,863 DEBUG    Received message 54 on ASGI channel/group simulation_event
2019-06-22 13:35:32,865 DEBUG    Acked delivery 54
2019-06-22 13:35:32,867 DEBUG    Sent WebSocket packet to client for ['::1', 39328]
2019-06-22 13:35:32,872 DEBUG    poll 70.367 ms took 0.476 ms: 2 events
2019-06-22 13:35:33,823 DEBUG    poll 999.629 ms took 433.268 ms: 1 events
2019-06-22 13:35:33,825 DEBUG    Received message 55 on ASGI channel/group simulation_event
2019-06-22 13:35:33,936 WARNING  Executing <Handle <TaskWakeupMethWrapper object at 0x7f1556248108>(<Future finis...events.py:295>) created at /usr/local/lib/python3.6/asyncio/streams.py:399> took 0.112 seconds
2019-06-22 13:35:33,938 DEBUG    Acked delivery 55
2019-06-22 13:35:33,940 DEBUG    Received message 56 on ASGI channel/group simulation_event
2019-06-22 13:35:33,943 DEBUG    Acked delivery 56
2019-06-22 13:35:33,945 DEBUG    Sent WebSocket packet to client for ['::1', 39328]
2019-06-22 13:35:33,945 DEBUG    poll 444.065 ms took 0.026 ms: 1 events
2019-06-22 13:35:33,952 DEBUG    Sent WebSocket packet to client for ['::1', 39328]
2019-06-22 13:35:33,955 DEBUG    poll 435.173 ms took 0.333 ms: 2 events
2019-06-22 13:35:34,825 DEBUG    poll 551.875 ms took 434.692 ms: 1 events
2019-06-22 13:35:34,827 DEBUG    Received message 57 on ASGI channel/group simulation_event
2019-06-22 13:35:34,830 DEBUG    Acked delivery 57
2019-06-22 13:35:34,833 DEBUG    Sent WebSocket packet to client for ['::1', 39328]
2019-06-22 13:35:34,833 DEBUG    poll 109.555 ms took 0.025 ms: 1 events
2019-06-22 13:35:34,894 DEBUG    poll 106.878 ms took 58.115 ms: 1 events
2019-06-22 13:35:34,896 DEBUG    Received message 58 on ASGI channel/group simulation_event
2019-06-22 13:35:34,899 DEBUG    Acked delivery 58
2019-06-22 13:35:34,904 DEBUG    poll 38.470 ms took 0.159 ms: 1 events
2019-06-22 13:35:34,907 DEBUG    Sent WebSocket packet to client for ['::1', 39328]
2019-06-22 13:35:34,908 DEBUG    poll 34.923 ms took 0.200 ms: 2 events
2019-06-22 13:35:35,827 DEBUG    poll 999.551 ms took 435.708 ms: 1 events
2019-06-22 13:35:35,829 DEBUG    Received message 59 on ASGI channel/group simulation_event
2019-06-22 13:35:35,832 DEBUG    Acked delivery 59
2019-06-22 13:35:35,834 DEBUG    Sent WebSocket packet to client for ['::1', 39328]
2019-06-22 13:35:35,834 DEBUG    poll 556.746 ms took 0.026 ms: 1 events
2019-06-22 13:35:35,897 DEBUG    poll 554.189 ms took 60.537 ms: 1 events
2019-06-22 13:35:35,899 DEBUG    Received message 60 on ASGI channel/group simulation_event
2019-06-22 13:35:35,903 DEBUG    Acked delivery 60
2019-06-22 13:35:35,905 DEBUG    Sent WebSocket packet to client for ['::1', 39328]
2019-06-22 13:35:35,905 DEBUG    poll 485.689 ms took 0.018 ms: 1 events
2019-06-22 13:35:36,829 DEBUG    poll 550.999 ms took 436.969 ms: 1 events
2019-06-22 13:35:36,831 DEBUG    Received message 61 on ASGI channel/group simulation_event
2019-06-22 13:35:36,834 DEBUG    Acked delivery 61
2019-06-22 13:35:36,836 DEBUG    Sent WebSocket packet to client for ['::1', 39328]
2019-06-22 13:35:36,836 DEBUG    poll 106.836 ms took 0.026 ms: 1 events
2019-06-22 13:35:36,901 DEBUG    poll 104.069 ms took 61.299 ms: 1 events
2019-06-22 13:35:36,903 DEBUG    Received message 62 on ASGI channel/group simulation_event
2019-06-22 13:35:36,906 DEBUG    Acked delivery 62
2019-06-22 13:35:36,909 DEBUG    Sent WebSocket packet to client for ['::1', 39328]
2019-06-22 13:35:36,911 DEBUG    poll 32.512 ms took 0.164 ms: 1 events
2019-06-22 13:35:36,918 DEBUG    poll 31.768 ms took 6.859 ms: 1 events
2019-06-22 13:35:37,831 DEBUG    poll 999.558 ms took 437.513 ms: 1 events
2019-06-22 13:35:37,833 DEBUG    Received message 63 on ASGI channel/group simulation_event
2019-06-22 13:35:37,836 DEBUG    Acked delivery 63
2019-06-22 13:35:37,838 DEBUG    Sent WebSocket packet to client for ['::1', 39328]
2019-06-22 13:35:37,839 DEBUG    poll 554.680 ms took 0.025 ms: 1 events
2019-06-22 13:35:37,903 DEBUG    poll 552.151 ms took 62.110 ms: 1 events
2019-06-22 13:35:37,905 DEBUG    Received message 64 on ASGI channel/group simulation_event
2019-06-22 13:35:37,908 DEBUG    Acked delivery 64
2019-06-22 13:35:37,911 DEBUG    Sent WebSocket packet to client for ['::1', 39328]
2019-06-22 13:35:37,911 DEBUG    poll 482.025 ms took 0.025 ms: 1 events
2019-06-22 13:35:38,833 DEBUG    poll 549.039 ms took 437.829 ms: 1 events
2019-06-22 13:35:38,835 DEBUG    Received message 65 on ASGI channel/group simulation_event
2019-06-22 13:35:38,838 DEBUG    Acked delivery 65
2019-06-22 13:35:38,842 DEBUG    Sent WebSocket packet to client for ['::1', 39328]
2019-06-22 13:35:38,842 DEBUG    poll 102.156 ms took 0.018 ms: 1 events
2019-06-22 13:35:38,905 DEBUG    poll 100.215 ms took 60.485 ms: 1 events
2019-06-22 13:35:38,908 DEBUG    Received message 66 on ASGI channel/group simulation_event
2019-06-22 13:35:38,911 DEBUG    Acked delivery 66
2019-06-22 13:35:38,914 DEBUG    Sent WebSocket packet to client for ['::1', 39328]
2019-06-22 13:35:38,914 DEBUG    poll 30.279 ms took 0.026 ms: 1 events
2019-06-22 13:35:39,835 DEBUG    poll 999.556 ms took 438.499 ms: 1 events
2019-06-22 13:35:39,837 DEBUG    Received message 67 on ASGI channel/group simulation_event
2019-06-22 13:35:39,840 DEBUG    Acked delivery 67
2019-06-22 13:35:39,842 DEBUG    Sent WebSocket packet to client for ['::1', 39328]
2019-06-22 13:35:39,843 DEBUG    poll 553.858 ms took 0.025 ms: 1 events
2019-06-22 13:35:39,908 DEBUG    poll 550.943 ms took 62.401 ms: 1 events
2019-06-22 13:35:39,910 DEBUG    Received message 68 on ASGI channel/group simulation_event
2019-06-22 13:35:39,912 DEBUG    Acked delivery 68
2019-06-22 13:35:39,915 DEBUG    Sent WebSocket packet to client for ['::1', 39328]
2019-06-22 13:35:39,916 DEBUG    poll 480.659 ms took 0.026 ms: 1 events
2019-06-22 13:35:40,840 DEBUG    poll 545.584 ms took 440.617 ms: 1 events
2019-06-22 13:35:40,842 DEBUG    Received message 69 on ASGI channel/group simulation_event
2019-06-22 13:35:40,844 DEBUG    Acked delivery 69
2019-06-22 13:35:40,847 DEBUG    Sent WebSocket packet to client for ['::1', 39328]
2019-06-22 13:35:40,847 DEBUG    poll 97.773 ms took 0.025 ms: 1 events
2019-06-22 13:35:40,909 DEBUG    poll 93.183 ms took 57.816 ms: 1 events
2019-06-22 13:35:40,911 DEBUG    Received message 70 on ASGI channel/group simulation_event
2019-06-22 13:35:40,913 DEBUG    Acked delivery 70
2019-06-22 13:35:40,917 DEBUG    Sent WebSocket packet to client for ['::1', 39328]
2019-06-22 13:35:40,918 DEBUG    poll 26.339 ms took 0.022 ms: 1 events
2019-06-22 13:35:41,842 DEBUG    poll 999.557 ms took 441.683 ms: 1 events
2019-06-22 13:35:41,844 DEBUG    Received message 71 on ASGI channel/group simulation_event
2019-06-22 13:35:41,846 DEBUG    Acked delivery 71
2019-06-22 13:35:41,851 DEBUG    Sent WebSocket packet to client for ['::1', 39328]
2019-06-22 13:35:41,851 DEBUG    poll 548.534 ms took 0.019 ms: 1 events
2019-06-22 13:35:41,912 DEBUG    poll 546.298 ms took 58.237 ms: 1 events
2019-06-22 13:35:41,914 DEBUG    Received message 72 on ASGI channel/group simulation_event
2019-06-22 13:35:41,917 DEBUG    Acked delivery 72
2019-06-22 13:35:41,923 DEBUG    Sent WebSocket packet to client for ['::1', 39328]
2019-06-22 13:35:41,923 DEBUG    poll 476.658 ms took 0.200 ms: 2 events
2019-06-22 13:35:42,844 DEBUG    poll 540.059 ms took 438.512 ms: 1 events
2019-06-22 13:35:42,846 DEBUG    Received message 73 on ASGI channel/group simulation_event
2019-06-22 13:35:42,849 DEBUG    Acked delivery 73
2019-06-22 13:35:42,851 DEBUG    Sent WebSocket packet to client for ['::1', 39328]
2019-06-22 13:35:42,851 DEBUG    poll 94.410 ms took 0.025 ms: 1 events
2019-06-22 13:35:42,914 DEBUG    poll 91.414 ms took 59.170 ms: 1 events
2019-06-22 13:35:42,915 DEBUG    Received message 74 on ASGI channel/group simulation_event
2019-06-22 13:35:42,917 DEBUG    Acked delivery 74
2019-06-22 13:35:42,919 DEBUG    Sent WebSocket packet to client for ['::1', 39328]
2019-06-22 13:35:42,919 DEBUG    poll 26.595 ms took 0.145 ms: 2 events
2019-06-22 13:35:44,408 INFO     poll 999.550 ms took 1001.064 ms: timeout
2019-06-22 13:35:44,949 DEBUG    poll 460.152 ms took 0.022 ms: 1 events
2019-06-22 13:35:44,949 DEBUG    poll 459.344 ms took 0.020 ms: 1 events
2019-06-22 13:35:46,412 INFO     poll 999.551 ms took 1000.895 ms: timeout
2019-06-22 13:35:48,415 INFO     poll 999.564 ms took 1001.069 ms: timeout
2019-06-22 13:35:50,417 INFO     poll 999.557 ms took 1001.060 ms: timeout
2019-06-22 13:35:52,420 INFO     poll 999.563 ms took 1000.713 ms: timeout
2019-06-22 13:35:54,422 INFO     poll 999.563 ms took 1001.051 ms: timeout

@adamhooper
Copy link
Contributor

Thank you so much for all this testing. One last question: if you use a object-scoped asyncio.Lock around your group_send call, does the problem persist?

@nnseva
Copy link
Contributor Author

nnseva commented Jun 24, 2019

Hi @adamhooper,

When the lock (upd: around a group_send call) is used, the issue disappears.

@adamhooper
Copy link
Contributor

Thank you for this awesome testing! I look forward to fixing this when I return, second week of July. In the meantime, asyncio.Lock seems like a tolerable workaround :)

@adamhooper
Copy link
Contributor

adamhooper commented Jul 9, 2019

A lock is the actual solution, so I'm adding it to channels_rabbitmq. I'm also filing Polyconseil/aioamqp#205 to clear up ambiguity.

This is fixed in v1.1.4 (which Travis should publish momentarily).

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants