lua tcp socket read timed out

[Bogdan Irimia]

Hello, everybody

We have our Kronometrix project based on OpenResty, and we are using the websocket server module "lua-resty-websocket" (require "resty.websocket.server")
In the handling code on the "/websocket" path we are doing these (generic) steps:
- connecting to Redis with a timeout of 1 year
- creating the websocket server instance, like this:
local wb, err = server:new{
        timeout = 5000,  -- in milliseconds
        max_payload_len = 6553500,
}
- creating an infinite loop (while true do)
- in  the infinite loop we are doing these operations:
      - handling close event
      - sending ping events
      - spawning several light threads in which we do:
            - creating own Redis connections
            - sending/receiving some payload over the websocket (the same one from the parent thread)
            - sleep for 100 ms
      - when the websocket is closed, we close the Redis connection and we are killing the light threads

We keep receiving these errors in the error log:

2017/09/08 19:48:44 [error] 68593#0: *5377 lua tcp socket read timed out, client: 127.0.0.1, server: , request: "GET /websocket HTTP/1.1", host: "dev.kronometrix.com"
2017/09/08 19:48:44 [error] 68592#0: *5673 lua tcp socket read timed out, client: 127.0.0.1, server: , request: "GET /websocket HTTP/1.1", host: "dev.kronometrix.com"
2017/09/08 19:48:49 [error] 68593#0: *5377 lua tcp socket read timed out, client: 127.0.0.1, server: , request: "GET /websocket HTTP/1.1", host: "dev.kronometrix.com"
2017/09/08 19:48:49 [error] 68592#0: *5673 lua tcp socket read timed out, client: 127.0.0.1, server: , request: "GET /websocket HTTP/1.1", host: "dev.kronometrix.com"
2017/09/08 19:48:57 [error] 68592#0: *5673 lua tcp socket read timed out, client: 127.0.0.1, server: , request: "GET /websocket HTTP/1.1", host: "dev.kronometrix.com"
2017/09/08 19:48:57 [error] 68593#0: *5377 lua tcp socket read timed out, client: 127.0.0.1, server: , request: "GET /websocket HTTP/1.1", host: "dev.kronometrix.com"
2017/09/08 19:49:02 [error] 68593#0: *5377 lua tcp socket read timed out, client: 127.0.0.1, server: , request: "GET /websocket HTTP/1.1", host: "dev.kronometrix.com"
2017/09/08 19:49:02 [error] 68592#0: *5673 lua tcp socket read timed out, client: 127.0.0.1, server: , request: "GET /websocket HTTP/1.1", host: "dev.kronometrix.com"
2017/09/08 19:49:08 [error] 68592#0: *5673 lua tcp socket read timed out, client: 127.0.0.1, server: , request: "GET /websocket HTTP/1.1", host: "dev.kronometrix.com"
2017/09/08 19:49:08 [error] 68593#0: *5377 lua tcp socket read timed out, client: 127.0.0.1, server: , request: "GET /websocket HTTP/1.1", host: "dev.kronometrix.com"
2017/09/08 19:49:13 [error] 68593#0: *5377 lua tcp socket read timed out, client: 127.0.0.1, server: , request: "GET /websocket HTTP/1.1", host: "dev.kronometrix.com"
2017/09/08 19:49:13 [error] 68592#0: *5673 lua tcp socket read timed out, client: 127.0.0.1, server: , request: "GET /websocket HTTP/1.1", host: "dev.kronometrix.com"
2017/09/08 19:49:19 [error] 68593#0: *5377 lua tcp socket read timed out, client: 127.0.0.1, server: , request: "GET /websocket HTTP/1.1", host: "dev.kronometrix.com"
2017/09/08 19:49:19 [error] 68592#0: *5673 lua tcp socket read timed out, client: 127.0.0.1, server: , request: "GET /websocket HTTP/1.1", host: "dev.kronometrix.com"
2017/09/08 19:49:24 [error] 68593#0: *5377 lua tcp socket read timed out, client: 127.0.0.1, server: , request: "GET /websocket HTTP/1.1", host: "dev.kronometrix.com"
2017/09/08 19:49:24 [error] 68592#0: *5673 lua tcp socket read timed out, client: 127.0.0.1, server: , request: "GET /websocket HTTP/1.1", host: "dev.kronometrix.com"
2017/09/08 19:50:14 [error] 68593#0: *5377 lua tcp socket read timed out, client: 127.0.0.1, server: , request: "GET /websocket HTTP/1.1", host: "dev.kronometrix.com"

