request help: active health check doesn't work

[panhow]

Issue description

I enabled the upstream ACTIVE health check(NOT PASSIVE), but it didn't health check the upstream endpoint actively.
I check the error.log,health checks only happened while i curl the route.
I want the health check to help me check whether the endpoint is Connection Refused or Connection Timeout

Environment

curl -XPUT localhost:9080/apisix/admin/upstreams/00000000000000000356 -H 'X-API-KEY: edd1c9f034335f136f87ad84b625c8f1' --data '
{
  "enable_websocket": true,
  "hash_on": "vars",
  "id": "00000000000000000356",
  "nodes": {
    "127.0.0.1:8000": 10,
    "127.0.0.1:6666": 10,
    "127.0.0.1:8888": 10
  },
  "desc": "test-health-check",
  "type": "roundrobin",
  "checks": {
    "active": {
      "unhealthy": {
        "interval": 3,
        "http_failures": 253,
        "tcp_failures": 5
      },
      "type": "http",
      "http_path": "/"
    }
  }
}'

curl http://127.0.0.1:9080/apisix/admin/routes/1  -H 'X-API-KEY: edd1c9f034335f136f87ad84b625c8f1' -X PUT -d '
{
    "methods": ["GET"],
    "uri": "/test/index.html",
    "upstream_id": "00000000000000000356"
}'

➜   incubator-apisix git:(master) ✗ telnet 127.0.0.1 6666
Trying 127.0.0.1...
Connected to localhost.
Escape character is '^]'.
^C
Connection closed by foreign host.
➜  incubator-apisix git:(master) ✗ telnet 127.0.0.1 8888
Trying 127.0.0.1...
telnet: connect to address 127.0.0.1: Connection refused
telnet: Unable to connect to remote host
➜  incubator-apisix git:(master) ✗ telnet 127.0.0.1 8000
Trying 127.0.0.1...
telnet: connect to address 127.0.0.1: Connection refused
telnet: Unable to connect to remote host

• error.log
  

• apisix version (cmd: apisix version):1.2

• OS:os X

[membphis]

it works fine at my side.

curl -XPUT 127.0.0.1:9080/apisix/admin/upstreams/00000000000000000356 -H 'X-API-KEY: edd1c9f034335f136f87ad84b625c8f1' --data '
{
  "enable_websocket": true,
  "hash_on": "vars",
  "nodes": {
    "127.0.0.1:1980": 10,
    "127.0.0.1:1981": 10,
    "127.0.0.1:1982": 10
  },
  "desc": "test-health-check",
  "type": "roundrobin",
  "checks": {
    "active": {
      "healthy": {
        "interval": 2,
        "successes": 1
      },
      "unhealthy": {
          "interval": 1,
          "http_failures": 2
      },
      "type": "http",
      "http_path": "/"
    }
  }
}'

curl http://127.0.0.1:9080/apisix/admin/routes/1  -H 'X-API-KEY: edd1c9f034335f136f87ad84b625c8f1' -X PUT -d '
{
    "methods": ["GET"],
    "uri": "/test/index.html",
    "upstream_id": "00000000000000000356"
}'

