search

apache / apisix-java-plugin-runner

APISIX Plugin Runner in Java
https://apisix.apache.org/
Apache License 2.0
129 stars 95 forks source link

bug: When using the APISIX ext-plugin-post-resp plugin and apisix java plugin runner 0.3.0 to rewrite the upstream response header, when the upstream return status code is 204, this HTTP request apisix will be sent twice #191

Open beginnerWJC opened 2 years ago

beginnerWJC commented 2 years ago

Current Behavior

When using the APISIX ext-plugin-post-resp plugin and apisix java plugin runner 0.3.0 to rewrite the upstream response header, when the upstream return status code is 204, this HTTP request apisix will be sent twice

Expected Behavior

No response

Error Logs

upstream return status code is 204 the logs of APISIX（Sent twice）

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"

the logs of 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

the logs of upstream（Got it twice）

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

When using the APISIX ext-plugin-post-resp plugin and apisix java plugin runner 0.3.0 to rewrite the upstream response header, when the upstream return status code is 204, this HTTP request apisix will be sent twice

if upstream return status code is 200. it is normal the logs of 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"

the logs of 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

the logs of upstream

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

Steps to Reproduce

1.Run APISX via the Docker image 2.Run apisix-dashboard via the Docker image 3.write java plugin

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);
    }

4.write test upstream interface

@ApiOperation(value="test204")
    @RequestMapping(value="/test204",method=RequestMethod.GET)
    @ResponseStatus(code = HttpStatus.NO_CONTENT)
    public void test204()throws CustomException{
        logger.info("test204");
    }

    @ApiOperation(value="test200")
    @RequestMapping(value="/test200",method=RequestMethod.GET)
    public void test200()throws CustomException{
        logger.info("test200");
    }

5.config route to proxy upstream

{
  "uri": "/robot-monitor/v1/*",
  "name": "test",
  "methods": [
    "GET",
    "POST",
    "PUT",
    "DELETE"
  ],
  "plugins": {
    "ext-plugin-post-resp": {
      "conf": [
        {
          "name": "TestPostFilter",
          "value": "{}"
        }
      ],
      "disable": false
    }
  },
  "upstream": {
    "nodes": [
      {
        "host": "192.168.2.120",
        "port": 8900,
        "weight": 1
      }
    ],
    "timeout": {
      "connect": 6,
      "send": 6,
      "read": 6
    },
    "type": "roundrobin",
    "scheme": "http",
    "pass_host": "pass",
    "keepalive_pool": {
      "idle_timeout": 60,
      "requests": 1000,
      "size": 320
    }
  },
  "status": 1
}

6.test it and find upstream return status code is 200. It is normal. but upstream return status code is 204. This HTTP request apisix will be sent twice

Environment

tzssangglass commented 2 years ago

Can you test this without the java plugin runner, client --> APISIX -> upstream, and upstream return 204? what would happen?

beginnerWJC commented 2 years ago

这个我已经测试过了，取消ext-plugin-post-resp插件使用是正常的。上游只会收到一次请求。 路由配置如下，取消了ext-plugin-post-resp插件的使用：

{
  "uri": "/robot-monitor/v1/*",
  "name": "test204",
  "methods": [
    "GET",
    "POST",
    "PUT",
    "DELETE"
  ],
  "plugins": {
    "ext-plugin-post-resp": {
      "conf": [
        {
          "name": "TestPostFilter",
          "value": "{}"
        }
      ],
      "disable": true
    }
  },
  "upstream": {
    "nodes": [
      {
        "host": "192.168.2.120",
        "port": 8900,
        "weight": 1
      }
    ],
    "timeout": {
      "connect": 6,
      "send": 6,
      "read": 6
    },
    "type": "roundrobin",
    "scheme": "http",
    "pass_host": "pass",
    "keepalive_pool": {
      "idle_timeout": 60,
      "requests": 1000,
      "size": 320
    }
  },
  "status": 1
}

APISIX日志：

2022/08/25 15:17:51 [warn] 50#50: *5238792 [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 15:17:51 [warn] 50#50: *5238792 [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 15:17:51 [warn] 50#50: *5238792 [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"

代理的上游日志：

