Failed to execute 'send' on 'WebSocket': Still in CONNECTING state.

[JulianOrteil]

@GibbsConsulting I am encountering this issue in the browser console more and more as the complexity of my project increases. I am unsure where this is coming from, but I am hoping we'll be able to solve it as it becoming quite an issue for me. Here is the full-stack trace for your debugging purposes from the browser console:

This is happening right after page load, but before any of my dpd.Pipe objects receive data from the server.

[GibbsConsulting]

@JulianOrteil how are you running the Django server, and what does its logging output show when the websockets are successful?

[JulianOrteil]

@GibbsConsulting Right now, just in development using python manage.py runserver 0.0.0.0:8000. I haven't tested this using a simulated production environment as I don't have one set up. I am using VSCode's debugger if that would make any difference. As for the logging output, they say they connect, but the error still shows. I think the error occurs BEFORE the WebSocket finalizes its connection with the server.

I used to develop this server in a dedicated docker container (using VSCode's Remote Containers functionality); however, this issue has forced me to develop locally. In essence: in docker, this issue was basically constant. Every time I pulled open the page in my browser, this would occur. In a local environment, this became intermittent, but occurring more often than not.

The output on the server from when the request is received to when everything is finished:

2022-02-26 12:38:35.255 | INFO     | channels.management.commands.runserver:log_action:147 - HTTP GET /circuits/280106/ 200 [0.38, 127.0.0.1:60272]
2022-02-26 12:38:35.267 | INFO     | channels.management.commands.runserver:log_action:166 - WebSocket DISCONNECT /ws/circuits/280106/ [127.0.0.1:60280]
2022-02-26 12:38:35.268 | INFO     | channels.management.commands.runserver:log_action:166 - WebSocket DISCONNECT /dpd/ws/channel [127.0.0.1:60276]
2022-02-26 12:38:35.269 | INFO     | apps.circuits.consumers:disconnect:37 - User 'AnonymousUser' is disconnecting
2022-02-26 12:38:35.269 | DEBUG    | apps.circuits.consumers:disconnect:40 - Deleting client's dedicated channel
2022-02-26 12:38:35.273 | DEBUG    | apps.circuits.consumers:disconnect:44 - Clearing device status consumers cache
2022-02-26 12:38:35.313 | INFO     | apps.circuits.consumers:disconnect:51 - Client has successfully disconnected
2022-02-26 12:38:35.354 | INFO     | channels.management.commands.runserver:log_action:153 - HTTP GET /django_plotly_dash/app/280106/_dash-component-suites/dash_renderer/polyfill@7.v1_9_1m1641826001.8.7.min.js 302 [0.06, 127.0.0.1:60272]
2022-02-26 12:38:35.400 | INFO     | channels.management.commands.runserver:log_action:153 - HTTP GET /django_plotly_dash/app/280106/_dash-component-suites/dash_renderer/react@16.v1_9_1m1641826001.14.0.min.js 302 [0.10, 127.0.0.1:60274]
2022-02-26 12:38:35.516 | INFO     | channels.management.commands.runserver:log_action:153 - HTTP GET /django_plotly_dash/app/280106/_dash-component-suites/dash_renderer/react-dom@16.v1_9_1m1641826001.14.0.min.js 302 [0.03, 127.0.0.1:60274]
2022-02-26 12:38:35.520 | INFO     | channels.management.commands.runserver:log_action:147 - HTTP GET /static/js/bootstrap/popper.min.js.map 200 [0.03, 127.0.0.1:60270]
2022-02-26 12:38:35.524 | INFO     | channels.management.commands.runserver:log_action:147 - HTTP GET /static/js/bootstrap/bootstrap.min.js.map 200 [0.04, 127.0.0.1:60264]
2022-02-26 12:38:35.562 | INFO     | channels.management.commands.runserver:log_action:153 - HTTP GET /django_plotly_dash/app/280106/_dash-component-suites/dash_renderer/prop-types@15.v1_9_1m1641826001.7.2.min.js 302 [0.08, 127.0.0.1:60272]
2022-02-26 12:38:35.597 | INFO     | channels.management.commands.runserver:log_action:153 - HTTP GET /django_plotly_dash/app/280106/_dash-component-suites/dpd_components/bundle.v0_1_0m1641826002.js 302 [0.11, 127.0.0.1:60266]
2022-02-26 12:38:35.636 | INFO     | channels.management.commands.runserver:log_action:153 - HTTP GET /django_plotly_dash/app/280106/_dash-component-suites/dash_html_components/dash_html_components.v1_1_3m1642018158.min.js 302 [0.15, 127.0.0.1:60268]
2022-02-26 12:38:35.638 | INFO     | channels.management.commands.runserver:log_action:147 - HTTP GET /static/css/bootstrap/bootstrap.min.css.map 200 [0.12, 127.0.0.1:60274]
2022-02-26 12:38:35.670 | INFO     | channels.management.commands.runserver:log_action:153 - HTTP GET /django_plotly_dash/app/280106/_dash-component-suites/dash_bootstrap_components/_components/dash_bootstrap_components.v1_0_2m1642018153.min.js 302 [0.12, 127.0.0.1:60264]
2022-02-26 12:38:35.696 | INFO     | channels.management.commands.runserver:log_action:153 - HTTP GET /django_plotly_dash/app/280106/_dash-component-suites/dash_core_components/dash_core_components.v1_16_0m1642018159.min.js 302 [0.15, 127.0.0.1:60270]
2022-02-26 12:38:35.727 | INFO     | channels.management.commands.runserver:log_action:153 - HTTP GET /django_plotly_dash/app/280106/_dash-component-suites/dash_core_components/dash_core_components-shared.v1_16_0m1642018159.js 302 [0.15, 127.0.0.1:60272]
2022-02-26 12:38:35.764 | INFO     | channels.management.commands.runserver:log_action:153 - HTTP GET /django_plotly_dash/app/280106/_dash-component-suites/dash_renderer/dash_renderer.v1_9_1m1641826001.min.js 302 [0.16, 127.0.0.1:60266]
2022-02-26 12:38:35.810 | INFO     | channels.management.commands.runserver:log_action:168 - WebSocket HANDSHAKING /dpd/ws/channel [127.0.0.1:60282]
2022-02-26 12:38:35.817 | INFO     | channels.management.commands.runserver:log_action:153 - HTTP GET /django_plotly_dash/app/280106/_dash-component-suites/dash_html_components/dash_html_components.min.js.map 302 [0.16, 127.0.0.1:60274]
2022-02-26 12:38:35.870 | INFO     | channels.management.commands.runserver:log_action:153 - HTTP GET /django_plotly_dash/app/280106/_dash-component-suites/dash_core_components/dash_core_components.min.js.map 302 [0.13, 127.0.0.1:60272]
2022-02-26 12:38:35.895 | INFO     | channels.management.commands.runserver:log_action:153 - HTTP GET /django_plotly_dash/app/280106/_dash-component-suites/dash_core_components/dash_core_components-shared.js.map 302 [0.14, 127.0.0.1:60270]
2022-02-26 12:38:35.900 | INFO     | channels.management.commands.runserver:log_action:147 - HTTP GET /static/dash/component/dash_html_components/dash_html_components.min.js.map 200 [0.07, 127.0.0.1:60274]
2022-02-26 12:38:35.907 | INFO     | channels.management.commands.runserver:log_action:147 - HTTP GET /static/dash/component/dash_core_components/dash_core_components.min.js.map 200 [0.03, 127.0.0.1:60272]
2022-02-26 12:38:35.980 | INFO     | channels.management.commands.runserver:log_action:147 - HTTP GET /django_plotly_dash/app/280106/_dash-layout 200 [0.17, 127.0.0.1:60266]
2022-02-26 12:38:36.017 | INFO     | channels.management.commands.runserver:log_action:147 - HTTP GET /django_plotly_dash/app/280106/_dash-dependencies 200 [0.20, 127.0.0.1:60264]
2022-02-26 12:38:36.022 | INFO     | channels.management.commands.runserver:log_action:147 - HTTP GET /static/dash/component/dash_core_components/dash_core_components-shared.js.map 200 [0.12, 127.0.0.1:60270]
2022-02-26 12:38:36.024 | INFO     | channels.management.commands.runserver:log_action:164 - WebSocket CONNECT /dpd/ws/channel [127.0.0.1:60282]
2022-02-26 12:38:36.039 | INFO     | channels.management.commands.runserver:log_action:168 - WebSocket HANDSHAKING /ws/circuits/280106/ [127.0.0.1:60284]
2022-02-26 12:38:36.086 | INFO     | channels.management.commands.runserver:log_action:153 - HTTP GET /django_plotly_dash/app/280106/_dash-component-suites/dash_core_components/async-plotlyjs.js 302 [0.05, 127.0.0.1:60264]
2022-02-26 12:38:36.115 | INFO     | channels.management.commands.runserver:log_action:153 - HTTP GET /django_plotly_dash/app/280106/_dash-component-suites/dash_core_components/async-graph.js 302 [0.08, 127.0.0.1:60266]
2022-02-26 12:38:36.119 | INFO     | apps.circuits.consumers:connect:14 - Incoming connection
2022-02-26 12:38:36.120 | DEBUG    | apps.circuits.consumers:connect:18 - User 'AnonymousUser' is connecting
2022-02-26 12:38:36.120 | DEBUG    | apps.circuits.consumers:connect:21 - Creating client's dedicated channel
2022-02-26 12:38:36.127 | INFO     | channels.management.commands.runserver:log_action:164 - WebSocket CONNECT /ws/circuits/280106/ [127.0.0.1:60284]
2022-02-26 12:38:36.128 | DEBUG    | apps.circuits.consumers:connect:27 - Caching client's device status consumer information
2022-02-26 12:38:36.158 | INFO     | apps.circuits.consumers:connect:34 - New consumer client successfully connected
2022-02-26 12:38:36.204 | INFO     | channels.management.commands.runserver:log_action:153 - HTTP GET /django_plotly_dash/app/280106/_dash-component-suites/dash_core_components/async-graph.js.map 302 [0.07, 127.0.0.1:60266]
2022-02-26 12:38:36.217 | INFO     | channels.management.commands.runserver:log_action:147 - HTTP GET /static/dash/component/dash_core_components/async-graph.js.map 200 [0.00, 127.0.0.1:60266]
2022-02-26 12:38:37.150 | DEBUG    | apps.circuits.jwspeaker._280106.views:delayed_send:66 - Triggering initial data display

A note about the technology my server employs:

• DB is a SQL Server, not a local DB like Postgres or sqlite3
• I use Dash and Bootstrap 5 for the frontend
• Apart from dpd's websocket connection, which I don't touch (except for what I mention in Live-Updating: ValueError: No route found for path 'dpd/ws/channel' #376), I have another websocket for other things I need
• I use AJAX heavily, but not during page load

[GibbsConsulting]

Are you able to run with all-but-one websocket disabled, and/or with a production setup -> given the fault is intermittent and appears to be somewhat environment dependent, it could be due to some sort of resource contention such as thread locking.

[JulianOrteil]

@GibbsConsulting Disabling all websockets beyond dpd's still results in the issue. I don't see much of a change in terms of consistency. As for the environment, I can certainly try to get a clone of the production environment; however, that will take some time. The production environment runs an NGINX/Gunicorn (Uvicorn)/Redis setup.

Also, apologies for leaving this out, the server also runs entirely as ASGI using asyncio. Both HTTP and WebSockets. Because of the large amounts of data input this server receives, WSGI just isn't able to keep up (data isn't during development, so this isn't the issue).

In the meantime, is there anything we can do to mitigate the error in websocketbridge.js?

[JulianOrteil]

@GibbsConsulting Okay, so I was able to reproduce a simulated production environment for the webserver and it does not appear this issue is being repro'd. However, I'm running into a whole host of new issues, but those are beyond the scope of this ticket.

[JulianOrteil]

@GibbsConsulting Further debugging has revealed that this might be an upstream issue with asgiref and, as you are probably correct in hypothesizing is a resource output limitation by asgiref. I was running asgiref 3.3.4 to avoid 3.4.0 and its deadlocking issue. That appears to be resolved and I am now running on 3.5.0. Switching to 3.5.0 seems to have helped a little bit, but not too much.

I did some more searching and decided to try and create a work-around in websocketbridge.js:

// line 182:
this.send = function (data) {
    if (ws.readyState == WebSocket.OPEN){
        ws.send(data);
    } else {
        setTimeout(() => {
            this.send(data);
        }, 100);
    }
};

This appears to have worked. Is this something you'd be interested in having a PR opened for?

Jules

[GibbsConsulting]

@JulianOrteil pull requests are always welcome! Not massively keen on maintaining websocketbridge.js but we now have it in our codebase as its original source (channels, IIRC) dropped it somewhat abruptly, so I think we'll have to address the issue rather than wait for it to be fixed elsewhere.

How were you running Django in the environment(s) that exhibited the issue? I'm wondering if running in a limited test environment (eg with limited number of threads) could be contributing to any resource contention.

[JulianOrteil]

@GibbsConsulting

In three different types of environments: two in development and one in production. In my development environments, I was just running Django using python manage.py runserver with DEBUG=True. All static and media resources were being served by Django and its underlying delivery systems.

Development environment 1 was through a local docker container. When running in this configuration, this issue was always occurring. I could not get one instance where it wouldn't fail. I was using VSCode's Remote Containers extension so all development was done in the container. I could see the websocket connect in the server's stdout so it wasn't a docker issue.

Development environment 2 was entirely local. When running in this configuration, this issue became intermittent yet occurred more often than not. Attempting hard refreshes (CTRL + Shift + R) did not show any major difference when compared against normal refreshes.

The production environment runs a Gunicorn/Uvicorn + NGINX + Redis configuration on a Linux box. NGINX is the media server in production and I don't recall if I ever saw the issue show up. I remember it occurred once in the simulated environment you asked me to implement. It is basically a clone of production.

I'll also mention that the server is entirely ASGI. All requests are handled in an async manner. I'll open a PR to implement the above patch for this issue. I've been running it now for the last 2-ish weeks and haven't encountered this issue since.

[JulianOrteil]

PR #387 is ready.