Redis: timeout

[liukaiyuliukaiyu]

the error log：

2024/08/06 15:49:01 [debug] 384947#384947: *171134 [lua] base_plugin.lua:24: access(): executing plugin "rate-limiting": access
2024/08/06 15:49:01 [error] 384947#384947: *171134 [lua] redis.lua:60: new(): ==========new==========, client: 127.0.0.1, server: kylin, request: "GET /test_kylin_upstream_timeout HTTP/1.1", host: "127.0.0.1:8000"
2024/08/06 15:49:01 [debug] 384947#384947: *171134 lua tcp socket pool get keepalive peer
2024/08/06 15:49:01 [debug] 384947#384947: *171134 lua tcp socket get keepalive peer: using connection 00007FBE83FEB1F8, fd:79
2024/08/06 15:49:01 [debug] 384947#384947: *171134 event timer del: 79: 3647014359
2024/08/06 15:49:01 [debug] 384947#384947: *171134 http cleanup add: 0000000001424E68
2024/08/06 15:49:01 [error] 384947#384947: *171134 [lua] redis.lua:220: _gen_req(): ======nargs======5, client: 127.0.0.1, server: kylin, request: "GET /test_kylin_upstream_timeout HTTP/1.1", host: "127.0.0.1:8000"
2024/08/06 15:49:01 [error] 384947#384947: *171134 [lua] redis.lua:231: _gen_req(): ======_gen_req=====eval=====i=====1, client: 127.0.0.1, server: kylin, request: "GET /test_kylin_upstream_timeout HTTP/1.1", host: "127.0.0.1:8000"
2024/08/06 15:49:01 [error] 384947#384947: *171134 [lua] redis.lua:231: _gen_req(): ======_gen_req===== local cache_key, expiration = KEYS[1], ARGV[1]
2024/08/06 15:49:01 [error] 384947#384947: *171134 [lua] redis.lua:231: _gen_req(): ======_gen_req=====1=====i=====3, client: 127.0.0.1, server: kylin, request: "GET /test_kylin_upstream_timeout HTTP/1.1", host: "127.0.0.1:8000"
2024/08/06 15:49:01 [error] 384947#384947: *171134 [lua] redis.lua:231: _gen_req(): ======_gen_req=====ratelimit:d7af6063-037c-47d0-934a-1f19c412ea94:d7af6063-037c-47d0-934a-1f19c412ea94:1722930541000:second:0aa0512166b1d56d3617dfb30304e602=====i=====4, client: 127.0.0.1, server: kylin, request: "GET /test_kylin_upstream_timeout HTTP/1.1", host: "127.0.0.1:8000"
2024/08/06 15:49:01 [error] 384947#384947: *171134 [lua] redis.lua:231: _gen_req(): ======_gen_req=====1=====i=====5, client: 127.0.0.1, server: kylin, request: "GET /test_kylin_upstream_timeout HTTP/1.1", host: "127.0.0.1:8000"
2024/08/06 15:49:01 [debug] 384947#384947: *171134 lua tcp socket send timeout: 50
2024/08/06 15:49:01 [debug] 384947#384947: *171134 lua allocate new chainlink and new buf of size 431, cl:0000000001424EB0
2024/08/06 15:49:01 [debug] 384947#384947: *171134 lua tcp socket send data
2024/08/06 15:49:01 [debug] 384947#384947: *171134 send: fd:79 431 of 431
2024/08/06 15:49:01 [debug] 384947#384947: *171134 lua tcp socket sent all the data
2024/08/06 15:49:01 [error] 384947#384947: *171134 [lua] redis.lua:268: eval(): =====req======26, client: 127.0.0.1, server: kylin, request: "GET /test_kylin_upstream_timeout HTTP/1.1", host: "127.0.0.1:8000"
2024/08/06 15:49:01 [error] 384947#384947: *171134 [lua] redis.lua:279: eval(): ===req===1:*5
2024/08/06 15:49:01 [error] 384947#384947: *171134 [lua] redis.lua:129: eval(): before_receive_time timestamp: 1722930541450, client: 127.0.0.1, server: kylin, request: "GET /test_kylin_upstream_timeout HTTP/1.1", host: "127.0.0.1:8000"
2024/08/06 15:49:01 [debug] 384947#384947: *171134 lua tcp socket calling receive() method
2024/08/06 15:49:01 [debug] 384947#384947: *171134 lua tcp socket read timeout: 50
2024/08/06 15:49:01 [debug] 384947#384947: *171134 lua allocate new chainlink and new buf of size 4096, cl:00000000014250C0
2024/08/06 15:49:01 [debug] 384947#384947: *171134 malloc: 0000000001425200:4096
2024/08/06 15:49:01 [debug] 384947#384947: *171134 lua tcp socket read timeout: 50
2024/08/06 15:49:01 [debug] 384947#384947: *171134 lua tcp socket read data: wait:0
2024/08/06 15:49:01 [debug] 384947#384947: *171134 event timer add: 79: 50:3647004499
2024/08/06 15:49:01 [debug] 384947#384947: *171134 lua resume returned 1
2024/08/06 15:49:01 [debug] 384947#384947: *171134 lua thread yielded
2024/08/06 15:49:01 [debug] 384947#384947: *171134 http run request: "/test_kylin_upstream_timeout?"
2024/08/06 15:49:01 [debug] 384947#384947: *171134 access phase: 14
2024/08/06 15:49:01 [debug] 384947#384947: *171134 lua access handler, uri:"/test_kylin_upstream_timeout" c:1
2024/08/06 15:49:01 [debug] 384947#384947: *171134 lua run write event handler: timedout:0, ready:1, writing_raw_req_socket:0
2024/08/06 15:49:01 [debug] 384947#384947: *171134 useless lua write event handler
2024/08/06 15:49:01 [debug] 384947#384947: *171134 event timer del: 79: 3647004499
2024/08/06 15:49:01 [debug] 384947#384947: *171134 lua tcp socket handler for "/test_kylin_upstream_timeout?", wev 0
2024/08/06 15:49:01 [debug] 384947#384947: *171134 lua tcp socket read handler
2024/08/06 15:49:01 [debug] 384947#384947: *171134 lua tcp socket handle read error
2024/08/06 15:49:01 [debug] 384947#384947: *171134 lua tcp socket waking up the current request
2024/08/06 15:49:01 [debug] 384947#384947: *171134 access phase: 14
2024/08/06 15:49:01 [debug] 384947#384947: *171134 lua access handler, uri:"/test_kylin_upstream_timeout" c:1
2024/08/06 15:49:01 [debug] 384947#384947: *171134 lua tcp operation done, resuming lua thread
2024/08/06 15:49:01 [debug] 384947#384947: *171134 lua tcp socket calling prepare retvals handler 0000000000663B16, u:00007FBE8318A408
2024/08/06 15:49:01 [debug] 384947#384947: *171134 lua tcp socket receive return value handler
2024/08/06 15:49:01 [debug] 384947#384947: *171134 lua run thread, top:0 c:1
2024/08/06 15:49:01 [error] 384947#384947: *171134 [lua] redis.lua:133: eval(): =========receive time===== 53ms, client: 127.0.0.1, server: kylin, request: "GET /test_kylin_upstream_timeout HTTP/1.1", host: "127.0.0.1:8000"
2024/08/06 15:49:01 [error] 384947#384947: *171134 [lua] redis.lua:134: eval(): =======line=======nil=====err=====timeout=====partial=====, client: 127.0.0.1, server: kylin, request: "GET /test_kylin_upstream_timeout HTTP/1.1", host: "127.0.0.1:8000"
2024/08/06 15:49:01 [debug] 384947#384947: *171134 lua finalize socket
2024/08/06 15:49:01 [debug] 384947#384947: *171134 lua http cleanup free: 0000000001424E68
2024/08/06 15:49:01 [debug] 384947#384947: *171134 lua close socket connection