2022-08-25 23:17:51.374  INFO 38280 --- [  XNIO-1 task-1] io.undertow.servlet                      : Initializing Spring DispatcherServlet 'dispatcherServlet'
2022-08-25 23:17:51.374  INFO 38280 --- [  XNIO-1 task-1] o.s.web.servlet.DispatcherServlet        : Initializing Servlet 'dispatcherServlet'
2022-08-25 23:17:51.396  INFO 38280 --- [  XNIO-1 task-1] o.s.web.servlet.DispatcherServlet        : Completed initialization in 22 ms
2022-08-25 23:17:51.460  INFO 38280 --- [  XNIO-1 task-1] c.w.controller.RobotMonitorController    : test204
2022-08-25 23:17:51.460  INFO 38280 --- [  XNIO-1 task-1] com.wellcloud.common.aspect.LogAspect    : request: test204, cost: 13
beginnerWJC commented 2 years ago

其实我感觉是ext-plugin-post-resp这个插件的问题

tzssangglass commented 2 years ago

Strangely, as you know, I tried to reproduce it several times without success.

You can add log output here: https://github.com/apache/apisix/blob/master/apisix/plugins/ext-plugin/init.lua#L730-L742

show ok, err and ty, resp

beginnerWJC commented 2 years ago

我不太了解APISIX的处理逻辑，但是我发现处理200和204的日志有所不同，从这里面可以看出问题吗？ 响应码为204的APISIX的处理日志

