bug: 使用apisix的ext-plugin-post-resp插件配合apisix-java-plugin-runner0.3.0支持过滤上游响应标头时，上游返回状态码为204时，会重复发送http的请求的问题

[beginnerWJC]

Issue description

Environment

• apisix-java-plugin-runner 0.3.0
• apisix 2.15.0

Minimal test code / Steps to reproduce the issue

1.配置使用ext-plugin-post-resp插件

2.测试时，发现上游返回204时会请求两次



http返回码改成200则正常了，只请求了一次

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

由于重复请求，导致第二次报错

What's the expected result?

上游返回204时，不再重复请求

[tzssangglass]

use text, not images.

[tzssangglass]

Who requested twice from whom? APISIX --> java runner?

[tzssangglass]

I tried but did not reproduce.

[beginnerWJC]

看起来是APISIX的这个ext-plugin-post-resp由于上游的http状态码是204调用了多次

[tzssangglass]

看起来是APISIX的这个ext-plugin-post-resp由于上游的http状态码是204调用了多次

I use openresty as upstream, conf as

    server {
        listen 1980;

        access_log off;
        location / {
            content_by_lua_block {
                ngx.status = 204
                ngx.say("hello, world")
            }
        }
    }

test access upstream directly:

curl http://127.0.0.1:1980/get -i
HTTP/1.1 204 No Content
Server: openresty/1.21.4.1
Date: Tue, 23 Aug 2022 10:57:44 GMT
Connection: keep-alive

test proxy by APISIX, and add the breakpoint in the postFilter function, T found that it only ran once.

I cannot reproduce the bug you mentioned, can you provide a minimal reproduction use case so that I can reproduce it locally?

[beginnerWJC]

我的测试postFilter代码
package org.apache.apisix.plugin.runner.filter;

import java.util.Map;
import org.apache.apisix.plugin.runner.PostRequest;
import org.apache.apisix.plugin.runner.PostResponse;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.stereotype.Component;
import com.alibaba.fastjson.JSON;

@component
public class TestPostFilter implements PluginFilter {

private final Logger logger = LoggerFactory.getLogger(TestPostFilter.class);

@Override
public String name() {
	return "TestPostFilter";
}

@Override
public void postFilter(PostRequest request, PostResponse response, PluginFilterChain chain) {
	logger.info("TestPostFilter插件开始执行！");
	Map<String, String> headersMap = request.getUpstreamHeaders();
	logger.info("上游返回的headers:{}",JSON.toJSONString(headersMap));
	int statusCode = request.getUpstreamStatusCode();
	logger.info("上游返回的状态码为:{}",statusCode);
	response.setHeader("apisix", "TestPostFilter");
	chain.postFilter(request, response);
}

}
通过apisix dashboard配置路由一个http返回值是204并且没有返回体的接口

然后测试调用，发现上游的接口返回204时会请求两次
由于我测试代理的是登出接口，第一次是204，第二次由于已经登出过了就变成401了，导致我发现了这个问题。



然后在本地把登出接口http返回码改成200就正常了，只请求了一次

这个是我完整的复现过程了

[tzssangglass]

I can't understand what you're saying about recurrence, there's too much of your own business logic in there.

In fact, you could do what I did and not use the logout interface for validation, in the simplest way possible.

You can actually watch APISIX's access.log generate a log at access.log per request and call the java runner's postFilter function once, as a comparison.

[beginnerWJC]

我重新写了两个测试接口进行测试，还是重现了这个现象，204会进行重试，200就是一次

我在接口层打印，发现204还是请求了两次
看了一下2.15版本的APISIX发现和代码也对上了，走了ext-plugin-post-resp.lua插件的重试逻辑

APISIX 2.15.0
apisix-java 0.3.0
使用的APISIX插件 ext-plugin-post-resp

[beginnerWJC]

我开启了APISIX的调试模式，看到了APISIX对于204响应码的请求发送了两次

[tzssangglass]

看了一下2.15版本的APISIX发现和代码也对上了，走了ext-plugin-post-resp.lua插件的重试逻辑

Retries don't happen every time, only if the java plugin runner has handled the exception, ref: https://github.com/apache/apisix/blob/master/apisix/plugins/ext-plugin/init.lua#L730-L742

        local ok, err = send(sock, constants.RPC_HTTP_RESP_CALL, builder:Output())
        if not ok then
            return nil, "failed to send RPC_HTTP_RESP_CALL: " .. err
        end


        local ty, resp = receive(sock)
        if ty == nil then
            return nil, "failed to receive RPC_HTTP_RESP_CALL: " .. resp
        end


        if ty ~= constants.RPC_HTTP_RESP_CALL then
            return nil, "failed to receive RPC_HTTP_RESP_CALL: unexpected type " .. ty
        end