Whether the lua-resty-redis client will block the nginx event loop in implementation, or the read timeout is caused by lua's own coroutine scheduling, or nginx can sometimes take more than 50ms between epoll-wait. because I found that the redis server responds quickly, and the redis client will appear in the timeout caused by not being able to read the response within 50ms

[ProBrian]

Hi @liukaiyuliukaiyu , can you provide more information about the redis deployment and config? Which includes the network topology between your kong deployment and redis deployment, and the configuration of your rate-limiting plugin.

[liukaiyuliukaiyu]

redis cluster configuration: 12G memory, 3 proxies, 12 redis, of which redis is one master and one slave, that is, 6 groups of redis
kong is deployed in elastic cloud containers, and redis cluster is a closed-loop call in the same computer room, and does not involve cross-room and cross-dedicated lines
rate-limiting plugin:

You can refer to: openresty/lua-resty-redis#279

[liukaiyuliukaiyu]

@ProBrian Hello, do you have any ideas on this problem? Please give me some guidance. Thank you

[chobits]

hi @liukaiyuliukaiyu I think we dont have some background from your error.log, I guess you added some debug log into the library, but you should know that we have no idea of your custom debug.log.

A good way for our developer is to give us minimal steps to reproduce your problem, note that complicated deployment and cases will make it hard for us to pinpoint it.

[chobits]

And also note that the discussion channel is used to discuss some kong design problem or potential features. If you still have some other problems, you could file a github issue.