2022/08/26 07:10:50 [info] 54#54: *147075 [lua] init.lua:380: http_access_phase(): matched route: {"value":{"name":"test204","upstream":{"timeout":{"connect":6,"send":6,"read":6},"parent":{"value":"table: 0x7fea60263578","modifiedIndex":240389,"clean_handlers":{},"has_domain":false,"update_count":0,"orig_modifiedIndex":240389,"key":"\/apisix\/routes\/422552840368554762","createdIndex":240257},"pass_host":"pass","nodes":[{"port":8900,"weight":1,"upstream_host":"192.168.2.120:8900","host":"192.168.2.120","priority":0}],"keepalive_pool":{"size":320,"idle_timeout":60,"requests":1000},"nodes_ref":"table: 0x7fea602638f8","type":"roundrobin","hash_on":"vars","scheme":"http","original_nodes":"table: 0x7fea602638f8"},"uri":"\/robot-monitor\/v1\/*","update_time":1661493500,"id":"422552840368554762","create_time":1661390719,"plugins":{"ext-plugin-post-resp":{"allow_degradation":false,"conf":[{"name":"TestPostFilter","value":"{}"}],"disable":false}},"priority":0,"methods":["GET","POST","PUT","DELETE"],"status":1},"modifiedIndex":240389,"clean_handlers":"table: 0x7fea5e844f28","has_domain":false,"update_count":0,"orig_modifiedIndex":240389,"key":"\/apisix\/routes\/422552840368554762","createdIndex":240257}, client: 172.17.67.1, server: _, request: "GET /robot-monitor/v1/robotMonitor/test204 HTTP/1.1", host: "192.168.40.174:30880"
2022/08/26 07:10:50 [info] 54#54: *147075 [lua] balancer.lua:194: pick_server(): route: {"value":{"name":"test204","upstream":{"timeout":{"connect":6,"send":6,"read":6},"parent":{"value":"table: 0x7fea60263578","modifiedIndex":240389,"clean_handlers":{},"has_domain":false,"update_count":0,"orig_modifiedIndex":240389,"key":"\/apisix\/routes\/422552840368554762","createdIndex":240257},"pass_host":"pass","nodes":[{"port":8900,"weight":1,"upstream_host":"192.168.2.120:8900","host":"192.168.2.120","priority":0}],"keepalive_pool":{"size":320,"idle_timeout":60,"requests":1000},"nodes_ref":"table: 0x7fea602638f8","type":"roundrobin","hash_on":"vars","scheme":"http","original_nodes":"table: 0x7fea602638f8"},"uri":"\/robot-monitor\/v1\/*","update_time":1661493500,"id":"422552840368554762","create_time":1661390719,"plugins":{"ext-plugin-post-resp":{"allow_degradation":false,"conf":[{"name":"TestPostFilter","value":"{}"}],"disable":false}},"priority":0,"methods":["GET","POST","PUT","DELETE"],"status":1},"modifiedIndex":240389,"clean_handlers":"table: 0x7fea5e844f28","has_domain":false,"update_count":0,"orig_modifiedIndex":240389,"key":"\/apisix\/routes\/422552840368554762","createdIndex":240257}, client: 172.17.67.1, server: _, request: "GET /robot-monitor/v1/robotMonitor/test204 HTTP/1.1", host: "192.168.40.174:30880"
2022/08/26 07:10:50 [info] 54#54: *147075 [lua] balancer.lua:195: pick_server(): ctx: {"debug_headers":{"ext-plugin-post-resp":true},"upstream_conf":{"timeout":{"connect":6,"send":6,"read":6},"parent":{"value":{"name":"test204","upstream":"table: 0x7fea602638b0","uri":"\/robot-monitor\/v1\/*","update_time":1661493500,"id":"422552840368554762","create_time":1661390719,"plugins":{"ext-plugin-post-resp":{"allow_degradation":false,"conf":[{"name":"TestPostFilter","value":"{}"}],"disable":false}},"priority":0,"methods":["GET","POST","PUT","DELETE"],"status":1},"modifiedIndex":240389,"clean_handlers":{},"has_domain":false,"update_count":0,"orig_modifiedIndex":240389,"key":"\/apisix\/routes\/422552840368554762","createdIndex":240257},"pass_host":"pass","nodes":[{"port":8900,"weight":1,"upstream_host":"192.168.2.120:8900","host":"192.168.2.120","priority":0}],"keepalive_pool":{"size":320,"idle_timeout":60,"requests":1000},"nodes_ref":"table: 0x7fea602638f8","type":"roundrobin","hash_on":"vars","scheme":"http","original_nodes":"table: 0x7fea602638f8"},"upstream_version":"240389#table: 0x7fea602638b0","var":{"_cache":{"uri":"\/robot-monitor\/v1\/robotMonitor\/test204","request_uri":"\/robot-monitor\/v1\/robotMonitor\/test204","upstream_scheme":"http","request_method":"GET","real_request_uri":"\/robot-monitor\/v1\/robotMonitor\/test204","host":"192.168.40.174","remote_addr":"172.17.67.1"},"_ctx":{"debug_headers":"table: 0x7fea5aa8e858","upstream_conf":"table: 0x7fea602638b0","upstream_version":"240389#table: 0x7fea602638b0","var":"table: 0x7fea5acdc458","curr_req_matched":{"_method":"GET",":ext":"robotMonitor\/test204","_path":"\/robot-monitor\/v1\/*"},"conf_type":"route","conf_id":"422552840368554762","conf_version":240389,"global_rules":{"values":[{"value":{"update_time":1661485822,"create_time":1656555647,"plugins":{"prometheus":{"disable":true,"prefer_name":true}},"id":"1"},"createdIndex":238812,"key":"\/apisix\/global_rules\/1","modifiedIndex":240387,"clean_handlers":{}}],"prev_index":240400,"sync_times":0,"need_reload":false,"last_err":"timeout","key":"\/apisix\/global_rules","values_hash":{"1":1},"conf_version":1,"automatic":true,"resync_delay":5,"running":true,"etcd_cli":{"timeout":30,"serializer":{"serialize":"function: 0x7fea60de2a08","deserialize":"function: 0x7fea60de29c8"},"ssl_verify":true,"is_auth":false,"ttl":-1,"sema":{"sem":"cdata<struct ngx_http_lua_sema_s *>: 0x7fea602e3028"},"key_prefix":"","last_auth_time":1661496611.936,"endpoints":[{"port":"2379","api_prefix":"\/v3","full_prefix":"http:\/\/192.168.40.197:2379\/v3","host":"192.168.40.197","http_host":"http:\/\/192.168.40.197:2379","address":"192.168.40.197","scheme":"http"},{"port":"2379","api_prefix":"\/v3","full_prefix":"http:\/\/192.168.40.198:2379\/v3","host":"192.168.40.198","http_host":"http:\/\/192.168.40.198:2379","address":"192.168.40.198","scheme":"http"},{"port":"2379","api_prefix":"\/v3","full_prefix":"http:\/\/192.168.40.199:2379\/v3","host":"192.168.40.199","http_host":"http:\/\/192.168.40.199:2379","address":"192.168.40.199","scheme":"http"}],"is_cluster":true},"checker":"function: 0x7fea70be94d0","item_schema":{"type":"object","required":["plugins"],"properties":{"plugins":{"type":"object"},"create_time":"table: 0x7fea60b5cd00","id":{"anyOf":[{"type":"string","maxLength":64,"minLength":1,"pattern":"^[a-zA-Z0-9-_.]+$"},{"type":"integer","minimum":1}]},"update_time":{"type":"integer"}}},"health_check_timeout":10,"last_err_time":1661497842},"matched_route":"table: 0x7fea60278190","matched_upstream":"table: 0x7fea602638b0","plugins":[{"schema":{"type":"object","$comment":"this is a mark for our injected plugin schema","properties":{"allow_degradation":{"type":"boolean","default":false},"conf":{"type":"array","items":{"type":"object","required":["name","value"],"properties":{"name":{"type":"string","maxLength":128,"minLength":1},"value":{"type":"string"}}},"minItems":1},"_meta":{"type":"object","properties":{"error_response":{"oneOf":[{"type":"string"},{"type":"object"}]},"priority":{"description":"priority of plugins by customized order","type":"
2022/08/26 07:10:50 [info] 54#54: *147075 [lua] ext-plugin-post-resp.lua:148: phase_func(): response info, status: 204, client: 172.17.67.1, server: _, request: "GET /robot-monitor/v1/robotMonitor/test204 HTTP/1.1", host: "192.168.40.174:30880"
2022/08/26 07:10:50 [info] 54#54: *147075 [lua] ext-plugin-post-resp.lua:149: phase_func(): response info, headers: {"Date":"Fri, 26 Aug 2022 07:10:50 GMT"}, client: 172.17.67.1, server: _, request: "GET /robot-monitor/v1/robotMonitor/test204 HTTP/1.1", host: "192.168.40.174:30880"
2022/08/26 07:10:50 [info] 54#54: *147075 [lua] init.lua:137: send(): sending rpc type: 4 data length: 112, client: 172.17.67.1, server: _, request: "GET /robot-monitor/v1/robotMonitor/test204 HTTP/1.1", host: "192.168.40.174:30880"
2022/08/26 07:10:50 [warn] 59#59: *189 [lua] init.lua:913: 08/26 07:10:50.074 [epollEventLoopGroup-2-1] INFO  [o.a.a.p.runner.filter.TestPostFilter] -TestPostFilter插件开始执行！
, context: ngx.timer
2022/08/26 07:10:50 [warn] 59#59: *189 [lua] init.lua:913: 08/26 07:10:50.074 [epollEventLoopGroup-2-1] INFO  [o.a.a.p.runner.filter.TestPostFilter] -上游返回的headers:{"Date":"Fri, 26 Aug 2022 07:10:50 GMT"}
, context: ngx.timer
2022/08/26 07:10:50 [warn] 59#59: *189 [lua] init.lua:913: 08/26 07:10:50.074 [epollEventLoopGroup-2-1] INFO  [o.a.a.p.runner.filter.TestPostFilter] -上游返回的状态码为:204
, context: ngx.timer
2022/08/26 07:10:50 [info] 54#54: *147075 [lua] init.lua:188: receive(): receiving rpc type: 4 data length: 20, client: 172.17.67.1, server: _, request: "GET /robot-monitor/v1/robotMonitor/test204 HTTP/1.1", host: "192.168.40.174:30880"
2022/08/26 07:10:50 [info] 54#54: *147075 [lua] init.lua:777: recv resp, code: 0 body: nil len: 0, client: 172.17.67.1, server: _, request: "GET /robot-monitor/v1/robotMonitor/test204 HTTP/1.1", host: "192.168.40.174:30880"
2022/08/26 07:10:50 [info] 54#54: *147075 [lua] ext-plugin-post-resp.lua:157: phase_func(): ext-plugin will send response, client: 172.17.67.1, server: _, request: "GET /robot-monitor/v1/robotMonitor/test204 HTTP/1.1", host: "192.168.40.174:30880"
2022/08/26 07:10:50 [info] 54#54: *147075 [lua] ext-plugin-post-resp.lua:168: phase_func(): ext-plugin send response succefully, client: 172.17.67.1, server: _, request: "GET /robot-monitor/v1/robotMonitor/test204 HTTP/1.1", host: "192.168.40.174:30880"
2022/08/26 07:10:50 [info] 54#54: *147075 [lua] init.lua:558: http_access_phase(): stash ngx ctx: 1, client: 172.17.67.1, server: _, request: "GET /robot-monitor/v1/robotMonitor/test204 HTTP/1.1", host: "192.168.40.174:30880"
2022/08/26 07:10:50 [info] 54#54: *147075 [lua] balancer.lua:378: run(): proxy request to 192.168.2.120:8900 while connecting to upstream, client: 172.17.67.1, server: _, request: "GET /robot-monitor/v1/robotMonitor/test204 HTTP/1.1", host: "192.168.40.174:30880"
2022/08/26 07:10:50 [info] 54#54: *147075 [lua] init.lua:574: fetch_ctx(): fetch ngx ctx: 1 while reading response header from upstream, client: 172.17.67.1, 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/26 07:10:50 [warn] 54#54: *147075 [lua] plugin.lua:384: trace_plugins_info_for_debug(): Apisix-Plugins:  while sending to client, client: 172.17.67.1, 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/26 07:10:50 [warn] 54#54: *147075 [lua] plugin.lua:384: trace_plugins_info_for_debug(): Apisix-Plugins:  while sending to client, client: 172.17.67.1, 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/26 07:10:50 [warn] 54#54: *147075 [lua] plugin.lua:384: trace_plugins_info_for_debug(): Apisix-Plugins:  while logging request, client: 172.17.67.1, 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/26 07:10:50 [info] 54#54: *147075 client 172.17.67.1 closed keepalive connection
2022/08/26 07:10:51 [info] 59#59: *147174 [lua] timers.lua:39: run timer[plugin#server-info], context: ngx.timer
2022/08/26 07:10:52 [info] 59#59: *147290 [lua] timers.lua:39: run timer[plugin#server-info], context: ngx.timer
2022/08/26 07:10:53 [info] 59#59: *147406 [lua] timers.lua:39: run timer[plugin#server-info], context: ngx.timer
172.17.67.1 - - [26/Aug/2022:07:10:50 +0000] 192.168.40.174:30880 "GET /robot-monitor/v1/robotMonitor/test204 HTTP/1.1" 204 0 0.012 "-" "curl/7.29.0" 192.168.2.120:8900 204 0.005 "http://192.168.40.174:30880"
2022/08/26 07:10:54 [info] 59#59: *147521 [lua] timers.lua:39: run timer[plugin#server-info], context: ngx.timer

