Websocket internally errors "/usr/local/share/lua/5.3/http/websocket.lua:282: read: Connection timed out"

[Mehgugs]

This happens when receiving payloads from the websocket.

Shard-0 has stopped receiving: ("/usr/local/share/lua/5.3/http/websocket.lua:282: read: Connection timed out\
stack traceback:\
\9[C]: in function 'assert'\
\9/usr/local/share/lua/5.3/http/websocket.lua:282: in function 'http.websocket.read_frame'\
\9/usr/local/share/lua/5.3/http/websocket.lua:394: in function </usr/local/share/lua/5.3/http/websocket.lua:386>\
\9[C]: in function 'xpcall'\
\9...s/marcus/documents/github/novus/lua/novus/shard/init.lua:183: in function 'novus.shard.messages'\
\9[C]: in function 'xpcall'\
\9.../marcus/documents/github/novus/lua/novus/client/init.lua:42: in function <.../marcus/documents/github/novus/lua/novus/client/init.lua:41>"

This happens regardless of if a timeout is passed to the socket.

The weird thing is when I request deflated messages (per message inflate/deflate inside my handling loop), I dont get this issue at all. The only time this happens is when I request raw json payloads. I'm using scm-0 from master (8ab5c30) to fix the timeout issues on the release rock.

This might be due to the payload size, heuristically I know it's the biggest payload I'm likely to receive causing this error, however this is not an issue with other clients for the api I'm connecting to.

[daurnimator]

Could you run with the environment variable SOCKET_DEBUG=1 set?
I'm wondering if your server is actually sending the data.

[Mehgugs]

With SOCKET_DEBUG=1 it works correctly, and logs the payloads I expect to see, it only errors without the debug variable set.

[daurnimator]

it only errors without the debug variable set.

That's extremely odd. The debug variable should only add logging, not change any behaviour.
Maybe there is a race condition somewhere, and the extra time spent logging is changing the winner?

[Mehgugs]

That seems likely, is there a way for me to collect the debug data into a file?

[daurnimator]

is there a way for me to collect the debug data into a file?

Just pipe/redirect it?

[Mehgugs]

https://ghostbin.com/paste/a6czk You can see it cut off reading here. It is crashing consistently it seems upon further inspection. I think I jumped the gun a little when it managed to reconnect previously.

[Mehgugs]

I added a xpcall handler to inspect the internals here is an example of a frame which errors:

{
    "RSV2": false,
    "RSV3": false,
    "RSV1": false,
    "MASK": false,
    "length": 12964,
    "FIN": true,
    "opcode": 1
}

[Mehgugs]

Any idea what could cause this? When this happens my receive loop breaks down and I dont know if i can handle it without reconnecting.

[daurnimator]

Your pastebin link has now expired. Could you repost it? (consider using a gist?)

[Mehgugs]

I'll try get some more data (I've lost the old log). What seems to happen is that the websocket cannot read the frame in 0 timeout https://github.com/daurnimator/lua-http/blob/master/http/websocket.lua#L282 I've made this line retry after a cqueues.sleep() and it can take up to 5 attempts to read.

I should also note that I've not found any further clues on how to reproduce it aside from connecting without requesting compression. I think it's possibly some kind of race condition?

[Mehgugs]

Why should these reads be 0 timeout exactly? In practice this isn't readable without waiting.

if frame.MASK then
	local key = assert(sock:xread(4, "b", 0))
	frame.key = { key:byte(1, 4) }
end

do
	local data = assert(sock:xread(frame.length, "b", 0))
	if frame.MASK then
		frame.data = apply_mask(data, frame.key)
	else
		frame.data = data
	end
end

EDIT:

This is a very naive solution I have been using to try and get a handle on what happens:

local function should_retry(timer) if timer then return timer:status() == "pending" else return true end end

local function read_again(deadline, socket, ...)
    local tries = 0
    local data, msg, code = socket:xread(...)
    local timeout = deadline and deadline - monotime()
    local timer = timeout and promise.new(sleep, timeout)
    while should_retry(timer) and (not data or code == ce.ETIMEDOUT) do
        tries = tries + 1
        sleep()
        data, msg, code = socket:xread(...)
    end
    used_tries = max(used_tries, tries)
    return data, msg, code
end

Calling this function on the socket in place of the xreads and logging the used_tries :

websocket.read_again used 5324 retries.

This makes me think the read_frame is not consuming the deadline somewhere?

[daurnimator]

Why should these reads be 0 timeout exactly? In practice this isn't readable without waiting.

There is a preceding :fill that will ensure that there are enough bytes waiting in the socket buffer.

When the :fill fails, we poll for readability, and then tail call ourselves to try again:

lua-http/http/websocket.lua

Line 229 in 1f30846

return read_frame(sock, deadline)

[daurnimator]

Are you still having problems?
If I'm unable to replicate your issue I'll have to close it.

[Mehgugs]

Hello, im so sorry i've not been more proactive with this. I'll try and get a reproducible example to work, and as far as im aware yes there's still something strange happening (it is mostly mitiaged right now by requesting compressed messages from the websocket but it by no means fixed).