Extension-websocket prints "Waiting for socket to be available for reading"

Sorry for blaming my own faulty server code on you, and thanks for 1.1.0!

2 Likes

Did the upgrade to 1.1.0 work for you?
Or do you still have the problem?

1 Like

Afraid the error persists after altering my server code to accept all requests unmoderated via autoAcceptConnections: true (since without it, only specific protocols can be accepted which are requested by the client but extension-websocket doesn’t support protocols).
The error persists across both my main defold project and my “bare-bones” extension-websocket-test project.
Log in ParryChat:

WARNING:WEBSOCKET: STATE_CONNECTING -> STATE_HANDSHAKE_WRITE
DEBUG:SCRIPT: here
Registered dhttp Extension
INFO:DLIB: SSDP: Started on address 192.168.4.106
WARNING:WEBSOCKET: STATE_HANDSHAKE_WRITE -> STATE_HANDSHAKE_READ
Sent buffer: 'GET /' 5 bytes
Sent buffer: '' 0 bytes
Sent buffer: ' HTTP/1.1\r\n' 11 bytes
Sent buffer: 'Host: ' 6 bytes
Sent buffer: 'parry-host.grify.repl.co' 24 bytes
Sent buffer: '' 0 bytes
Sent buffer: '\r\n' 2 bytes
Sent buffer: 'Upgrade: websocket\r\n' 20 bytes
Sent buffer: 'Connection: Upgrade\r\n' 21 bytes
Sent buffer: 'Sec-WebSocket-Key: ' 19 bytes
Sent buffer: 'h1xoDO5vEQOrPWEJUvTUtA==' 24 bytes
Sent buffer: '\r\n' 2 bytes
Sent buffer: 'Sec-WebSocket-Version: 13\r\n' 27 bytes
Sent buffer: '\r\n' 2 bytes
ERROR:WEBSOCKET: Failed to find valid key in the response headers
ERROR:WEBSOCKET: Response:
""

WARNING:WEBSOCKET: STATUS: 'Failed verifying handshake headers:

'  len: 38
WARNING:WEBSOCKET: STATE_HANDSHAKE_READ -> STATE_DISCONNECTED
Received bytes: 'HTTP/1.1 101 Switching Protocols\r\nConnection: Upgrade\r\nSec-Websocket-Accept: +YhSgSUjBE3KFo/PBuinpDLRzWo=\r\nUpgrade: websocket\r\nDate: Wed, 07 Oct 2020 07:25:56 GMT\r\nVia: 1.1 google\r\n\r\n' 183 bytes
DEBUG:SCRIPT: Error:	nil
ERROR:SCRIPT: /main/network-manager.script:4: attempt to concatenate local 'conn' (a userdata value)
stack traceback:
	/main/network-manager.script:4: in function </main/network-manager.script:2>

Log in bare-bones:

DEBUG:SCRIPT: Error:	nil
ERROR:SCRIPT: /main/wsssocket.script:3: attempt to concatenate local 'conn' (a userdata value)
stack traceback:
	/main/wsssocket.script:3: in function </main/wsssocket.script:1>

I will make a bare-bones ws server tomorrow in case that is still where the issue lies but with the autoAcceptConnections flag I don’t understand how it could be a problem with the accept function?
Thanks for sticking with me through this nonetheless!

1 Like

This is the good part I wanted to see. That means that we get a good response from your server.

However, I’m a bit puzzled about the order of things that things happen.
I.e why is it checking for the response key before it received it?

ERROR:WEBSOCKET: Failed to find valid key in the response headers
ERROR:WEBSOCKET: Response:
“”

I believe this is an issue with the extension though.
Do you have a repro case you can share with me?

1 Like

Yeah of course!
Repro:
PerryRepro 2.zip (574.6 KB)

Does the repro work or is the issue on my environment?

The server sent a case insensitive string, and the client didn’t expect that.
I now have a fix coming, it’s currently waiting for review.

2 Likes

There’s now a version 1.2.0

2 Likes

With version 1.2.0 that fixed one of the problems in the console at line 20 of my previous log, “Failed to find valid key in the response headers” but now at line 20 I get another error, “Waiting for socket to be available for reading” which repeats itself ~71 times (causing the display to drop to 3fps as I previously noted) and then experiencing the error:

ERROR:SCRIPT: /main/network-manager.script:7: attempt to concatenate local 'conn' (a userdata value)
stack traceback:
	/main/network-manager.script:7: in function </main/network-manager.script:2>"

this error is followed with ERROR:WEBSOCKET: Websocket poll error: WSLAY_ERR_CALLBACK_FAILURE, and a repeat of the conn error.

Here is the current console log:

WARNING:WEBSOCKET: STATE_CONNECTING -> STATE_HANDSHAKE_WRITE
DEBUG:SCRIPT: here
Registered dhttp Extension
INFO:DLIB: SSDP: Started on address 192.168.4.106
WARNING:WEBSOCKET: STATE_HANDSHAKE_WRITE -> STATE_HANDSHAKE_READ
Sent buffer: 'GET /' 5 bytes
Sent buffer: '' 0 bytes
Sent buffer: ' HTTP/1.1\r\n' 11 bytes
Sent buffer: 'Host: ' 6 bytes
Sent buffer: 'parry-host.grify.repl.co' 24 bytes
Sent buffer: '' 0 bytes
Sent buffer: '\r\n' 2 bytes
Sent buffer: 'Upgrade: websocket\r\n' 20 bytes
Sent buffer: 'Connection: Upgrade\r\n' 21 bytes
Sent buffer: 'Sec-WebSocket-Key: ' 19 bytes
Sent buffer: 'dC67eqAgedSYHGQCGOI13g==' 24 bytes
Sent buffer: '\r\n' 2 bytes
Sent buffer: 'Sec-WebSocket-Version: 13\r\n' 27 bytes
Sent buffer: '\r\n' 2 bytes
WARNING:WEBSOCKET: Waiting for socket to be available for reading
WARNING:WEBSOCKET: Secret key (base64): dC67eqAgedSYHGQCGOI13g==
WARNING:WEBSOCKET: Secret key + RFC_MAGIC: dC67eqAgedSYHGQCGOI13g==258EAFA5-E914-47DA-95CA-C5AB0DC85B11
WARNING:WEBSOCKET: Client key (base64): YxBZjjlKlNmFzsWwYGclNHqJMSo=
WARNING:WEBSOCKET: Server key (base64): YxBZjjlKlNmFzsWwYGclNHqJMSo=
WARNING:WEBSOCKET: STATE_HANDSHAKE_READ -> STATE_CONNECTED
ERROR:SCRIPT: /main/network-manager.script:7: attempt to concatenate local 'conn' (a userdata value)
stack traceback:
	/main/network-manager.script:7: in function </main/network-manager.script:2>
Received bytes: 'HTTP/1.1 101 Switching Protocols\r\nConnection: Upgrade\r\nSec-Websocket-Accept: YxBZjjlKlNmFzsWwYGclNHqJMSo=\r\nUpgrade: websocket\r\nDate: Mon, 12 Oct 2020 21:06:21 GMT\r\nVia: 1.1 google\r\n\r\n' 183 bytes
Hashed key (sha1): 'c\10Y\8e9J\94\d9\85\ce\c5\b0`g%4z\891*' 20 bytes
Received bytes: '\89\00' 2 bytes
Sent buffer: '\8a\80']\c6@' 6 bytes
Received bytes: '\89\00' 2 bytes
Sent buffer: '\8a\80.-\f1\f2' 6 bytes

If you open your network-manager.script and goto row 7, you’ll see:

print("Connected " .. conn)

This is the line it complains about, sine connisn’t a string, you cannot concatenate the two into a new string.

In the repro case you gave me, it connects as expected though (just tested it again).
Have you changed anything in the example?

I will have to fix the logging though since it’s confusing to see some of the messages out-of-order (the received headers are printed after the Connected event)

I got that code (the) from the official documentation so maybe that should be updated to reflect that. Casting conn to string before using it has solved that error and now we’re down to the final error, which is:

WARNING:WEBSOCKET: STATUS: 'Missing: 'HTTP/1.1 101' in header'  len: 33
WARNING:WEBSOCKET: STATE_HANDSHAKE_READ -> STATE_DISCONNECTED
1 Like

Thanks, I’ll fix that!

When you get that message, did it also print out the headers from the server?

1 Like

I think so. Is the following text what you are asking for?

Received bytes: 'HTTP/1.1 200 OK\r\nContent-Length: 13\r\nContent-Type: text/html; charset=utf-8\r\nDate: Tue, 13 Oct 2020 06:41:07 GMT\r\nEtag: W/"d-aGTv12Omx4QelmA2daCP+sXihWo"\r\nX-Powered-By: Express\r\nVia: 1.1 google\r\nConnection: close\r\n\r\nServer is up.' 229 bytes
1 Like

I just tested this myself, and got the same headers.

The problem here is that your server doesn’t want to upgrade the connection to a websocket. It doesn’t return HTTP 101, but 200 OK.
So a connection cannot be made.

The connection has worked before though, so I’m not sure why it started behaving like that now.

EDIT:
I just released 1.3.0, where the logging output doesn’t come out-or-order, and I also fixed the documentation:

2 Likes

This appears to have fixed the problem!
Thank you very much for your kind help and persistence!
I truly appreciate it :slight_smile:
Have a nice day!
grify

1 Like

I’m back /:
The issue with WARNING:WEBSOCKET: Waiting for socket to be available for reading still persists, and it still causes the fps drop. I’ve checked my code and it is only calling websocket.connect once, so I don’t know what’s causing it.

And, what does the log say?

Here’s the log:

INFO:ENGINE: Defold Engine 1.2.173 (fe2b689)
INFO:WEBSOCKET: dmWebSocket::g_DebugWebSocket == 2
INFO:WEBSOCKET: Registered websocket extension
WARNING:WEBSOCKET: STATE_CONNECTING -> STATE_HANDSHAKE_WRITE
WARNING:WEBSOCKET: Sent buffer: 'GET /' 5 bytes
WARNING:WEBSOCKET: Sent buffer: '' 0 bytes
WARNING:WEBSOCKET: Sent buffer: ' HTTP/1.1\r\n' 11 bytes
WARNING:WEBSOCKET: Sent buffer: 'Host: ' 6 bytes
WARNING:WEBSOCKET: Sent buffer: 'parry-host.grify.repl.co' 24 bytes
WARNING:WEBSOCKET: Sent buffer: '' 0 bytes
WARNING:WEBSOCKET: Sent buffer: '\r\n' 2 bytes
WARNING:WEBSOCKET: Sent buffer: 'Upgrade: websocket\r\n' 20 bytes
WARNING:WEBSOCKET: Sent buffer: 'Connection: Upgrade\r\n' 21 bytes
WARNING:WEBSOCKET: Sent buffer: 'Sec-WebSocket-Key: ' 19 bytes
WARNING:WEBSOCKET: Sent buffer: 'VFM9V6m7sSkoacUtHq9y3A==' 24 bytes
WARNING:WEBSOCKET: Sent buffer: '\r\n' 2 bytes
WARNING:WEBSOCKET: Sent buffer: 'Sec-WebSocket-Version: 13\r\n' 27 bytes
WARNING:WEBSOCKET: Sent buffer: '\r\n' 2 bytes
WARNING:WEBSOCKET: STATE_HANDSHAKE_WRITE -> STATE_HANDSHAKE_READ
WARNING:WEBSOCKET: Waiting for socket to be available for reading

And that last line is repeated indefinitely, while the window is 3fps.

1 Like

I’ll fix the indefinite checking for data to read.

But, I wonder, what code is used as the websocket server? Can I read it or test it somewhere?

Trying to connect with websocat, doesn’t give me a “connected” status:

users/grify/PerryRepro $ websocat -v -v ws://parry-host.grify.repl.co                                                               09:05:23
[INFO  websocat::lints] Auto-inserting the line mode
[DEBUG websocat] Done third phase of interpreting options.
[DEBUG websocat] Done fourth phase of interpreting options.
[DEBUG websocat] Preparation done. Now actually starting.
[DEBUG websocat::sessionserve] Serving Line2Message(Stdio) to Message2Line(WsClient("ws://parry-host.grify.repl.co/")) with Options { websocket_text_mode: true, websocket_protocol: None, websocket_reply_protocol: None, udp_oneshot_mode: false, udp_broadcast: false, udp_multicast_loop: false, udp_ttl: None, udp_join_multicast_addr: [], udp_join_multicast_iface_v4: [], udp_join_multicast_iface_v6: [], udp_reuseaddr: false, unidirectional: false, unidirectional_reverse: false, max_messages: None, max_messages_rev: None, exit_on_eof: false, oneshot: false, unlink_unix_socket: false, exec_args: [], ws_c_uri: "ws://0.0.0.0/", linemode_strip_newlines: false, linemode_strict: false, origin: None, custom_headers: [], custom_reply_headers: [], websocket_version: None, websocket_dont_close: false, websocket_ignore_zeromsg: false, one_message: false, no_auto_linemode: false, buffer_size: 65536, broadcast_queue_len: 16, read_debt_handling: Warn, linemode_zero_terminated: false, restrict_uri: None, serve_static_files: [], exec_set_env: false, no_exit_on_zeromsg: false, reuser_send_zero_msg_on_disconnect: false, process_zero_sighup: false, process_exit_sighup: false, socks_destination: None, auto_socks5: None, socks5_bind_script: None, tls_domain: None, tls_insecure: false, headers_to_env: [], max_parallel_conns: None, ws_ping_interval: None, ws_ping_timeout: None, request_uri: None, request_method: None, request_headers: [], autoreconnect_delay_millis: 20, ws_text_prefix: None, ws_binary_prefix: None, ws_binary_base64: false, ws_text_base64: false }
[DEBUG websocat::stdio_peer] get_stdio_peer (async)
[DEBUG websocat::stdio_peer] Setting stdin to nonblocking mode
[DEBUG websocat::stdio_peer] Installing signal handler
[DEBUG websocat::sessionserve] Underlying connection established
[INFO  websocat::ws_client_peer] get_ws_client_peer
... here it stops!

whereas, when testing towards a test server, it does:

users/grify/PerryRepro $ websocat -v -v ws://echo.websocket.org                                                                     09:08:18
[INFO  websocat::lints] Auto-inserting the line mode
[DEBUG websocat] Done third phase of interpreting options.
[DEBUG websocat] Done fourth phase of interpreting options.
[DEBUG websocat] Preparation done. Now actually starting.
[DEBUG websocat::sessionserve] Serving Line2Message(Stdio) to Message2Line(WsClient("ws://echo.websocket.org/")) with Options { websocket_text_mode: true, websocket_protocol: None, websocket_reply_protocol: None, udp_oneshot_mode: false, udp_broadcast: false, udp_multicast_loop: false, udp_ttl: None, udp_join_multicast_addr: [], udp_join_multicast_iface_v4: [], udp_join_multicast_iface_v6: [], udp_reuseaddr: false, unidirectional: false, unidirectional_reverse: false, max_messages: None, max_messages_rev: None, exit_on_eof: false, oneshot: false, unlink_unix_socket: false, exec_args: [], ws_c_uri: "ws://0.0.0.0/", linemode_strip_newlines: false, linemode_strict: false, origin: None, custom_headers: [], custom_reply_headers: [], websocket_version: None, websocket_dont_close: false, websocket_ignore_zeromsg: false, one_message: false, no_auto_linemode: false, buffer_size: 65536, broadcast_queue_len: 16, read_debt_handling: Warn, linemode_zero_terminated: false, restrict_uri: None, serve_static_files: [], exec_set_env: false, no_exit_on_zeromsg: false, reuser_send_zero_msg_on_disconnect: false, process_zero_sighup: false, process_exit_sighup: false, socks_destination: None, auto_socks5: None, socks5_bind_script: None, tls_domain: None, tls_insecure: false, headers_to_env: [], max_parallel_conns: None, ws_ping_interval: None, ws_ping_timeout: None, request_uri: None, request_method: None, request_headers: [], autoreconnect_delay_millis: 20, ws_text_prefix: None, ws_binary_prefix: None, ws_binary_base64: false, ws_text_base64: false }
[DEBUG websocat::stdio_peer] get_stdio_peer (async)
[DEBUG websocat::stdio_peer] Setting stdin to nonblocking mode
[DEBUG websocat::stdio_peer] Installing signal handler
[DEBUG websocat::sessionserve] Underlying connection established
[INFO  websocat::ws_client_peer] get_ws_client_peer
[INFO  websocat::ws_client_peer] Connected to ws
[DEBUG websocat::ws_peer] incoming ping
[DEBUG websocat::ws_peer] incoming ping
.. the pings keep coming