响应码为200的APISIX处理日志

2022/08/26 07:14:23 [info] 50#50: *172346 [lua] balancer.lua:194: pick_server(): route: {"value":{"name":"test204","upstream":{"timeout":{"connect":6,"send":6,"read":6},"parent":{"value":"table: 0x7fea60263578","modifiedIndex":240389,"clean_handlers":{},"has_domain":false,"update_count":0,"orig_modifiedIndex":240389,"key":"\/apisix\/routes\/422552840368554762","createdIndex":240257},"pass_host":"pass","nodes":[{"port":8900,"weight":1,"upstream_host":"192.168.2.120:8900","host":"192.168.2.120","priority":0}],"keepalive_pool":{"size":320,"idle_timeout":60,"requests":1000},"nodes_ref":"table: 0x7fea602638f8","type":"roundrobin","hash_on":"vars","scheme":"http","original_nodes":"table: 0x7fea602638f8"},"uri":"\/robot-monitor\/v1\/*","update_time":1661493500,"id":"422552840368554762","create_time":1661390719,"plugins":{"ext-plugin-post-resp":{"conf":[{"name":"TestPostFilter","value":"{}"}],"allow_degradation":false,"disable":false}},"priority":0,"methods":["GET","POST","PUT","DELETE"],"status":1},"modifiedIndex":240389,"clean_handlers":"table: 0x7fea6037a870","has_domain":false,"update_count":0,"orig_modifiedIndex":240389,"key":"\/apisix\/routes\/422552840368554762","createdIndex":240257}, client: 172.17.67.1, server: _, request: "GET /robot-monitor/v1/robotMonitor/test200 HTTP/1.1", host: "192.168.40.174:30880"
2022/08/26 07:14:23 [info] 50#50: *172346 [lua] balancer.lua:195: pick_server(): ctx: {"debug_headers":{"ext-plugin-post-resp":true},"upstream_conf":{"timeout":{"connect":6,"send":6,"read":6},"parent":{"value":{"name":"test204","upstream":"table: 0x7fea602638b0","uri":"\/robot-monitor\/v1\/*","update_time":1661493500,"id":"422552840368554762","create_time":1661390719,"plugins":{"ext-plugin-post-resp":{"conf":[{"name":"TestPostFilter","value":"{}"}],"allow_degradation":false,"disable":false}},"priority":0,"methods":["GET","POST","PUT","DELETE"],"status":1},"modifiedIndex":240389,"clean_handlers":{},"has_domain":false,"update_count":0,"orig_modifiedIndex":240389,"key":"\/apisix\/routes\/422552840368554762","createdIndex":240257},"pass_host":"pass","nodes":[{"port":8900,"weight":1,"upstream_host":"192.168.2.120:8900","host":"192.168.2.120","priority":0}],"keepalive_pool":{"size":320,"idle_timeout":60,"requests":1000},"nodes_ref":"table: 0x7fea602638f8","type":"roundrobin","hash_on":"vars","scheme":"http","original_nodes":"table: 0x7fea602638f8"},"upstream_version":"240389#table: 0x7fea602638b0","var":{"_cache":{"uri":"\/robot-monitor\/v1\/robotMonitor\/test200","request_uri":"\/robot-monitor\/v1\/robotMonitor\/test200","upstream_scheme":"http","request_method":"GET","real_request_uri":"\/robot-monitor\/v1\/robotMonitor\/test200","host":"192.168.40.174","remote_addr":"172.17.67.1"},"_ctx":{"debug_headers":"table: 0x7fea5aa010d8","upstream_conf":"table: 0x7fea602638b0","upstream_version":"240389#table: 0x7fea602638b0","var":"table: 0x7fea5aa4a2e0","curr_req_matched":{"_method":"GET",":ext":"robotMonitor\/test200","_path":"\/robot-monitor\/v1\/*"},"conf_type":"route","conf_id":"422552840368554762","conf_version":240389,"global_rules":{"values":[{"value":{"update_time":1661485822,"create_time":1656555647,"plugins":{"prometheus":{"disable":true,"prefer_name":true}},"id":"1"},"createdIndex":238812,"key":"\/apisix\/global_rules\/1","modifiedIndex":240387,"clean_handlers":{}}],"prev_index":240400,"need_reload":false,"sync_times":0,"key":"\/apisix\/global_rules","values_hash":{"1":1},"conf_version":1,"health_check_timeout":10,"resync_delay":5,"running":true,"etcd_cli":{"timeout":30,"serializer":{"serialize":"function: 0x7fea60de2a08","deserialize":"function: 0x7fea60de29c8"},"ssl_verify":true,"is_auth":false,"ttl":-1,"sema":{"sem":"cdata<struct ngx_http_lua_sema_s *>: 0x7fea602e3028"},"key_prefix":"","last_auth_time":1661496611.936,"endpoints":[{"port":"2379","api_prefix":"\/v3","full_prefix":"http:\/\/192.168.40.197:2379\/v3","host":"192.168.40.197","http_host":"http:\/\/192.168.40.197:2379","address":"192.168.40.197","scheme":"http"},{"port":"2379","api_prefix":"\/v3","full_prefix":"http:\/\/192.168.40.198:2379\/v3","host":"192.168.40.198","http_host":"http:\/\/192.168.40.198:2379","address":"192.168.40.198","scheme":"http"},{"port":"2379","api_prefix":"\/v3","full_prefix":"http:\/\/192.168.40.199:2379\/v3","host":"192.168.40.199","http_host":"http:\/\/192.168.40.199:2379","address":"192.168.40.199","scheme":"http"}],"is_cluster":true},"checker":"function: 0x7fea70be94d0","item_schema":{"type":"object","required":["plugins"],"properties":{"plugins":{"type":"object"},"create_time":"table: 0x7fea60b5cd00","id":{"anyOf":[{"type":"string","maxLength":64,"minLength":1,"pattern":"^[a-zA-Z0-9-_.]+$"},{"type":"integer","minimum":1}]},"update_time":{"type":"integer"}}},"last_err_time":1661498022,"automatic":true},"matched_route":"table: 0x7fea60278190","matched_upstream":"table: 0x7fea602638b0","plugins":[{"schema":{"type":"object","$comment":"this is a mark for our injected plugin schema","properties":{"_meta":{"type":"object","properties":{"error_response":{"oneOf":[{"type":"string"},{"type":"object"}]},"priority":{"description":"priority of plugins by customized order","type":"integer"},"filter":{"description":"filter determines whether the plugin needs to be executed at runtime","items":{"type":"array"},"maxItems":20,"type":"array"}}},"allow_degradation":{"type":"boolean","default":false},"conf":{"type":"array","items":{"type":"object
2022/08/26 07:14:23 [info] 50#50: *172346 [lua] ext-plugin-post-resp.lua:148: phase_func(): response info, status: 200, client: 172.17.67.1, server: _, request: "GET /robot-monitor/v1/robotMonitor/test200 HTTP/1.1", host: "192.168.40.174:30880"
2022/08/26 07:14:23 [info] 50#50: *172346 [lua] ext-plugin-post-resp.lua:149: phase_func(): response info, headers: {"Content-Length":"0","Date":"Fri, 26 Aug 2022 07:14:23 GMT","Connection":"keep-alive"}, client: 172.17.67.1, server: _, request: "GET /robot-monitor/v1/robotMonitor/test200 HTTP/1.1", host: "192.168.40.174:30880"
2022/08/26 07:14:23 [info] 50#50: *172346 [lua] init.lua:137: send(): sending rpc type: 4 data length: 204, client: 172.17.67.1, server: _, request: "GET /robot-monitor/v1/robotMonitor/test200 HTTP/1.1", host: "192.168.40.174:30880"
2022/08/26 07:14:23 [warn] 59#59: *189 [lua] init.lua:913: 08/26 07:14:23.202 [epollEventLoopGroup-2-2] INFO  [o.a.a.p.runner.filter.TestPostFilter] -TestPostFilter插件开始执行！
, context: ngx.timer
2022/08/26 07:14:23 [warn] 59#59: *189 [lua] init.lua:913: 08/26 07:14:23.204 [epollEventLoopGroup-2-2] INFO  [o.a.a.p.runner.filter.TestPostFilter] -上游返回的headers:{"Connection":"keep-alive","Content-Length":"0","Date":"Fri, 26 Aug 2022 07:14:23 GMT"}
08/26 07:14:23.204 [epollEventLoopGroup-2-2] INFO  [o.a.a.p.runner.filter.TestPostFilter] -上游返回的状态码为:200
, context: ngx.timer
2022/08/26 07:14:23 [info] 50#50: *172346 [lua] init.lua:188: receive(): receiving rpc type: 4 data length: 20, client: 172.17.67.1, server: _, request: "GET /robot-monitor/v1/robotMonitor/test200 HTTP/1.1", host: "192.168.40.174:30880"
2022/08/26 07:14:23 [info] 50#50: *172346 [lua] init.lua:777: recv resp, code: 0 body: nil len: 0, client: 172.17.67.1, server: _, request: "GET /robot-monitor/v1/robotMonitor/test200 HTTP/1.1", host: "192.168.40.174:30880"
2022/08/26 07:14:23 [info] 50#50: *172346 [lua] ext-plugin-post-resp.lua:157: phase_func(): ext-plugin will send response, client: 172.17.67.1, server: _, request: "GET /robot-monitor/v1/robotMonitor/test200 HTTP/1.1", host: "192.168.40.174:30880"
2022/08/26 07:14:23 [warn] 50#50: *172346 [lua] plugin.lua:384: trace_plugins_info_for_debug(): Apisix-Plugins: , client: 172.17.67.1, server: _, request: "GET /robot-monitor/v1/robotMonitor/test200 HTTP/1.1", host: "192.168.40.174:30880"
2022/08/26 07:14:23 [warn] 50#50: *172346 [lua] plugin.lua:384: trace_plugins_info_for_debug(): Apisix-Plugins: , client: 172.17.67.1, server: _, request: "GET /robot-monitor/v1/robotMonitor/test200 HTTP/1.1", host: "192.168.40.174:30880"
2022/08/26 07:14:23 [info] 50#50: *172346 [lua] ext-plugin-post-resp.lua:168: phase_func(): ext-plugin send response succefully, client: 172.17.67.1, server: _, request: "GET /robot-monitor/v1/robotMonitor/test200 HTTP/1.1", host: "192.168.40.174:30880"
2022/08/26 07:14:23 [info] 50#50: *172346 [lua] init.lua:558: http_access_phase(): stash ngx ctx: 1, client: 172.17.67.1, server: _, request: "GET /robot-monitor/v1/robotMonitor/test200 HTTP/1.1", host: "192.168.40.174:30880"
2022/08/26 07:14:23 [warn] 50#50: *172346 [lua] plugin.lua:384: trace_plugins_info_for_debug(): Apisix-Plugins: , client: 172.17.67.1, server: _, request: "GET /robot-monitor/v1/robotMonitor/test200 HTTP/1.1", host: "192.168.40.174:30880"
2022/08/26 07:14:23 [warn] 50#50: *172346 [lua] plugin.lua:384: trace_plugins_info_for_debug(): Apisix-Plugins: , client: 172.17.67.1, server: _, request: "GET /robot-monitor/v1/robotMonitor/test200 HTTP/1.1", host: "192.168.40.174:30880"
2022/08/26 07:14:23 [info] 50#50: *172346 [lua] init.lua:574: fetch_ctx(): fetch ngx ctx: 1 while logging request, client: 172.17.67.1, server: _, request: "GET /robot-monitor/v1/robotMonitor/test200 HTTP/1.1", host: "192.168.40.174:30880"
2022/08/26 07:14:23 [warn] 50#50: *172346 [lua] plugin.lua:384: trace_plugins_info_for_debug(): Apisix-Plugins:  while logging request, client: 172.17.67.1, server: _, request: "GET /robot-monitor/v1/robotMonitor/test200 HTTP/1.1", host: "192.168.40.174:30880"
2022/08/26 07:14:23 [info] 50#50: *172346 client 172.17.67.1 closed keepalive connection
2022/08/26 07:14:24 [info] 59#59: *172427 [lua] timers.lua:39: run timer[plugin#server-info], context: ngx.timer
2022/08/26 07:14:25 [info] 59#59: *172543 [lua] timers.lua:39: run timer[plugin#server-info], context: ngx.timer
2022/08/26 07:14:26 [info] 59#59: *172659 [lua] timers.lua:39: run timer[plugin#server-info], context: ngx.timer
172.17.67.1 - - [26/Aug/2022:07:14:23 +0000] 192.168.40.174:30880 "GET /robot-monitor/v1/robotMonitor/test200 HTTP/1.1" 200 5 0.011 "-" "curl/7.29.0" - - - "http://192.168.40.174:30880"
tzssangglass commented 2 years ago