2020/05/08 15:02:57 [error] 62623#0: *7170 connect() failed (111: Connection refused) while connecting to upstream, client: 127.0.0.1, server: , request: "GET /test/index.html HTTP/1.1", upstream: "http://127.0.0.1:1980/test/index.html", host: "127.0.0.1:9080"
2020/05/08 15:02:57 [warn] 62623#0: *7170 [lua] healthcheck.lua:1107: log(): [healthcheck] (upstream#/apisix/upstreams/00000000000000000356) unhealthy TCP increment (1/2) for '(127.0.0.1:1980)' while connecting to upstream, client: 127.0.0.1, server: , request: "GET /test/index.html HTTP/1.1", upstream: "http://127.0.0.1:1980/test/index.html", host: "127.0.0.1:9080"
2020/05/08 15:02:57 [error] 62623#0: *7170 connect() failed (111: Connection refused) while connecting to upstream, client: 127.0.0.1, server: , request: "GET /test/index.html HTTP/1.1", upstream: "http://127.0.0.1:1981/test/index.html", host: "127.0.0.1:9080"
2020/05/08 15:02:57 [warn] 62623#0: *7170 [lua] healthcheck.lua:1107: log(): [healthcheck] (upstream#/apisix/upstreams/00000000000000000356) unhealthy TCP increment (1/2) for '(127.0.0.1:1981)' while connecting to upstream, client: 127.0.0.1, server: , request: "GET /test/index.html HTTP/1.1", upstream: "http://127.0.0.1:1981/test/index.html", host: "127.0.0.1:9080"
2020/05/08 15:02:57 [warn] 62623#0: *7173 [lua] healthcheck.lua:1107: log(): [healthcheck] (upstream#/apisix/upstreams/00000000000000000356) unhealthy TCP increment (2/2) for '(127.0.0.1:1980)', context: ngx.timer, client: 127.0.0.1, server: 0.0.0.0:9080
2020/05/08 15:02:57 [warn] 62623#0: *7173 [lua] healthcheck.lua:1107: log(): [healthcheck] (upstream#/apisix/upstreams/00000000000000000356) unhealthy TCP increment (2/2) for '(127.0.0.1:1981)', context: ngx.timer, client: 127.0.0.1, server: 0.0.0.0:9080
2020/05/08 15:02:57 [warn] 62623#0: *7173 [lua] healthcheck.lua:1107: log(): [healthcheck] (upstream#/apisix/upstreams/00000000000000000356) unhealthy TCP increment (1/2) for '(127.0.0.1:1982)', context: ngx.timer, client: 127.0.0.1, server: 0.0.0.0:9080
2020/05/08 15:02:57 [error] 62623#0: *7170 connect() failed (111: Connection refused) while connecting to upstream, client: 127.0.0.1, server: , request: "GET /test/index.html HTTP/1.1", upstream: "http://127.0.0.1:1982/test/index.html", host: "127.0.0.1:9080"
2020/05/08 15:02:57 [warn] 62623#0: *7170 [lua] healthcheck.lua:1107: log(): [healthcheck] (upstream#/apisix/upstreams/00000000000000000356) unhealthy TCP increment (2/2) for '(127.0.0.1:1982)' while connecting to upstream, client: 127.0.0.1, server: , request: "GET /test/index.html HTTP/1.1", upstream: "http://127.0.0.1:1982/test/index.html", host: "127.0.0.1:9080"
2020/05/08 15:02:57 [warn] 62623#0: *7170 [lua] balancer.lua:67: fetch_health_nodes(): all upstream nodes is unhealth, use default while connecting to upstream, client: 127.0.0.1, server: , request: "GET /test/index.html HTTP/1.1", upstream: "http://127.0.0.1:1982/test/index.html", host: "127.0.0.1:9080"
2020/05/08 15:02:57 [error] 62623#0: *7170 connect() failed (111: Connection refused) while connecting to upstream, client: 127.0.0.1, server: , request: "GET /test/index.html HTTP/1.1", upstream: "http://127.0.0.1:1980/test/index.html", host: "127.0.0.1:9080"
2020/05/08 15:03:05 [warn] 62623#0: *7847 [lua] healthcheck.lua:1107: log(): [healthcheck] (upstream#/apisix/upstreams/00000000000000000356) healthy SUCCESS increment (1/1) for '(127.0.0.1:1980)', context: ngx.timer, client: 127.0.0.1, server: 0.0.0.0:9080
2020/05/08 15:03:05 [warn] 62623#0: *7847 [lua] healthcheck.lua:1107: log(): [healthcheck] (upstream#/apisix/upstreams/00000000000000000356) healthy SUCCESS increment (1/1) for '(127.0.0.1:1981)', context: ngx.timer, client: 127.0.0.1, server: 0.0.0.0:9080
2020/05/08 15:03:05 [warn] 62623#0: *7847 [lua] healthcheck.lua:1107: log(): [healthcheck] (upstream#/apisix/upstreams/00000000000000000356) healthy SUCCESS increment (1/1) for '(127.0.0.1:1982)', context: ngx.timer, client: 127.0.0.1, server: 0.0.0.0:9080