We added this directive in the nginx.conf file, but it didn't help:
lua_check_client_abort on;

We think the errors might come from:
- either from the way the websocket is closed on the client vs on the server side - maybe the ping/pong frames fail, or something else?
- or from the way we are handling the connection with Redis (maybe because we kill the light threads without signaling it somehow?)

How can we pinpoint the source of the error? What could we try in order to fix this error?

Thank you

Bogdan

[Bogdan Irimia]

So anybody has an idea about this?

Thank you

Bogdan Irimia wrote:

Hello, everybody

We have our Kronometrix project based on OpenResty, and we are using
the websocket server module "lua-resty-websocket" (require
"resty.websocket.server")
In the handling code on the "/websocket" path we are doing these
(generic) steps:
- connecting to Redis with a timeout of 1 year
- creating the websocket server instance, like this:
local wb, err = server:new{
timeout = 5000, -- in milliseconds
max_payload_len = 6553500,
}
- creating an infinite loop (while true do)
- in the infinite loop we are doing these operations:
- handling close event
- sending ping events
- spawning several light threads in which we do:
- creating own Redis connections

- sending/receiving some payloa d over the websocket (the same one from

the parent thread)
- sleep for 100 ms
- when the websocket is closed, we close the Redis connection and we
are killing the light threads

We keep receiving these errors in the error log:

|2017/09/08 19:48:44 [error] 68593#0: *5377 lua tcp socket read timed out, client: 127.0.0.1, server: , request: "GET /websocket HTTP/1.1", host: "dev.kronometrix.com"
2017/09/08 19:48:44 [error] 68592#0: *5673 lua tcp socket read timed out, client: 127.0.0.1, server: , request: "GET /websocket HTTP/1.1", host: "dev.kronometrix.com"
2017/09/08 19:48:49 [error] 68593#0: *5377 lua tcp socket read timed out, client: 127.0.0.1, server: , request: "GET /websocket HTTP/1.1", host: "dev.kronometrix.com"
2017/09/08 19:48:49 [error] 68592#0: *5673 lua tcp socket read timed out, client: 127.0.0.1, server: , request: "GET /websocket HTTP/1.1", host: "dev.kronometrix.com"
2017/09/08 19:48:57 [error] 68592#0: *5673 lua tcp socket read timed out, client: 127.0.0.1, server: , request: "GET /websocket HTTP/1.1", host: "dev.kronometrix.com"
2017/09/08 19:48:57 [error] 68593#0: *5377 lua tcp socket read timed out, client: 127.0.0.1, server: , request: "GET /websocket HTTP/1.1", host: "dev.kronometrix.com"
2017/09/08 19:49:02 [error] 68593#0: *5377 lua tcp socket read timed out, client: 127.0.0.1, server: , request: "GET /websocket HTTP/1.1", host: "dev.kronometrix.com"
2017/09/08 19:49:02 [error] 68592#0: *5673 lua tcp socket read timed out, client: 127.0.0.1, server: , request: "GET /websocket HTTP/1.1", host: "dev.kronometrix.com"
2017/09/08 19:49:08 [error] 68592#0: *5673 lua tcp socket read timed out, client: 127.0.0.1, server: , request: "GET /websocket HTTP/1.1", host: "dev.kronometrix.com"
2017/09/08 19:49:08 [error] 68593#0: *5377 lua tcp socket read timed out, client: 127.0.0.1, server: , request: "GET /websocket HTTP/1.1", host: "dev.kronometrix.com"