The only difference I found is that when upstream returns 204, there is no "Connection": "keep-alive" in the upstream headers.

So I started a Spring Boot project that returns 204 the way you did, and it looks like this:

curl http://127.0.0.1:8080/test204 -i
HTTP/1.1 204
Date: Sat, 27 Aug 2022 11:48:53 GMT

I used test204 as an upstream but still could not reproduce it.

tzssangglass commented 2 years ago

the logs of upstream（Got it twice）

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

It seems you think the logs here are the only proof that APISIX sent two requests to the Java Plugin Runner?

Are there any other direct logs that prove APISIX sent two requests to the Java Plugin Runner?

beginnerWJC commented 2 years ago

不是APISIX向Java Plugin Runner 发送了两个请求，是开启了APISIX的ext-plugin-post-resp插件然后使用Java Plugin Runner的postFilter方法用于改写上游返回的请求头时，发现在这种情况下，如果上游返回的状态码是204的话，上游会收到两次请求，如果将上游返回的状态码改为200则正常了，或者不使用APISIX的ext-plugin-post-resp插件，也都是正常的。

tzssangglass commented 2 years ago

Unfortunately, I was unable to reproduce this problem after several tries.

You can debug it yourself here: https://github.com/apache/apisix/blob/master/apisix/plugins/ext-plugin-post-resp.lua#L139-L146

