bug: 10 second URL test comes with 1 second api_ctx nil value error

[azura27]

Issue description

When I test with WRK, 10 seconds flow would have one second error, and cause the QPS to decrease 1w
For issue tracing:
in function: common_phase(phase_name) ADD log: core.log.error("nil instance: api_ctx") after the "api_ctx = ngx.ctx.api_ctx"
in function: http_log_phase() ADD log: core.log.error("fail to create healthcheck instance: ", err) after "api_ctx = common_phase("log")"

Environment

• apisix version (cmd: apisix version): 2.0 (with changes from: https://github.com/apache/apisix/pull/2575/files)
• OS: (cmd: uname -a) Linux 3.10.0-693.el7.x86_64 change: added doc of how to load plugin. #1 SMP Tue Aug 22 21:09:27 UTC 2017 x86_64 x86_64 x86_64 GNU/Linux
• OpenResty / Nginx version: (cmd: nginx -V or openresty -V) 1.15.8.3

Minimal test code / Steps to reproduce the issue

1. run apisix with plugins open: zipkin, limit-count, prometheus,consumer-restriction,key-auth
2. run test with wrk ./wrk -t 4 -d 10 -c 3000

What's the actual result? (including assertion message & call stack if applicable)

2021/01/05 13:51:25 [error] 5324#5324: *97919 [lua] init.lua:653: common_phase(): nil instance: api_ctx while logging request, client:
2021/01/05 13:51:25 [error] 5324#5324: *97919 [lua] init.lua:753: http_log_phase(): fail to create healthcheck instance: nil while logging request, client:

What's the expected result?

no error log and higher QPS

[azura27]

log at info level， found epoll log below:
epoll_wait() reported that client prematurely closed connection, so upstream connection is closed too while sending request to upstream, client: 192.168.1.11, server: , request: "GET /dev/temp.htm?apikey=auth-one HTTP/1.1", subrequest: "@waf", upstream: "192.168.1.10:8000", host: "tt.com:9080"
P.S. The apisix been reconstructed with a subrequest

[spacewander]

There is no code to delete api_ctx in APISIX. I guess it is because the client closed the request before we assign an api_ctx. Would you apply the patch to check if the api_ctx is assigned?

diff --git apisix/init.lua apisix/init.lua
index de51cd38..65585aec 100644
--- apisix/init.lua
+++ apisix/init.lua
@@ -327,6 +327,7 @@ function _M.http_access_phase()

     if not api_ctx then
         api_ctx = core.tablepool.fetch("api_ctx", 0, 32)
+        core.log.alert("set api_ctx ", tostring(ngx_ctx))
         ngx_ctx.api_ctx = api_ctx
     end

@@ -586,6 +587,7 @@ end
 local function common_phase(phase_name)
     local api_ctx = ngx.ctx.api_ctx
     if not api_ctx then
+        core.log.alert("can't find api_ctx ", tostring(ngx.ctx))
         return
     end

BTW, is this problem only happened in subrequest?

[azura27]

I have test without the reconstruction part, It happens too. Thanks for your advice, I will track the api_ctx to look for the origin

[azura27]

P.S. the server runs apisix also runs Nginx. And I find that the "apisix restart" command does not work, with "APISIX is running..." warn return. Does this need to deliver a parameter to start function when restart cmd sent? Just for advice.

[spacewander]

And I find that the "apisix restart" command does not work

The restart command is only a combination of start and stop. Maybe there is a stale nginx.pid file under logs/ or your Nginx uses a different path for pid_file? Anyway, we should open an issue to discuss this instead of hijacking this one.

[azura27]

The restart command is only a combination of start and stop. Maybe there is a stale nginx.pid file under logs/ or your Nginx uses a different path for pid_file? Anyway, we should open an issue to discuss this instead of hijacking this one.

issue start #3202

[azura27]

There is no code to delete api_ctx in APISIX. I guess it is because the client closed the request before we assign an api_ctx. Would you apply the patch to check if the api_ctx is assigned?

I think this is nil value is result from Nginx error: " epoll_wait() reported that client prematurely closed connection, so upstream connection is closed too while sending request to upstream, client: 192.168.1.11, server: , request: "GET /dev/temp.htm?apikey=auth-one HTTP/1.1", subrequest: "@waf", upstream: "192.168.1.10:8000", host: "tt.com:9080" "
And I have searched on WEB, no solution can solve my problem

[azura27]

A werid scene is that when I visit the URL with shell script, this error would not happen, but with wrk/ab tools It would happen

[tokers]

A werid scene is that when I visit the URL with shell script, this error would not happen, but with wrk/ab tools It would happen

Sounds like it's related to stress.

[azura27]

Maybe there is some relation to the stress, but It worked well several days ago. So some other need take into cosnideration too.

I test new/delete route A, andin the mean time, visit B. And after that this QPS stress test went wrong.
But it seeme have no relation with this test, for that I change the server to run apisix, same issue happens too

[azura27]

After test with lower cocurrent connections, this problem disappear with 499(timeout status). It seems this is result from timeout.
Not a bug.