2017/09 /08 19:49:13 [error] 68593#0: *5377 lua tcp socket read timed out, client: 127.0.0.1, server: , request: "GET /websocket HTTP/1.1", host: "dev.kronometrix.com"

2017/09/08 19:49:13 [error] 68592#0: *5673 lua tcp socket read timed out, client: 127.0.0.1, server: , request: "GET /websocket HTTP/1.1", host: "dev.kronometrix.com"
2017/09/08 19:49:19 [error] 68593#0: *5377 lua tcp socket read timed out, client: 127.0.0.1, server: , request: "GET /websocket HTTP/1.1", host: "dev.kronometrix.com"
2017/09/08 19:49:19 [error] 68592#0: *5673 lua tcp socket read timed out, client: 127.0.0.1, server: , request: "GET /websocket HTTP/1.1", host: "dev.kronometrix.com"
2017/09/08 19:49:24 [error] 68593#0: *5377 lua tcp socket read timed out, client: 127.0.0.1, server: , request: "GET /websocket HTTP/1.1", host: "dev.kronometrix.com"

2017/09/08 19:49:24 [error] 68592#0: *5673 lua tcp socket read timed out, client: 127.0.0.1, server: , request: "GET /websocket HTTP/1.1", hos t: "dev.kronometrix.com"

2017/09/08 19:50:14 [error] 68593#0: *5377 lua tcp socket read timed out, client: 127.0.0.1, server: , request: "GET /websocket HTTP/1.1", host: "dev.kronometrix.com"|

We added this directive in the nginx.conf file, but it didn't help:
lua_check_client_abort on;

We think the errors might come from:
- either from the way the websocket is closed on the client vs on the
server side - maybe the ping/pong frames fail, or something else?
- or from the way we are handling the connection with Redis (maybe
because we kill the light threads without signaling it somehow?)

How can we pinpoint the source of the error? What could we try in
order to fix this error?

Thank you

Bogdan

--
You received this message because you are subscribed to the Google
Groups "openresty-en" group.
To unsubscribe from this group and stop receiving emails from it, send
an email to ope nresty-en+...@googlegroups.com
<mailto:openresty-en...@googlegroups.com>.
For more options, visit https://groups.google.com/d/optout.

[Bogdan Irimia]

We've narrowed this down to the cases when the client browser is Safari. So this happens when a Safari browser accesses the page (which uses websocket).

Any idea on how we can narrow this down even further? Or how to remedy?

Thanks

Bogdan Irimia

Monday, September 11, 2017 10:58 AM via Postbox

--
You received this message because you are subscribed to the Google Groups "openresty-en" group.

To unsubscribe from this group and stop receiving emails from it, send an email to openresty-en...@googlegroups.com.

[Yichun Zhang (agentzh)]

Hello!

If you already handle cosocket errors on the Lua land, then you can
just shut up those error logs by adding the following line to your
nginx.conf:

lua_socket_log_errors off;

It's completely normal to receive read timeout errors when doing
websockets, which simply means there's no new incoming messages on the
current websocket connection. No need to panic on this.

Regards,
Yichun

[Bogdan Irimia]

Ok, that's enough for us.
I thought that the error indicates that we don't use properly the websocket connection, somehow...

Thank you very much


Yichun Zhang (agentzh) wrote:

 & nbsp;     - handling close event

client: 127.0.0.1, server: , reque st: "GET /websocket HTTP/1.1", host:

We think t he errors might come from:

- either from the way the websocket is closed on the client vs on the server
side - maybe the ping/pong frames fail, or something else?
- or from the way we are handling the connection with Redis (maybe because
we kill the light threads without signaling it somehow?)

How can we pinpoint the source of the error? What could we try in order to
fix this error?

Thank you

Bogdan
--
You received this message because you are subscribed to the Google Groups
"openresty-en" group.
To unsubscribe from this group and stop receiving emails from it, send an
email to openresty-en...@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.


--
You received this message because you are subscribed to the Google Groups
"openresty-en" group.
To unsubscribe from this group and stop receiving emails from it, send an

email to openresty-en+unsubs cr...@googlegroups.com.