This is where the ext-plugin-post-resp plugin sends data upstream.

beginnerWJC commented 2 years ago

我还发现了个问题，我想在插件里面将返回值改成200规避这个问题，然后发现无法修改响应码 插件代码：

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);
        if(statusCode == 204) {
            logger.info("修改上游的状态码为200");
            response.setStatusCode(200);
        }
        response.setHeader("apisix", "TestPostFilter");
        chain.postFilter(request, response);
    }

日志打印

2022/08/30 01:36:25 [warn] 58#58: *194 [lua] init.lua:913: 08/30 01:36:25.794 [epollEventLoopGroup-2-2] INFO  [o.a.a.p.runner.filter.TestPostFilter] -TestPostFilter插件开始执行！
, context: ngx.timer
2022/08/30 01:36:25 [warn] 58#58: *194 [lua] init.lua:913: 08/30 01:36:25.794 [epollEventLoopGroup-2-2] INFO  [o.a.a.p.runner.filter.TestPostFilter] -上游返回的headers:{"Date":"Tue, 30 Aug 2022 01:36:25 GMT"}
, context: ngx.timer
2022/08/30 01:36:25 [warn] 58#58: *194 [lua] init.lua:913: 08/30 01:36:25.795 [epollEventLoopGroup-2-2] INFO  [o.a.a.p.runner.filter.TestPostFilter] -上游返回的状态码为:204
, context: ngx.timer
2022/08/30 01:36:25 [warn] 58#58: *194 [lua] init.lua:913: 08/30 01:36:25.795 [epollEventLoopGroup-2-2] INFO  [o.a.a.p.runner.filter.TestPostFilter] -修改上游的状态码为200
, context: ngx.timer
172.17.67.1 - - [30/Aug/2022:01:36:25 +0000] 192.168.40.174:30880 "GET /robot-monitor/v1/robotMonitor/test204 HTTP/1.1" 204 0 0.205 "-" "PostmanRuntime/7.28.4" 192.168.2.120:8900 204 0.007 "http://192.168.40.174:30880"

postman: image 还是204，没有改写成功 但是header头加上了

tzssangglass commented 2 years ago

just remove if(statusCode == 204) and use response.setStatusCode(200); directly?

beginnerWJC commented 2 years ago

如果statusCode为204，则改写成200。日志里面显示走到if语句里面了，但是没有替换成功

tzssangglass commented 2 years ago

我还发现了个问题，我想在插件里面将返回值改成200规避这个问题，然后发现无法修改响应码

you can submit another issue to describe this issue, one issue trace one problem.

tzssangglass commented 2 years ago

如果statusCode为204，则改写成200。日志里面显示走到if语句里面了，但是没有替换成功

I just verified that changing from 200 to 400 works.