I have reproduced it again in Debug mode

I still can't reproduce it.

Here is my reproduction process:

1. upstream(an openresty server)

master_process on;

worker_processes 2;

error_log logs/error.log warn;
pid logs/nginx.pid;

worker_rlimit_nofile 20480;

events {
    accept_mutex off;
    worker_connections 10620;
}

worker_shutdown_timeout 3;

http {
    server {
        listen 1980;

        access_log off;
        location / {
            content_by_lua_block {
                ngx.status = 204
                ngx.say("hello, world")
            }
        }
    }
}

test

curl http://127.0.0.1:1980/get -i
HTTP/1.1 204 No Content
Server: openresty/1.21.4.1
Date: Thu, 25 Aug 2022 04:19:24 GMT
Connection: keep-alive

2. route

curl http://127.0.0.1:9080/apisix/admin/routes/1 -H 'X-API-KEY: edd1c9f034335f136f87ad84b625c8f1' -X PUT -d '
{
    "uri":"/get",
    "plugins":{
        "ext-plugin-post-resp":{
            "conf":[
                {
                    "name":"TestResponseFilter",
                    "value":"{\"rewrite_path\":\"token\",\"validate_url\":\"https://www.sso.foo.com/token/validate\",\"rejected_code\":\"403\"}"
                }
            ]
        }
    },
    "upstream":{
        "nodes":{
            "127.0.0.1:1980":1
        },
        "type":"roundrobin"
    }
}'

config.yaml

apisix:
  admin_key:
    - name: admin
      key: edd1c9f034335f136f87ad84b625c8f1  # using fixed API token has security risk, please update it when you deploy to production environment
      role: admin
ext-plugin:
  path_for_test: "/tmp/runner.sock"

4. java plugin runner: https://github.com/tzssangglass/java-plugin-runner-demo-1

5. test proxy by APISIX and connect to java plugin runner

curl http://127.0.0.1:9080/get -i
HTTP/1.1 204 No Content
Connection: keep-alive
Date: Thu, 25 Aug 2022 04:15:20 GMT
Date: Thu, 25 Aug 2022 04:15:20 GMT
Server: APISIX/2.15.0

the logs of java plugin runner

2022-08-25 12:15:14.714  INFO 2521381 --- [           main] c.e.d.DemoApplication                    : No active profile set, falling back to 1 default profile: "default"
2022-08-25 12:15:15.229  INFO 2521381 --- [           main] c.e.d.DemoApplication                    : Started DemoApplication in 0.898 seconds (JVM running for 1.716)
2022-08-25 12:15:15.362  WARN 2521381 --- [           main] o.a.a.p.r.s.ApplicationRunner            : java runner is listening on the socket file: /tmp/runner.sock
2022-08-25 12:15:20.278  WARN 2521381 --- [ntLoopGroup-2-2] c.e.d.TestResponseFilter                 : status : 204

the status : 204 only print once.

[beginnerWJC]

有看过代理的上游的日志吗？java plugin runner的日志里面我也只会打印一次，但是在代理的上游日志里面看到了两次调用的日志。
APISIX插件配置

"ext-plugin-post-resp": {
      "conf": [
        {
          "name": "TestPostFilter",
          "value": "{}"
        }
      ],
      "disable": false
    }

TestPostFilter的代码

public void postFilter(PostRequest request, PostResponse response, PluginFilterChain chain) {
		logger.info("TestPostFilter插件开始执行！");
		Map<String, String> headersMap = request.getUpstreamHeaders();
		logger.info("上游返回的headers:{}",JSON.toJSONString(headersMap));
		int statusCode = request.getUpstreamStatusCode();
		logger.info("上游返回的状态码为:{}",statusCode);
		response.setHeader("apisix", "TestPostFilter");
		chain.postFilter(request, response);
    }

我是配置了APISIX的debug.yaml，开启了基本调试模式

basic:
      enable: true

代理的上游接口响应码为204的日志(在代理的接口日志那里显示调用了两次)：
APISIX的日志：(看到发送了两次)