2020/05/08 15:03:21 [warn] 62623#0: *9247 [lua] healthcheck.lua:1107: log(): [healthcheck] (upstream#/apisix/upstreams/00000000000000000356) unhealthy TCP increment (1/2) for '(127.0.0.1:1980)', context: ngx.timer, client: 127.0.0.1, server: 0.0.0.0:9080
2020/05/08 15:03:21 [warn] 62623#0: *9247 [lua] healthcheck.lua:1107: log(): [healthcheck] (upstream#/apisix/upstreams/00000000000000000356) unhealthy TCP increment (1/2) for '(127.0.0.1:1981)', context: ngx.timer, client: 127.0.0.1, server: 0.0.0.0:9080
2020/05/08 15:03:21 [warn] 62623#0: *9247 [lua] healthcheck.lua:1107: log(): [healthcheck] (upstream#/apisix/upstreams/00000000000000000356) unhealthy TCP increment (1/2) for '(127.0.0.1:1982)', context: ngx.timer, client: 127.0.0.1, server: 0.0.0.0:9080
2020/05/08 15:03:23 [warn] 62623#0: *9396 [lua] healthcheck.lua:1107: log(): [healthcheck] (upstream#/apisix/upstreams/00000000000000000356) unhealthy TCP increment (2/2) for '(127.0.0.1:1980)', context: ngx.timer, client: 127.0.0.1, server: 0.0.0.0:9080
2020/05/08 15:03:23 [warn] 62623#0: *9396 [lua] healthcheck.lua:1107: log(): [healthcheck] (upstream#/apisix/upstreams/00000000000000000356) unhealthy TCP increment (2/2) for '(127.0.0.1:1981)', context: ngx.timer, client: 127.0.0.1, server: 0.0.0.0:9080
2020/05/08 15:03:23 [warn] 62623#0: *9396 [lua] healthcheck.lua:1107: log(): [healthcheck] (upstream#/apisix/upstreams/00000000000000000356) unhealthy TCP increment (2/2) for '(127.0.0.1:1982)', context: ngx.timer, client: 127.0.0.1, server: 0.0.0.0:9080

[panhow]

here is my log,
first request send in 11:45 am,
second request send at about 15:00 pm.
no ohter logs during two requests.
I think the health check should have other health check logs after the first request

2020/05/08 11:45:57 [error] 40876#0: *3379 kevent() reported that connect() failed (61: Connection refused) while connecting to upstream, client: 127.0.0.1, server: , request: "GET / HTTP/1.1", upstream: "http://127.0.0.1:8000/", host: "cc.pgh.com"
2020/05/08 11:45:57 [warn] 40876#0: *3379 [lua] healthcheck.lua:1107: log(): [healthcheck] (upstream#/apisix/upstreams/00000000000000000356) unhealthy TCP increment (1/2) for '(127.0.0.1:8000)' while connecting to upstream, client: 127.0.0.1, server: , request: "GET / HTTP/1.1", upstream: "http://127.0.0.1:8000/", host: "cc.pgh.com"
2020/05/08 15:00:01 [error] 40876#0: *1326929 kevent() reported that connect() failed (61: Connection refused) while connecting to upstream, client: 127.0.0.1, server: , request: "GET / HTTP/1.1", upstream: "http://127.0.0.1:8888/", host: "cc.pgh.com"
2020/05/08 15:00:01 [warn] 40876#0: *1326929 [lua] healthcheck.lua:1107: log(): [healthcheck] (upstream#/apisix/upstreams/00000000000000000356) unhealthy TCP increment (1/2) for '(127.0.0.1:8888)' while connecting to upstream, client: 127.0.0.1, server: , request: "GET / HTTP/1.1", upstream: "http://127.0.0.1:8888/", host: "cc.pgh.com"
2020/05/08 15:00:01 [error] 40876#0: *1326929 kevent() reported that connect() failed (61: Connection refused) while connecting to upstream, client: 127.0.0.1, server: , request: "GET / HTTP/1.1", upstream: "http://127.0.0.1:8000/", host: "cc.pgh.com"
2020/05/08 15:00:01 [warn] 40876#0: *1326929 [lua] healthcheck.lua:1107: log(): [healthcheck] (upstream#/apisix/upstreams/00000000000000000356) unhealthy TCP increment (2/2) for '(127.0.0.1:8000)' while connecting to upstream, client: 127.0.0.1, server: , request: "GET / HTTP/1.1", upstream: "http://127.0.0.1:8000/", host: "cc.pgh.com"
2020/05/08 15:00:01 [error] 40876#0: *1326929 kevent() reported that connect() failed (61: Connection refused) while connecting to upstream, client: 127.0.0.1, server: , request: "GET / HTTP/1.1", upstream: "http://127.0.0.1:8888/", host: "cc.pgh.com"
2020/05/08 15:00:01 [warn] 40876#0: *1326929 [lua] healthcheck.lua:1107: log(): [healthcheck] (upstream#/apisix/upstreams/00000000000000000356) unhealthy TCP increment (2/2) for '(127.0.0.1:8888)' while connecting to upstream, client: 127.0.0.1, server: , request: "GET / HTTP/1.1", upstream: "http://127.0.0.1:8888/", host: "cc.pgh.com"

