Channels issue under load

[Filbert]

Multi-tenant Django application with 100's of WebSockets using Daphne/Channels.

channels==2.4.0

channels-redis==2.4.2

daphne==2.5.0

Django==2.2.13

Only clue I have at this point is WebClients seem to hang up waiting for messages that are not delivered.  I see in the Django logs "RuntimeError: Lock is not acquired." over and over throughout the day.

Sample client code I have here causes the issue at will.  I can only hit it with 20 or so tasks before it falls over.

import time

async def test_socket(n, url, count, delay):

    uri = 'wss://{0}/ws/'.format(url)

    print('Starting task {0}...'.format(n))

    async with websockets.connect(uri, close_timeout=5, ping_interval=5, ping_timeout=5) as websocket:

        payload = '{"stream":"ping", "payload":{}}'

        for i in range(0, count):

            print('TASK {0} : Channels/daphne request {1} times'.format(n, i))

            await websocket.send(payload)

            asyncio.sleep(delay)

            response = await asyncio.wait_for(websocket.recv(), timeout=30)

            print('TASK {0} : Channels/daphne for responded {1} {2} times'.format(n, i, response))

async def start_tasks(loop, url, count, delay, tasks):

    t = [test_socket(n, url, count, delay) for n in range (0, tasks)]

    await asyncio.gather(*t, loop=loop)

if __name__ == "__main__":

    parser = argparse.ArgumentParser()

    parser.add_argument('--url', type=str, help='url to hit')

    parser.add_argument('--count', type=int, default=1, help='number of iterations')

    parser.add_argument('--delay', type=int, default=1, help='delay in 10ths of a second')

    parser.add_argument('--tasks', type=int, default=1, help='number of tasks')

    args = parser.parse_args()

    loop = asyncio.get_event_loop()

    try:

        result = loop.run_until_complete(start_tasks(loop, args.url, args.count, args.delay, args.tasks))

    except Exception as ex:

        print(ex)

[Filbert]

And strangely I am seeing blocks of this in the log as well here and there from Daphne. (Ignore the XX). 

XX.240.122.161:443 - - [14/May/2021:13:36:09] "WSCONNECTING /ws/" - -

XX.240.122.161:443 - - [14/May/2021:13:36:09] "WSCONNECT /ws/" - -

XX7.0.61.54:443 - - [14/May/2021:13:37:50] "WSCONNECTING /ws/" - -

XX7.0.61.54:443 - - [14/May/2021:13:37:50] "WSCONNECT /ws/" - -

XX4.108.212.90:443 - - [14/May/2021:13:42:10] "WSCONNECTING /ws/" - -

XX4.108.212.90:443 - - [14/May/2021:13:42:10] "WSCONNECT /ws/" - -

XX.123.245.94:443 - - [14/May/2021:13:47:30] "WSCONNECTING /ws/" - -

XX.123.245.94:443 - - [14/May/2021:13:47:30] "WSCONNECT /ws/" - -

XX.131.52.248:443 - - [14/May/2021:13:48:31] "WSCONNECTING /ws/" - -

XX.131.52.248:443 - - [14/May/2021:13:48:31] "WSCONNECT /ws/" - -

XX.123.245.94:443 - - [14/May/2021:13:53:06] "WSCONNECTING /ws/" - -

XX.123.245.94:443 - - [14/May/2021:13:53:06] "WSCONNECT /ws/" - -

XX.123.245.90:443 - - [14/May/2021:13:55:39] "WSCONNECTING /ws/" - -

XX.123.245.90:443 - - [14/May/2021:13:55:39] "WSCONNECT /ws/" - -

XX.240.122.161:443 - - [14/May/2021:14:02:46] "WSCONNECTING /ws/" - -

XX.240.122.161:443 - - [14/May/2021:14:02:46] "WSCONNECT /ws/" - -

XX.123.245.94:443 - - [14/May/2021:14:08:05] "WSDISCONNECT /ws/" - -

XX4.108.212.90:443 - - [14/May/2021:14:09:22] "WSCONNECTING /ws/" - -

XX4.108.212.90:443 - - [14/May/2021:14:09:22] "WSCONNECT /ws/" - -

XX.247.160.89:443 - - [14/May/2021:14:10:20] "WSCONNECTING /ws/" - -

XX.247.160.89:443 - - [14/May/2021:14:10:20] "WSCONNECT /ws/" - -

XX.142.149.206:443 - - [14/May/2021:14:11:53] "WSCONNECTING /ws/" - -

XX.142.149.206:443 - - [14/May/2021:14:11:53] "WSCONNECT /ws/" - -

XX.240.122.186:443 - - [14/May/2021:14:13:38] "WSCONNECTING /ws/" - -

XX.240.122.186:443 - - [14/May/2021:14:13:38] "WSCONNECT /ws/" - -

XX.142.150.22:443 - - [14/May/2021:14:20:20] "WSCONNECTING /ws/" - -

XX.142.150.22:443 - - [14/May/2021:14:20:20] "WSCONNECT /ws/" - -

XX7.0.61.54:443 - - [14/May/2021:14:23:12] "WSDISCONNECT /ws/" - -

XX.123.245.94:443 - - [14/May/2021:14:26:18] "WSCONNECTING /ws/" - -

XX.123.245.94:443 - - [14/May/2021:14:26:18] "WSCONNECT /ws/" - -

XX.178.167.247:443 - - [14/May/2021:14:28:20] "WSCONNECTING /ws/" - -

XX.178.167.247:443 - - [14/May/2021:14:28:20] "WSCONNECT /ws/" - -

XX.207.233.198:443 - - [14/May/2021:14:30:10] "WSCONNECTING /ws/" - -

XX.207.233.198:443 - - [14/May/2021:14:30:10] "WSCONNECT /ws/" - -

XX.207.233.198:443 - - [14/May/2021:14:30:10] "WSCONNECTING /ws/" - -

XX.207.233.198:443 - - [14/May/2021:14:30:10] "WSCONNECT /ws/" - -

XX.207.233.198:443 - - [14/May/2021:14:30:11] "WSDISCONNECT /ws/" - -

XX.207.233.198:443 - - [14/May/2021:14:30:20] "WSCONNECTING /ws/" - -

XX.207.233.198:443 - - [14/May/2021:14:30:20] "WSCONNECT /ws/" - -

XX.207.233.198:443 - - [14/May/2021:14:30:21] "WSCONNECTING /ws/" - -

XX.207.233.198:443 - - [14/May/2021:14:30:21] "WSCONNECT /ws/" - -

XX7.0.61.54:443 - - [14/May/2021:14:33:26] "WSCONNECTING /ws/" - -

[Filbert]

I see this is likely something with channels_redis, is this an indicator of a bug or redis going offline (no indication it did) ??