ngx_lua logged error: lua tcp socket connect timed out

[microwish]

Hi Yichun,

My application used memcached.lua and I took some load tests.

If I explicitly called memcached.close(), a great number errors of "Connection refused" were logged. While I called memcached.set_keepalive(60000, 1000) instead of memcached.close(), that many errors of "lua tcp socket connect timed out" were logged.

Any suggestion or hint?

Thank you.

[Yichun Zhang (agentzh)]

Hello!

On Mon, Nov 11, 2013 at 4:17 PM, microwish wrote:
> My application used memcached.lua and I took some load tests.
>
> If I explicitly called memcached.close(), a great number errors of
> "Connection refused" were logged. While I called
> memcached.set_keepalive(60000, 1000) instead of memcached.close(), that many
> errors of "lua tcp socket connect timed out" were logged.
>

It seems that you're overloading your memcached server. Ensure that
the TCP recv() queue and accept() queue in kernel are not dropping
packets on your memcached server side.

Regards,
-agentzh

[Yichun Zhang (agentzh)]

Hello!

On Mon, Nov 11, 2013 at 4:17 PM, microwish wrote:

> My application used memcached.lua and I took some load tests.
>

Also ensure you're using the lua-resty-memcached module because the
old memcached.lua library is always blocking.

-agentzh

[microwish]

Thanks!

You mean the latest memcached.lua file by "lua-resty-memcached module"?

I found that memcached.lua was last updated 2 months ago on https://github.com/agentzh/lua-resty-memcached/, so what I'm using is possibly the latest. I'll be taking a futher check.

[Yichun Zhang (agentzh)]

Hello!

On Mon, Nov 11, 2013 at 5:38 PM, microwish wrote:
> You mean the latest memcached.lua file by "lua-resty-memcached module"?
>

The formal Lua module name in lua-resty-memcached is actually
"resty.memcached". Simply saying "memcached.lua" is very confusing.

Regards,
-agentzh

[microwish]

OK, got it. I'll be telling as clearly as possible in future.
Thanks!

[microwish]

Hi agentzh,

New finding.

1) "lua socket tcp connect timed out" is in nginx error log when set_keepalive function of lua-resty-memcached module is called;

2) connect() function returns OK, while receive() function returns with error "failed to receive 1st line: timeout".
   That agrees with the first point.
   By ngx_lua source codes, I guess that connection's read event was triggered and finally ngx_http_lua_abort_pending_timers() was called;

3) The most weird is that, when I issued STATS command of memcached, curr_connections was only around 150 and listen_disabled_num was always 0.
    memcached was started with -c 10240 and -b 10240, which is subject to  memcached's effective user's ulimit;

Any suggestions?

Thanks a lot!

[microwish]

Sorry.

By "receive() function " below, I mean the get() function of lua-resty-memcached module.

[Yichun Zhang (agentzh)]

Hello!

On Mon, Nov 11, 2013 at 10:50 PM, microwish wrote:
>
> 1) "lua socket tcp connect timed out" is in nginx error log when
> set_keepalive function of lua-resty-memcached module is called;
>

If you use set_keepalive correctly, then there should be few connect()
requests. So the "lua socket tcp connect timed out" error is an
indication that you may not call set_keepalive in the right way. Will
you provide a minimal and complete example that can reproduce the
issue?

> 2) connect() function returns OK, while receive() function returns with
> error "failed to receive 1st line: timeout".
> That agrees with the first point.

This is a different error. It means that receive() timed out rather
than connect(). There are basically two possibilities:

1. your memcached server does not return the response within the
timeout limit you set (you can confirm this by using tools like
tcpdump or wireshark or systemtap-based tools).
2. nginx's event loop is blocked by something (you can check this by
using the epoll-loop-blocking-distr tool if you're on Linux:
https://github.com/agentzh/stapxx#epoll-loop-blocking-distr ).

> By ngx_lua source codes, I guess that connection's read event was
> triggered and finally ngx_http_lua_abort_pending_timers() was called;
>

Your guess here does not make any sense.
ngx_http_lua_abort_pending_timers() is completely unrelated.

> 3) The most weird is that, when I issued STATS command of memcached,
> curr_connections was only around 150 and listen_disabled_num was always 0.

I'd rather trust the outputs of kernel-level tools like tcp-accept-queue here:

https://github.com/agentzh/nginx-systemtap-toolkit#tcp-accept-queue

Best regards,
-agentzh

[microwish]

agentzh, thank you so much!

I am trying using the tools.

Later I'll posting some codes calling set_keepalive() function of lua-resty-module.

As for ngx_http_lua_abort_pending_timers, I have wanted to tell ngx_event_expire_timers function in event/ngx_event_timer.c.
In this function, "timedout" attribute of read event was set to 1, and that led to the error "lua tcp socket connect timed out". Am I right?

[Yichun Zhang (agentzh)]

Hello!

On Tue, Nov 12, 2013 at 12:36 AM, microwish wrote:
> As for ngx_http_lua_abort_pending_timers, I have wanted to tell
> ngx_event_expire_timers function in event/ngx_event_timer.c.
> In this function, "timedout" attribute of read event was set to 1, and that
> led to the error "lua tcp socket connect timed out". Am I right?
>

You're wrong. As I've said, ngx_http_lua_abort_pending_timers is
completely unrelated to the socket API you're using here.
ngx_http_lua_abort_pending_timers is called to abort pending timers
created by the ngx.timer.at API upon Nginx server shutdown:

https://github.com/chaoslawful/lua-nginx-module#ngxtimerat

Grepping is a great way to study others' source code but you still
have to be careful about the actual context of the source lines
matching your grep queries.

Regards,
-agentzh