2022/08/25 05:01:15 [warn] 57#57: *191 [lua] init.lua:913: 08/25 05:01:15.190 [epollEventLoopGroup-2-1] INFO  [o.a.a.p.runner.filter.TestPostFilter] -TestPostFilter插件开始执行！
, context: ngx.timer
2022/08/25 05:01:15 [warn] 57#57: *191 [lua] init.lua:913: 08/25 05:01:15.191 [epollEventLoopGroup-2-1] INFO  [o.a.a.p.runner.filter.TestPostFilter] -上游返回的headers:{"Date":"Thu, 25 Aug 2022 05:01:15 GMT"}
, context: ngx.timer
2022/08/25 05:01:15 [warn] 57#57: *191 [lua] init.lua:913: 08/25 05:01:15.191 [epollEventLoopGroup-2-1] INFO  [o.a.a.p.runner.filter.TestPostFilter] -上游返回的状态码为:204
, context: ngx.timer
2022/08/25 05:01:15 [warn] 48#48: *849033 [lua] plugin.lua:384: trace_plugins_info_for_debug(): Apisix-Plugins: prometheus while sending to client, client: 172.17.67.0, server: _, request: "GET /robot-monitor/v1/robotMonitor/test204 HTTP/1.1", upstream: "http://192.168.2.120:8900/robot-monitor/v1/robotMonitor/test204", host: "192.168.40.174:30880"
2022/08/25 05:01:15 [warn] 48#48: *849033 [lua] plugin.lua:384: trace_plugins_info_for_debug(): Apisix-Plugins: prometheus while sending to client, client: 172.17.67.0, server: _, request: "GET /robot-monitor/v1/robotMonitor/test204 HTTP/1.1", upstream: "http://192.168.2.120:8900/robot-monitor/v1/robotMonitor/test204", host: "192.168.40.174:30880"
2022/08/25 05:01:15 [warn] 48#48: *849033 [lua] plugin.lua:384: trace_plugins_info_for_debug(): Apisix-Plugins: prometheus while logging request, client: 172.17.67.0, server: _, request: "GET /robot-monitor/v1/robotMonitor/test204 HTTP/1.1", upstream: "http://192.168.2.120:8900/robot-monitor/v1/robotMonitor/test204", host: "192.168.40.174:30880"
172.17.67.0 - - [25/Aug/2022:05:01:15 +0000] 192.168.40.174:30880 "GET /robot-monitor/v1/robotMonitor/test204 HTTP/1.1" 204 0 0.010 "-" "PostmanRuntime/7.28.4" 192.168.2.120:8900 204 0.004 "http://192.168.40.174:30880"

java plugin runner的日志：

08/25 05:01:15.190 [epollEventLoopGroup-2-1] INFO  [o.a.a.p.runner.filter.TestPostFilter] -TestPostFilter插件开始执行！
08/25 05:01:15.191 [epollEventLoopGroup-2-1] INFO  [o.a.a.p.runner.filter.TestPostFilter] -上游返回的headers:{"Date":"Thu, 25 Aug 2022 05:01:15 GMT"}
08/25 05:01:15.191 [epollEventLoopGroup-2-1] INFO  [o.a.a.p.runner.filter.TestPostFilter] -上游返回的状态码为:204

代理的上游显示的日志：(这里看到调用了两次)

2022-08-25 13:01:15.175  INFO 28652 --- [  XNIO-1 task-3] c.w.controller.RobotMonitorController    : test204
2022-08-25 13:01:15.175  INFO 28652 --- [  XNIO-1 task-3] com.wellcloud.common.aspect.LogAspect    : request: test204, cost: 0
2022-08-25 13:01:15.180  INFO 28652 --- [  XNIO-1 task-4] c.w.controller.RobotMonitorController    : test204
2022-08-25 13:01:15.181  INFO 28652 --- [  XNIO-1 task-4] com.wellcloud.common.aspect.LogAspect    : request: test204, cost: 1

代理的上游响应码是200的日志
APISIX的日志：

