none stop retry when upstream peer close socket

[GhostZCH]

We fond a problem when use balance by lua module. The process is like bellow:

1. Client visit a right url and ngx setup a keep alive connection to upstream peer success;
2. Another client visit a wrong url and ngx send the request to the the upstream peer;
3. The upstream peer find the request is a wrong url and close the connection immediately;
4. Then, ngx while try setup new connections and sent the wrong request repeatitively until we reload ngx.

I find you reduse u->peer.tries in ngx_http_lua_balancer_free_peer
but ngx_http_upstream_next do u->peer.tries++. That makes me confused.

ngx_http_upstream_next:
if (u->peer.cached && ft_type == NGX_HTTP_UPSTREAM_FT_ERROR
    && (!u->request_sent || !r->request_body_no_buffering))
{
    status = 0;

    /* TODO: inform balancer instead */

    u->peer.tries++;

} else {

ngx_http_lua_balancer_free_peer:
if (bp->sockaddr && bp->socklen) {
    bp->last_peer_state = (int) state;

    if (pc->tries) {
        pc->tries--;
    }

    return;
}

[GhostZCH]

Here is a part of debug log

2016/02/26 18:25:51 [debug] 7450#0: epoll: fd:19 ev:201D d:00007FA53594A521
2016/02/26 18:25:51 [debug] 7450#0: epoll_wait() error on fd:19 ev:201D
2016/02/26 18:25:51 [debug] 7450#0: *15 http upstream request: "/?"
2016/02/26 18:25:51 [debug] 7450#0: *15 http upstream process header
2016/02/26 18:25:51 [error] 7450#0: *15 connect() failed (111: Connection refused) while connecting to upstream, client: 10.8.192.37, server: , request: "GET / HTTP/1.1", upstream: "http://10.8.192.37:8080/", host: "ynm3k.financee.com.cn"
2016/02/26 18:25:51 [debug] 7450#0: *15 http next upstream, 2
2016/02/26 18:25:51 [debug] 7450#0: *15 free keepalive peer
2016/02/26 18:25:51 [debug] 7450#0: *15 close http upstream connection: 19
2016/02/26 18:25:51 [debug] 7450#0: *15 free: 0000000003BA9370, unused: 48
2016/02/26 18:25:51 [debug] 7450#0: *15 event timer del: 19: 1456482411598
2016/02/26 18:25:51 [debug] 7450#0: *15 reusable connection: 0
2016/02/26 18:25:51 [debug] 7450#0: *15 get keepalive peer
2016/02/26 18:25:51 [debug] 7450#0: *15 lua balancer peer, try: 1
2016/02/26 18:25:51 [debug] 7450#0: *15 lua reset ctx
2016/02/26 18:25:51 [debug] 7450#0: *15 socket 19
2016/02/26 18:25:51 [debug] 7450#0: *15 epoll add connection: fd:19 ev:80002005
2016/02/26 18:25:51 [debug] 7450#0: *15 connect to 10.8.192.37:8080, fd:19 #2451
2016/02/26 18:25:51 [debug] 7450#0: *15 http upstream connect: -2
2016/02/26 18:25:51 [debug] 7450#0: *15 posix_memalign: 0000000003BA9370:128 @16
2016/02/26 18:25:51 [debug] 7450#0: *15 event timer add: 19: 60000:1456482411602
2016/02/26 18:25:51 [debug] 7450#0: epoll: stale event 00007FA53594A520
2016/02/26 18:25:51 [debug] 7450#0: timer delta: 4
2016/02/26 18:25:51 [debug] 7450#0: worker cycle
2016/02/26 18:25:51 [debug] 7450#0: epoll timer: 906

[agentzh]

@GhostZCH Thanks for the report. Several suggestions though:

1. Will you please create a self-contained and minimal example that can easily reproduce the issue on, say, my machine?
2. Will you provide the complete debugging logs for the whole session of the request?
3. Will you provide the exact version numbers of your NGINX and ngx_lua module (or the OpenResty bundle) please?

[GhostZCH]

@agentzh sorry, this is the details:

Version:
Nginx: 10.8.150.41:8000
Lua-Nginx-Module: commit 78426ff
lua-resty-core: commit 8f099abbcbdfd1c3bbfd00f801866d617c621ae5
OS: Ubuntu 14.04.4 LTS

Config:

• nginx.conf

  #user  nobody;
  worker_processes  2;
  
  
  events {
      worker_connections  1024;
  }
  
  
  error_log logs/error.log error;
  error_log logs/debug.log debug;
  
  http {
      include       mime.types;
      sendfile        on;
      keepalive_timeout  65;
  
      upstream backend {
      server 0.0.0.1;
      balancer_by_lua_file lua/upstream.lua;
      keepalive 3;
      }
  
      lua_package_path "/home/ngx/code/lua-resty-core/lib/?.lua;;";
      # lua_package_cpath "/opt/openresty/lualib/?.so;";
      lua_code_cache off;
  
      lua_max_pending_timers 4096;
      lua_max_running_timers 1024;
  
  
      server {
      listen       8080;
  
      location / {
          proxy_pass $scheme://backend;
          proxy_set_header Connection "";
          error_page 404 $scheme://$host:80$request_uri;
      }
      }
  }
  

• upstream-lua

  local balancer = require "ngx.balancer"
  local host = "127.0.0.1"
  local port = 8000
  
  local ok, err = balancer.set_current_peer(host, port)
  if not ok then
      ngx.log(ngx.ERR, "failed to set to current peer: ", err)
      return ngx.exit(500)
  end
  

Back end[python]:

import SocketServer
import datetime


def make_resp():
    GMT_FORMAT = '%a, %d %b %Y %H:%M:%S GMT'
    now = datetime.datetime.utcnow()

    content = '''
<html>
<head><title>MyServerDemo/0.1</title></head>
<body>
<h1>Hello, World!</h1>
</body>
</html>
'''

    response = '''HTTP/1.1 200 OK
Server: %s
Date: %s
Content-Type: text/html;charset=utf8
Content-Length: %s
Connection: keep-alive

%s''' % (
    'simpleserver',
    now.strftime(GMT_FORMAT),
    len(content),
    content
)

    return response

count = 0

class MyTCPHandler(SocketServer.BaseRequestHandler):
    def handle(self):
    global count
    print "handle"
    while True:
        self.request.recv(1024)
        count += 1
        if count == 1:
            resp = make_resp()
            self.request.sendall(resp)
        else:
            print count
            break
    print "break"


if __name__ == "__main__":
    HOST, PORT = "", 8000
    server = SocketServer.TCPServer((HOST, PORT), MyTCPHandler)
    server.serve_forever()

Log:

debug.txt.zip

you can try grep User-Agent: curl/7.35.0 find two client access

[agentzh]

@GhostZCH Thanks for the report. I can reproduce this issue with the following minimal and self-contained example:

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

The fix has just been committed as 60ebb5c. Please try it out on your side.

[GhostZCH]

@agentzh Thank you very much! The bug fixed.