kingluo opened a new issue, #8181: URL: https://github.com/apache/apisix/issues/8181
### Current Behavior enable ext-plugin-post-resp plugin, while the below conditions satisfied, the downstream response would lost last chunk: * ext-plugin-post-resp does not change upstream response body, so that upstream response would be forwarded to downstream * upstream responses multiple chunks, the first chunk plus headers bigger than `postpone_output` (1460 by deafult), the second or the last chunk is smaller than `postpone_output` Issue report source (slack link): https://the-asf.slack.com/archives/CUC5MN17A/p1666604718850519 ## Reason Issue trigger function: https://github.com/apache/apisix/blob/e2d0f0b16bb157412684a38b129d12acb4628d39/apisix/plugins/ext-plugin-post-resp.lua#L109 Assume we got two chunks from upstream. The first chunk plus headers are bigger than `postpone_output`, so `ngx.print` would send the data via socket system call. If it's successful, then it would place two free bufs in `ctx->free_bufs`, in fact, these two bufs points to the same buf. See below for low level detail. Then `ngx.flush` would consume one free buf, and try to flush, altough nothing needed to flush at the moment. After `ngx.flush` finishes, the `ctx->free_bufs` has three free bufs, all point to the same buf. The second chunk consumes one free buf, and because it is smaller than `postpone_output`, so it is kept by nginx, so not return to `ctx->free_bufs`. Then the problem comes in, `ngx.flush` consumes one free buf, but this buf points the one used by the last chunk, and got cleared, set `buf->flush=1`, which results in emtpy content but with chunk prefix and suffix: ``` d\r\n\r\n ``` Here `d\r\n` is chunk prefix, means 13 bytes, and tail `\r\n` is chunk suffix. But nothing between! As a result, `curl` would reports `transfer closed with outstanding read data remaining`, because it makes `curl` confused. ### low-level explanation `ngx_http_lua_ngx_echo` and `ngx_http_lua_ngx_flush` would finally call `ngx_chain_update_chains` twice, and makes the same buf returns to `ctx->free_bufs` twice! Both `ngx_http_lua_ngx_echo` and `ngx_http_lua_ngx_flush` calls `ngx_http_lua_output_filter`: ```c static ngx_int_t ngx_http_lua_output_filter(ngx_http_request_t *r, ngx_chain_t *in) { ... rc = ngx_http_output_filter(r, in); if (rc == NGX_ERROR) { return NGX_ERROR; } ctx = ngx_http_get_module_ctx(r, ngx_http_lua_module); if (ctx == NULL) { return rc; } ngx_chain_update_chains(r->pool, &ctx->free_bufs, &ctx->busy_bufs, &in, (ngx_buf_tag_t) &ngx_http_lua_module); ... return rc; } ``` ```c static ngx_int_t ngx_http_lua_body_filter(ngx_http_request_t *r, ngx_chain_t *in) { ... ngx_chain_update_chains(r->pool, &ctx->free_bufs, &ctx->filter_busy_bufs, &out, (ngx_buf_tag_t) &ngx_http_lua_module); ... return rc; } ``` ### use gdb to verify it `ctx_freebufs.gdb` ```gdb b ngx_http_lua_output.c:241 command 1 set $v = ctx->free_bufs while ($v != 0) p $v p $v->buf set $v=$v->next end continue end b ngx_http_lua_output.c:554 command 2 set $v = ctx->free_bufs while ($v != 0) p $v p $v->buf set $v=$v->next end continue end continue ``` Output: ``` Thread 1 "openresty" hit Breakpoint 1, ngx_http_lua_ngx_echo (L=0x7f7b4139a2a0, newline=<optimized out>) at ../ngx_lua-0.10.21/src/ngx_http_lua_output.c:241 241 if (rc == NGX_ERROR || rc >= NGX_HTTP_SPECIAL_RESPONSE) { $1 = (ngx_chain_t *) 0x55bedbbd6350 $2 = (ngx_buf_t *) 0x55bedbbd6360 $3 = (ngx_chain_t *) 0x55bedbbd69e8 $4 = (ngx_buf_t *) 0x55bedbbd6360 Thread 1 "openresty" hit Breakpoint 2, ngx_http_lua_ngx_flush (L=0x7f7b4139a2a0) at ../ngx_lua-0.10.21/src/ngx_http_lua_output.c:556 556 if (rc == NGX_ERROR || rc >= NGX_HTTP_SPECIAL_RESPONSE) { $5 = (ngx_chain_t *) 0x55bedbbd6350 $6 = (ngx_buf_t *) 0x55bedbbd6360 $7 = (ngx_chain_t *) 0x55bedbbd69f8 $8 = (ngx_buf_t *) 0x55bedbbd6360 $9 = (ngx_chain_t *) 0x55bedbbd69e8 $10 = (ngx_buf_t *) 0x55bedbbd6360 Thread 1 "openresty" hit Breakpoint 1, ngx_http_lua_ngx_echo (L=0x7f7b4139a2a0, newline=<optimized out>) at ../ngx_lua-0.10.21/src/ngx_http_lua_output.c:241 241 if (rc == NGX_ERROR || rc >= NGX_HTTP_SPECIAL_RESPONSE) { $11 = (ngx_chain_t *) 0x55bedbbd69f8 $12 = (ngx_buf_t *) 0x55bedbbd6360 $13 = (ngx_chain_t *) 0x55bedbbd69e8 $14 = (ngx_buf_t *) 0x55bedbbd6360 Thread 1 "openresty" hit Breakpoint 2, ngx_http_lua_ngx_flush (L=0x7f7b4139a2a0) at ../ngx_lua-0.10.21/src/ngx_http_lua_output.c:556 556 if (rc == NGX_ERROR || rc >= NGX_HTTP_SPECIAL_RESPONSE) { $15 = (ngx_chain_t *) 0x55bedbbd69f8 $16 = (ngx_buf_t *) 0x55bedbbd6360 $17 = (ngx_chain_t *) 0x55bedbbd6350 $18 = (ngx_buf_t *) 0x55bedbbd6360 $19 = (ngx_chain_t *) 0x55bedbbe1a18 $20 = (ngx_buf_t *) 0x55bedbbd6360 $21 = (ngx_chain_t *) 0x55bedbbe19e0 $22 = (ngx_buf_t *) 0x55bedbbd6360 $23 = (ngx_chain_t *) 0x55bedbbd69e8 $24 = (ngx_buf_t *) 0x55bedbbd6360 ``` **Note that all free bufs points to the same address `0x55bedbbd6360`!!!** ## workaround before bugfix Comment `ngx.flush`, in fact, it does not affect the final result, because when the main request finishes, all chunks would be send to downstream. And it even does not affect performance! Because as long as your chunk is bigger than `postpone_output`, it would be send directly via socket, no matter whether you flush or not later. ``` local function send_chunk(chunk) if not chunk then return nil end local ok, print_err = ngx_print(chunk) if not ok then return "output response failed: ".. (print_err or "") end --local ok, flush_err = ngx_flush(true) --if not ok then -- core.log.warn("flush response failed: ", flush_err) --end return nil end ``` ### Expected Behavior _No response_ ### Error Logs _No response_ ### Steps to Reproduce `go_chunked_http_server.go` ```go package main import ( "io" "net" "net/http" ) func handle(w http.ResponseWriter, req *http.Request) { w.Header().Set("Transfer-Encoding", "chunked") buf := make([]byte, 10000) io.WriteString(w, string(buf[:1450])) if f, ok := w.(http.Flusher); ok { f.Flush() } io.WriteString(w, string(buf[:13])) } func main() { addr := "127.0.0.1:9094" l, err := net.Listen("tcp", addr) if err != nil { panic("AAAAH") } server := http.Server{ Handler: http.HandlerFunc(handle), } server.Serve(l) } ``` ```bash go run go_chunked_http_server.go curl -i http://127.0.0.1:9180/apisix/admin/routes/chunked_bug \ -H 'X-API-KEY: edd1c9f034335f136f87ad84b625c8f1' -X PUT -d ' { "uri": "/stream-bytes/*", "plugins": { "ext-plugin-post-resp": { "conf" : [ {"name": "ext-plugin-A", "value": "{\"enable\":\"feature\"}"} ] } }, "upstream": { "type": "roundrobin", "nodes": { "127.0.0.1:9094": 1 } } }' curl -s -vvv localhost:9080/stream-bytes/8205 -o /tmp/chunked.response * TCP_NODELAY set * Connected to localhost (::1) port 9080 (#0) > GET /stream-bytes/8205 HTTP/1.1 > Host: localhost:9080 > User-Agent: curl/7.68.0 > Accept: */* > * Mark bundle as not supporting multiuse < HTTP/1.1 200 OK < Date: Wed, 26 Oct 2022 09:25:35 GMT < Content-Type: text/plain; charset=utf-8 < Transfer-Encoding: chunked < Connection: keep-alive < Server: APISIX/2.99.0 < { [1467 bytes data] 100 1457 0 1457 0 0 24 0 --:--:-- 0:01:00 --:--:-- 0* transfer closed with outstanding read data remaining 100 1457 0 1457 0 0 24 0 --:--:-- 0:01:00 --:--:-- 0 * Closing connection 0 curl: (18) transfer closed with outstanding read data remaining ``` ### Environment - APISIX version (run `apisix version`): master branch - Operating system (run `uname -a`): - OpenResty / Nginx version (run `openresty -V` or `nginx -V`): - etcd version, if relevant (run `curl http://127.0.0.1:9090/v1/server_info`): - APISIX Dashboard version, if relevant: - Plugin runner version, for issues related to plugin runners: - LuaRocks version, for installation issues (run `luarocks --version`): -- This is an automated message from the Apache Git Service. To respond to the message, please log on to GitHub and use the URL above to go to the specific comment. To unsubscribe, e-mail: [email protected] For queries about this service, please contact Infrastructure at: [email protected]
