balancer by lua block: Getting errors : attempt to send data on a closed socket

[rohitjoshi]

Hello,
I am running a performance test using balancer by lua block module. Periodically, I am seeing following errors.

2016/07/07 03:17:04 [error] 2346#0: *200075 attempt to send data on a closed socket: u:0000000040095EA8, c:0000000000000000, client: xx.xxx.xxx.44, server: 127.0.0.1, request: "GET /perftest_category/success?http_status=201&body_size=100 HTTP/1.1", host: "xx.xxx.xxx.64:11111"
2016/07/07 03:17:04 [error] 2352#0: *207819 attempt to send data on a closed socket: u:00000000410F5058, c:0000000000000000, client: xx.xxx.xxx.44, server: 127.0.0.1, request: "GET /perftest_category/success?http_status=201&body_size=100 HTTP/1.1", host: "xx.xxx.xxx.64:11111"
2016/07/07 03:17:04 [error] 2346#0: *200075 attempt to send data on a closed socket: u:0000000040096068, c:0000000000000000, client: xx.xxx.xxx.44, server: 127.0.0.1, request: "GET /perftest_category/success?http_status=201&body_size=100 HTTP/1.1", host: "xx.xxx.xxx.64:11111"
2016/07/07 03:17:04 [error] 2352#0: *207819 attempt to send data on a closed socket: u:00000000410F4CB8, c:0000000000000000, client: xx.xxx.xxx.44, server: 127.0.0.1, request: "GET /perftest_category/success?http_status=201&body_size=100 HTTP/1.1", host: "xx.xxx.xxx.64:11111"
2016/07/07 03:17:04 [error] 2346#0: *200075 attempt to send data on a closed socket: u:0000000040095CC8, c:0000000000000000, client: xx.xxx.xxx.44, server: 127.0.0.1, request: "GET /perftest_category/success?http_status=201&body_size=100 HTTP/1.1", host: "xx.xxx.xxx.64:11111"
2016/07/07 03:17:04 [error] 2346#0: *200075 attempt to send data on a closed socket: u:0000000040095EA8, c:0000000000000000, client: xx.xxx.xxx.44, server: 127.0.0.1, request: "GET /perftest_category/success?http_status=201&body_size=100 HTTP/1.1", host: "xx.xxx.xxx.64:11111"
2016/07/07 03:17:04 [error] 2357#0: *203392 attempt to send data on a closed socket: u:00000000410F4E98, c:0000000000000000, client: xx.xxx.xxx.44, server: 127.0.0.1, request: "GET /perftest_category/success?http_status=201&body_size=100 HTTP/1.1", host: "xx.xxx.xxx.64:11111"

My code:

upstream balancer_upstream {

      server 0.0.0.1 max_fails=0 fail_timeout=5s;   # just an invalid address as a place holder

      balancer_by_lua_block {

          local upstream_servers_str = ngx.var.upstream_servers

          local upstream_servers = capi_util.json_to_lua(upstream_servers_str)
          local set_peer = false
          if not ngx.ctx.upstream_retries then
            ngx.ctx.upstream_retries = 0
          end

          if #upstream_servers == 1 then
             local ip_port = upstream_servers[1]
             local ok, err = balancer.set_current_peer(ip_port["ip"], ip_port["port"])
             set_peer = true
          else    
            if ngx.ctx.upstream_retries < #upstream_servers then
                local ok, err = balancer.set_more_tries(1)
                local ip_port = upstream_servers[ngx.ctx.upstream_retries + 1]
                ngx.ctx.upstream_retries = ngx.ctx.upstream_retries + 1
                ok, err = balancer.set_current_peer(ip_port["ip"], ip_port["port"])
                set_peer = true
            end
        end


        if not set_peer then
         ngx.status = 500
         return ngx.exit(500)
       end
     }

      keepalive 1000;  # connection pool
}

[agentzh]

@rohitjoshi Will you please provide a minimal and standalone example that we can easily reproduce the issue on our side?

[agentzh]

@rohitjoshi BTW, it's a bad idea to parse a JSON string in your balancer_by_lua* handler upon every request. It's very expensive.

[agentzh]

@rohitjoshi For the minimal example that can reproduce the issue, I don't think you need the JSON part or the branching code testing the size of the server array (you can just use a static table, or even a static host and port pair).

[agentzh]

@rohitjoshi And for the standalone part of the example, you need to provide your location definition, as well as a fake backend server in the same nginx.conf, as well as the test requests required to access the entry point of your nginx server.

[agentzh]

@rohitjoshi Please see the test suite for balancer_by_lua* and ngx.balancer for an idea of what standalone and minimal examples look like:

https://github.com/openresty/lua-resty-core/blob/master/t/balancer.t

[agentzh]

@rohitjoshi I've just had a closer look and I don't think that error is trigger by the balancer_by_lua* config snippet you provided.

The error message is generated in your cosocket related Lua code when you try continuing using a cosocket object after a fatal error has happened in a previous cosocket operation. How to fix:

1. ensure you have Lua code that checks the return values of all the cosocket operations that may fail and handle any errors properly in your own Lua code (like retry or give up).
2. after you have handled all the errors on the Lua land, turn off such automatic cosocket error logging by adding the following line to your nginx.conf:

lua_socket_log_errors off;

[agentzh]

@rohitjoshi A fatal error in a cosocket operation closes the underlying socket immediately. So when you go ahead and try sending data on this closed socket without re-connecting, you get the error log message "attempt to send data on a closed socket" from the cosocket object when your do not turn off lua_socket_log_errors (default on).

[rohitjoshi]

@agentzh thanks. Yes, errors seem to be due to upstream simulator server closing the connection. I did not see errors reflected in my client (wrk).

I ran performance test using two scenarios using wrk.

./wrk -c15000 -t128 -d30s -H "Api-Key: rohit" "https://10.205.192.64:11111/perftest_category/success?http_status=201&body_size=100"

Based on the body_size query parameter, simulator server returns that size in the response.

I ran 3 tests with body size 100, 500 and 1000.

1. Balancer by Lua:

Response size: 100 Requests/sec:   69123.15  Avg Latency:  239.27ms
Response size: 500 Requests/sec:   68385.40  Avg Latency:  247.50ms
Response size: 1000 Requests/sec:  64240.14 Avg Latency:  254.42ms

1. Nginx upstream with nginx-upstream-dynamic-servers module (dynamic resolve)

Response size: 100 Requests/sec:   71613.66  Avg Latency:  248.93ms
Response size: 500 Requests/sec:   68367.540  Avg Latency:  251.14ms
Response size: 1000 Requests/sec:  65553.37 Avg Latency:  242.05ms

Both test are returning almost identical results with nginx upstream has slightly lower latency and higher throughput. May be due to my code where I am converting string to table using msgpack. (I replaced json with msgpack). Will optimize this.

By the way, I did not see any attempt to send data on a closed socket while using nginx upstream but did see upstream prematurely closed connection while reading response header from upstream errors which might be equivalent to what is logged when balancer by lua is used.

Thanks again.

[rohitjoshi]

Setting lua_socket_log_errors does disable these errors.