And, I’m not sure if it’s related, but going to the page for that repl, it says this:

The example has worked fine previously, then it wouldn’t upgrade the TCP request, and now it won’t send data to the client.
My current guess is that something is wrong with your server/setup.
I would start by implementing an echo server, and verifying that it works correctly with e.g. websocat, so that when your next issue arises, you can go back to verifying that your server works as intended.

Btw, how do you currently verify your server functionality?
I also tried wss://parry-host.grify.repl.co on this page (https://www.websocket.org/echo.html) but it returned **ERROR:** undefined.

Do you have any logs on your server to help assist you in troubleshooting it?

1 Like

Do you think you could make the indefinite checking end after a predefined amount of attempts and call a function so that it can be handled from the client?

The server code is directly connected to the database which utilizes the groundbreaking innovation of storing passwords in plaintext so the server code is obfuscated online. I can strip the userdata and send you a copy.

The SyntaxError you saw was part of the incredibly useful debugging system. It was just me missing a comma after changing the auth keys at the end of yesterday’s dev session, but it unfortunately wasn’t the cause of the connection problems. I’ve corrected the error and now visiting the url will simply provide the typical 200 ok message.

The server itself also has extensive logs for debugging, but according to the server, it simply didn’t receive the data (when the client could not connect and dropped in framerate, so a function on the client to handle these occurances of “failed connections” would be very much appreciated).

Why is the server receiving binary data instead of strings?
{ type: 'binary', binaryData: <Buffer 61 79 65> }

Here are the server logs from that:

Importing files...
2020-10-15 07:55:18 UTC 00:55:18 PT | Starting Parry server...
2020-10-15 07:55:18 UTC 00:55:18 PT | Importing modules...
2020-10-15 07:55:19 UTC 00:55:19 PT | Connecting to database...
2020-10-15 07:55:19 UTC 00:55:19 PT | Creating HTTP server...
2020-10-15 07:55:19 UTC 00:55:19 PT | Creating WebSocket server...
WebSocketServer {
  _events: [Object: null prototype] { request: [Function] },
  _eventsCount: 1,
  _maxListeners: undefined,
  _handlers: {
    upgrade: [Function: bound ],
    requestAccepted: [Function: bound ],
    requestResolved: [Function: bound ]
  },
  connections: [],
  pendingRequests: [],
  config: {
    httpServer: [ [Server] ],
    maxReceivedFrameSize: 65536,
    maxReceivedMessageSize: 1048576,
    fragmentOutgoingMessages: true,
    fragmentationThreshold: 16384,
    keepalive: true,
    keepaliveInterval: 20000,
    dropConnectionOnKeepaliveTimeout: true,
    keepaliveGracePeriod: 10000,
    useNativeKeepalive: false,
    assembleFragments: true,
    autoAcceptConnections: false,
    ignoreXForwardedFor: false,
    disableNagleAlgorithm: true,
    closeTimeout: 5000
  },
  [Symbol(kCapture)]: false
}
Hint: hit control+c anytime to enter REPL.
2020-10-15 07:55:19 UTC 00:55:19 PT | HTTP server listening on port 25434
New request
2020-10-15 07:55:28 UTC 00:55:28 PT | [connect] Client at {redacted}
[ '{redacted}' ]
2020-10-15 07:55:34 UTC 00:55:34 PT | [disconnect] Client at {redacted}

and on the client what is ERROR:WEBSOCKET: Websocket poll error: WSLAY_ERR_CALLBACK_FAILURE?

Thank you