2022/08/25 05:13:26 [warn] 57#57: *191 [lua] init.lua:913: 08/25 05:13:26.124 [epollEventLoopGroup-2-1] INFO  [o.a.a.p.runner.filter.TestPostFilter] -TestPostFilter插件开始执行！
, context: ngx.timer
2022/08/25 05:13:26 [warn] 57#57: *191 [lua] init.lua:913: 08/25 05:13:26.125 [epollEventLoopGroup-2-1] INFO  [o.a.a.p.runner.filter.TestPostFilter] -上游返回的headers:{"Connection":"keep-alive","Content-Length":"0","Date":"Thu, 25 Aug 2022 05:13:26 GMT"}
, context: ngx.timer
2022/08/25 05:13:26 [warn] 57#57: *191 [lua] init.lua:913: 08/25 05:13:26.125 [epollEventLoopGroup-2-1] INFO  [o.a.a.p.runner.filter.TestPostFilter] -上游返回的状态码为:200
, context: ngx.timer
2022/08/25 05:13:26 [warn] 50#50: *936815 [lua] plugin.lua:384: trace_plugins_info_for_debug(): Apisix-Plugins: prometheus, client: 172.17.67.0, server: _, request: "GET /robot-monitor/v1/robotMonitor/test200 HTTP/1.1", host: "192.168.40.174:30880"
2022/08/25 05:13:26 [warn] 50#50: *936815 [lua] plugin.lua:384: trace_plugins_info_for_debug(): Apisix-Plugins: prometheus, client: 172.17.67.0, server: _, request: "GET /robot-monitor/v1/robotMonitor/test200 HTTP/1.1", host: "192.168.40.174:30880"
2022/08/25 05:13:26 [warn] 50#50: *936815 [lua] plugin.lua:384: trace_plugins_info_for_debug(): Apisix-Plugins: prometheus, client: 172.17.67.0, server: _, request: "GET /robot-monitor/v1/robotMonitor/test200 HTTP/1.1", host: "192.168.40.174:30880"
2022/08/25 05:13:26 [warn] 50#50: *936815 [lua] plugin.lua:384: trace_plugins_info_for_debug(): Apisix-Plugins: prometheus, client: 172.17.67.0, server: _, request: "GET /robot-monitor/v1/robotMonitor/test200 HTTP/1.1", host: "192.168.40.174:30880"
2022/08/25 05:13:26 [warn] 50#50: *936815 [lua] plugin.lua:384: trace_plugins_info_for_debug(): Apisix-Plugins: prometheus while logging request, client: 172.17.67.0, server: _, request: "GET /robot-monitor/v1/robotMonitor/test200 HTTP/1.1", host: "192.168.40.174:30880"
172.17.67.0 - - [25/Aug/2022:05:13:26 +0000] 192.168.40.174:30880 "GET /robot-monitor/v1/robotMonitor/test200 HTTP/1.1" 200 5 0.033 "-" "PostmanRuntime/7.28.4" - - - "http://192.168.40.174:30880"

java plugin runner的日志：

08/25 05:13:26.124 [epollEventLoopGroup-2-1] INFO  [o.a.a.p.runner.filter.TestPostFilter] -TestPostFilter插件开始执行！
08/25 05:13:26.125 [epollEventLoopGroup-2-1] INFO  [o.a.a.p.runner.filter.TestPostFilter] -上游返回的headers:{"Connection":"keep-alive","Content-Length":"0","Date":"Thu, 25 Aug 2022 05:13:26 GMT"}
08/25 05:13:26.125 [epollEventLoopGroup-2-1] INFO  [o.a.a.p.runner.filter.TestPostFilter] -上游返回的状态码为:200

代理的上游显示的日志：

2022-08-25 13:13:26.096  INFO 28652 --- [  XNIO-1 task-5] c.w.controller.RobotMonitorController    : test200
2022-08-25 13:13:26.096  INFO 28652 --- [  XNIO-1 task-5] com.wellcloud.common.aspect.LogAspect    : request: test200, cost: 0

代理的两个接口没有任何区别，唯一的区别就是http的响应码

@ApiOperation(value="获取一个组的最少连接数机器人")
@RequestMapping(value="/test204",method=RequestMethod.GET)
@ResponseStatus(code = HttpStatus.NO_CONTENT)
public void test204()throws CustomException{
	logger.info("test204");
}
	
@ApiOperation(value="获取一个组的最少连接数机器人")
@RequestMapping(value="/test200",method=RequestMethod.GET)
public void test200()throws CustomException{
	logger.info("test200");
}

[tzssangglass]

有看过代理的上游的日志吗？java plugin runner的日志里面我也只会打印一次，但是在代理的上游日志里面看到了两次调用的日志。

Repeat the above replication steps again, the difference is that after opening the upstream access log, I only see one access log when the request goes through the APISIX proxy to the upstream.

127.0.0.1 - - [25/Aug/2022:14:51:49 +0800] "GET /get HTTP/1.1" 204 0 "-" "curl/7.84.0"

[tzssangglass]

Are you finding that the APISIX request happened upstream twice? So I guess it has nothing to do with the java plugin runner?

[beginnerWJC]

的确看起来和java plugin runner无关，看起来是APISIX请求了两次，我去APISIX下面反馈一下把