[panhow]

i find it work in this config, active health check must work with both health and unhealth, if i only set unhealth, it works strange.
here is my correct configure:

curl -XPUT localhost:9080/apisix/admin/upstreams/00000000000000000356 -H 'X-API-KEY: edd1c9f034335f136f87ad84b625c8f1' --data '
{
  "enable_websocket": true,
  "hash_on": "vars",
  "id": "00000000000000000356",
  "nodes": {
    "127.0.0.1:8000": 10,
    "127.0.0.1:6666": 10,
    "127.0.0.1:8888": 10
  },
  "desc": "k8s_kae/moservice-adadapteradmin/30",
  "type": "roundrobin",
  "checks": {
    "active": {
      "healthy": {
        "interval": 2,
        "successes": 1
      },
      "unhealthy": {
        "interval": 3,
        "http_failures": 254,
        "tcp_failures": 5
      },
      "type": "http",
      "http_path": "/"
    }
  }
}'

@membphis thx

[panhow]

i get another promblem is, i don't want the upstream endpoints are set unhealthy caused it response too many 50x. I just want to set it unhealthy when apisix can't Connect to it.(Return Connection Timeout. @membphis

[membphis]

here is the fully define of schema, you can take a look:

https://github.com/apache/incubator-apisix/blob/master/apisix/schema_def.lua#L69

here is the official doc website, you can take a look: https://kong.github.io/lua-resty-healthcheck/

[panhow]

Did anything update? @membphis @moonming
Now i use apisix on this version: 89baaeababfa82218f9e3aa3374346a48fb382cb,
this health check config doesn't work
this log never shows

2020/05/08 15:03:05 [warn] 62623#0: *7847 [lua] healthcheck.lua:1107: log(): [healthcheck] (upstream#/apisix/upstreams/00000000000000000356) healthy SUCCESS increment (1/1) for '(127.0.0.1:1980)', context: ngx.timer, client: 127.0.0.1, server: 0.0.0.0:9080
2020/05/08 15:03:05 [warn] 62623#0: *7847 [lua] healthcheck.lua:1107: log(): [healthcheck] (upstream#/apisix/upstreams/00000000000000000356) healthy SUCCESS increment (1/1) for '(127.0.0.1:1981)', context: ngx.timer, client: 127.0.0.1, server: 0.0.0.0:9080
2020/05/08 15:03:05 [warn] 62623#0: *7847 [lua] healthcheck.lua:1107: log(): [healthcheck] (upstream#/apisix/upstreams/00000000000000000356) healthy SUCCESS increment (1/1) for '(127.0.0.1:1982)', context: ngx.timer, client: 127.0.0.1, server: 0.0.0.0:9080

it works fine at my side.

curl -XPUT 127.0.0.1:9080/apisix/admin/upstreams/00000000000000000356 -H 'X-API-KEY: edd1c9f034335f136f87ad84b625c8f1' --data '
{
  "enable_websocket": true,
  "hash_on": "vars",
  "nodes": {
    "127.0.0.1:1980": 10,
    "127.0.0.1:1981": 10,
    "127.0.0.1:1982": 10
  },
  "desc": "test-health-check",
  "type": "roundrobin",
  "checks": {
    "active": {
      "healthy": {
        "interval": 2,
        "successes": 1
      },
      "unhealthy": {
          "interval": 1,
          "http_failures": 2
      },
      "type": "http",
      "http_path": "/"
    }
  }
}'

curl http://127.0.0.1:9080/apisix/admin/routes/1  -H 'X-API-KEY: edd1c9f034335f136f87ad84b625c8f1' -X PUT -d '
{
    "methods": ["GET"],
    "uri": "/test/index.html",
    "upstream_id": "00000000000000000356"
}'

2020/05/08 15:02:57 [error] 62623#0: *7170 connect() failed (111: Connection refused) while connecting to upstream, client: 127.0.0.1, server: , request: "GET /test/index.html HTTP/1.1", upstream: "http://127.0.0.1:1980/test/index.html", host: "127.0.0.1:9080"
2020/05/08 15:02:57 [warn] 62623#0: *7170 [lua] healthcheck.lua:1107: log(): [healthcheck] (upstream#/apisix/upstreams/00000000000000000356) unhealthy TCP increment (1/2) for '(127.0.0.1:1980)' while connecting to upstream, client: 127.0.0.1, server: , request: "GET /test/index.html HTTP/1.1", upstream: "http://127.0.0.1:1980/test/index.html", host: "127.0.0.1:9080"
2020/05/08 15:02:57 [error] 62623#0: *7170 connect() failed (111: Connection refused) while connecting to upstream, client: 127.0.0.1, server: , request: "GET /test/index.html HTTP/1.1", upstream: "http://127.0.0.1:1981/test/index.html", host: "127.0.0.1:9080"
2020/05/08 15:02:57 [warn] 62623#0: *7170 [lua] healthcheck.lua:1107: log(): [healthcheck] (upstream#/apisix/upstreams/00000000000000000356) unhealthy TCP increment (1/2) for '(127.0.0.1:1981)' while connecting to upstream, client: 127.0.0.1, server: , request: "GET /test/index.html HTTP/1.1", upstream: "http://127.0.0.1:1981/test/index.html", host: "127.0.0.1:9080"
2020/05/08 15:02:57 [warn] 62623#0: *7173 [lua] healthcheck.lua:1107: log(): [healthcheck] (upstream#/apisix/upstreams/00000000000000000356) unhealthy TCP increment (2/2) for '(127.0.0.1:1980)', context: ngx.timer, client: 127.0.0.1, server: 0.0.0.0:9080
2020/05/08 15:02:57 [warn] 62623#0: *7173 [lua] healthcheck.lua:1107: log(): [healthcheck] (upstream#/apisix/upstreams/00000000000000000356) unhealthy TCP increment (2/2) for '(127.0.0.1:1981)', context: ngx.timer, client: 127.0.0.1, server: 0.0.0.0:9080
2020/05/08 15:02:57 [warn] 62623#0: *7173 [lua] healthcheck.lua:1107: log(): [healthcheck] (upstream#/apisix/upstreams/00000000000000000356) unhealthy TCP increment (1/2) for '(127.0.0.1:1982)', context: ngx.timer, client: 127.0.0.1, server: 0.0.0.0:9080
2020/05/08 15:02:57 [error] 62623#0: *7170 connect() failed (111: Connection refused) while connecting to upstream, client: 127.0.0.1, server: , request: "GET /test/index.html HTTP/1.1", upstream: "http://127.0.0.1:1982/test/index.html", host: "127.0.0.1:9080"
2020/05/08 15:02:57 [warn] 62623#0: *7170 [lua] healthcheck.lua:1107: log(): [healthcheck] (upstream#/apisix/upstreams/00000000000000000356) unhealthy TCP increment (2/2) for '(127.0.0.1:1982)' while connecting to upstream, client: 127.0.0.1, server: , request: "GET /test/index.html HTTP/1.1", upstream: "http://127.0.0.1:1982/test/index.html", host: "127.0.0.1:9080"
2020/05/08 15:02:57 [warn] 62623#0: *7170 [lua] balancer.lua:67: fetch_health_nodes(): all upstream nodes is unhealth, use default while connecting to upstream, client: 127.0.0.1, server: , request: "GET /test/index.html HTTP/1.1", upstream: "http://127.0.0.1:1982/test/index.html", host: "127.0.0.1:9080"
2020/05/08 15:02:57 [error] 62623#0: *7170 connect() failed (111: Connection refused) while connecting to upstream, client: 127.0.0.1, server: , request: "GET /test/index.html HTTP/1.1", upstream: "http://127.0.0.1:1980/test/index.html", host: "127.0.0.1:9080"
2020/05/08 15:03:05 [warn] 62623#0: *7847 [lua] healthcheck.lua:1107: log(): [healthcheck] (upstream#/apisix/upstreams/00000000000000000356) healthy SUCCESS increment (1/1) for '(127.0.0.1:1980)', context: ngx.timer, client: 127.0.0.1, server: 0.0.0.0:9080
2020/05/08 15:03:05 [warn] 62623#0: *7847 [lua] healthcheck.lua:1107: log(): [healthcheck] (upstream#/apisix/upstreams/00000000000000000356) healthy SUCCESS increment (1/1) for '(127.0.0.1:1981)', context: ngx.timer, client: 127.0.0.1, server: 0.0.0.0:9080
2020/05/08 15:03:05 [warn] 62623#0: *7847 [lua] healthcheck.lua:1107: log(): [healthcheck] (upstream#/apisix/upstreams/00000000000000000356) healthy SUCCESS increment (1/1) for '(127.0.0.1:1982)', context: ngx.timer, client: 127.0.0.1, server: 0.0.0.0:9080


2020/05/08 15:03:21 [warn] 62623#0: *9247 [lua] healthcheck.lua:1107: log(): [healthcheck] (upstream#/apisix/upstreams/00000000000000000356) unhealthy TCP increment (1/2) for '(127.0.0.1:1980)', context: ngx.timer, client: 127.0.0.1, server: 0.0.0.0:9080
2020/05/08 15:03:21 [warn] 62623#0: *9247 [lua] healthcheck.lua:1107: log(): [healthcheck] (upstream#/apisix/upstreams/00000000000000000356) unhealthy TCP increment (1/2) for '(127.0.0.1:1981)', context: ngx.timer, client: 127.0.0.1, server: 0.0.0.0:9080
2020/05/08 15:03:21 [warn] 62623#0: *9247 [lua] healthcheck.lua:1107: log(): [healthcheck] (upstream#/apisix/upstreams/00000000000000000356) unhealthy TCP increment (1/2) for '(127.0.0.1:1982)', context: ngx.timer, client: 127.0.0.1, server: 0.0.0.0:9080
2020/05/08 15:03:23 [warn] 62623#0: *9396 [lua] healthcheck.lua:1107: log(): [healthcheck] (upstream#/apisix/upstreams/00000000000000000356) unhealthy TCP increment (2/2) for '(127.0.0.1:1980)', context: ngx.timer, client: 127.0.0.1, server: 0.0.0.0:9080
2020/05/08 15:03:23 [warn] 62623#0: *9396 [lua] healthcheck.lua:1107: log(): [healthcheck] (upstream#/apisix/upstreams/00000000000000000356) unhealthy TCP increment (2/2) for '(127.0.0.1:1981)', context: ngx.timer, client: 127.0.0.1, server: 0.0.0.0:9080
2020/05/08 15:03:23 [warn] 62623#0: *9396 [lua] healthcheck.lua:1107: log(): [healthcheck] (upstream#/apisix/upstreams/00000000000000000356) unhealthy TCP increment (2/2) for '(127.0.0.1:1982)', context: ngx.timer, client: 127.0.0.1, server: 0.0.0.0:9080

[membphis]

what is your full config file now? I need it for confirming.

[spacewander]

Closed as lack of response.