bug: API disabled in the context of body_filter_by_lua*

Guohao1020 commented 1 year ago

Current Behavior

When the java plug-in ext-plugin-post-resp is used, API disabled occurs when the response body is large. in the context of body_filter_by_lua*, however, there is no problem on the local computer. Deploy the program to the server and it will appear. Error message:

lua entry thread aborted: runtime error: /usr/local/apisix/apisix/plugins/ext-plugin-post-resp.lua:109: API disabled in the context of body_filter_by_lua*
stack traceback:
coroutine 0:
[C]: in function 'ngx_print'
/usr/local/apisix/apisix/plugins/ext-plugin-post-resp.lua:109: in function 'send_chunk'
/usr/local/apisix/apisix/plugins/ext-plugin-post-resp.lua:132: in function 'send_response'
/usr/local/apisix/apisix/plugins/ext-plugin-post-resp.lua:171: in function 'phase_func'
/usr/local/apisix/apisix/plugin.lua:1097: in function 'common_phase'
/usr/local/apisix/apisix/init.lua:507: in function 'handle_upstream'
/usr/local/apisix/apisix/init.lua:669: in function 'http_access_phase'
access_by_lua(nginx.conf:334):2: in main chunk, client: 11.18.1.47, server: _, request: "POST /1122/o8k8yu/jrsoap/soa/TradeInfoService HTTP/1.1"

Plug-in code:

package cn.devops.plugin.filter;

import cn.devops.plugin.constant.CacheNameTimeConstant;
import cn.devops.plugin.constant.GatewayConstants;
import cn.hutool.core.util.ObjectUtil;
import cn.hutool.core.util.StrUtil;
import lombok.extern.slf4j.Slf4j;
import org.apache.apisix.plugin.runner.HttpRequest;
import org.apache.apisix.plugin.runner.HttpResponse;
import org.apache.apisix.plugin.runner.PostRequest;
import org.apache.apisix.plugin.runner.PostResponse;
import org.apache.apisix.plugin.runner.filter.PluginFilterChain;
import org.springframework.cache.Cache;
import org.springframework.cache.CacheManager;
import org.springframework.data.redis.core.RedisTemplate;
import org.w3c.dom.Document;
import org.w3c.dom.Element;
import org.w3c.dom.NodeList;
import org.xml.sax.InputSource;

import javax.annotation.Resource;
import javax.xml.parsers.DocumentBuilder;
import javax.xml.parsers.DocumentBuilderFactory;
import java.io.StringReader;
import java.net.URL;
import java.util.ArrayList;
import java.util.List;
import java.util.concurrent.TimeUnit;

@Slf4j
public class WebServiceResponseRewritePluginFilter extends BaseGatewayPluginFilter {

    @Resource
    private CacheManager cacheManager;
    @Resource(name = "gatewayRedisTemplate")
    private RedisTemplate<String, Object> gatewayRedisTemplate;

    @Override
    public String name() {
        return "web-service-response-rewrite";
    }

    @Override
    public void filter(HttpRequest request, HttpResponse response, PluginFilterChain chain) {
        String host = request.getHeader("host");
        String requestId = request.getVars("request_id");
        gatewayRedisTemplate.opsForValue().set(GatewayConstants.getGatewayRequestHostKey(requestId),
                host, 30, TimeUnit.MINUTES);
        Cache cache = cacheManager.getCache(CacheNameTimeConstant.CACHE_REQUEST_HOST);
        if (ObjectUtil.isNotNull(cache)) {
            cache.put(requestId, host);
        }
        chain.filter(request, response);
    }

    @Override
    public void postFilter(PostRequest request, PostResponse response, PluginFilterChain chain) {

        String requestId = request.getVars("request_id");
        boolean isWsdlXml = false;

        String requestUri = request.getVars("request_uri");

        if (StrUtil.contains(requestUri, "wsdl")) {
            isWsdlXml = true;
        }

        if (!isWsdlXml) {
            chain.postFilter(request, response);
            return;
        }

        String host = null;
        Cache cache = cacheManager.getCache(CacheNameTimeConstant.CACHE_REQUEST_HOST);
        if (ObjectUtil.isNotNull(cache)) {
            host = cache.get(requestId, String.class);
        }
        if (StrUtil.isBlank(host)) {
            host = (String) gatewayRedisTemplate.opsForValue()
                    .get(GatewayConstants.getGatewayRequestHostKey(requestId));
        }
        if (StrUtil.isBlank(host)) {
            chain.postFilter(request, response);
            return;
        }

        String newLocation = StrUtil.subBefore(requestUri, "?", false);

        try {
            DocumentBuilderFactory dbFactory = DocumentBuilderFactory.newInstance();
            DocumentBuilder dBuilder = dbFactory.newDocumentBuilder();
            InputSource inputSource = new InputSource(new StringReader(request.getBody()));
            Document doc = dBuilder.parse(inputSource);

            NodeList soapAddressList = doc.getElementsByTagName("soap:address");
            if (soapAddressList.getLength() > 0) {
                for (int i = 0; i < soapAddressList.getLength(); i++) {
                    Element soapAddressElement = (Element) soapAddressList.item(i);
                    String location = soapAddressElement.getAttribute("location");
                    URL url = new URL(location);
                    soapAddressElement.setAttribute("location",
                            url.getProtocol() + "://" + host + newLocation);
                }
            } else {
                chain.postFilter(request, response);
                return;
            }

            javax.xml.transform.TransformerFactory transformerFactory = javax.xml.transform.TransformerFactory.newInstance();
            javax.xml.transform.Transformer transformer = transformerFactory.newTransformer();
            javax.xml.transform.dom.DOMSource source = new javax.xml.transform.dom.DOMSource(doc);
            java.io.StringWriter writer = new java.io.StringWriter();
            javax.xml.transform.stream.StreamResult result = new javax.xml.transform.stream.StreamResult(writer);
            transformer.transform(source, result);

            String updatedXml = writer.toString();
            response.setBody(updatedXml);

        } catch (Exception e) {
            log.error(e.getMessage(), e);
        }
        response.setHeader("Content-Type", "text/xml;charset=UTF-8");
        chain.postFilter(request, response);
    }

    @Override
    public List<String> requiredVars() {
        List<String> vars = new ArrayList<>();
        vars.add("remote_addr");
        vars.add("server_port");
        vars.add("request_id");
        vars.add("request_uri");
        vars.add("request_method");
        vars.add("request_length");
        vars.add("status");
        return vars;
    }

    @Override
    public Boolean requiredBody() {
        return true;
    }

    @Override
    public Boolean requiredRespBody() {
        return true;
    }

}

Expected Behavior

The upstream request response body was returned, but after using the plug-in, the request response body was truncated, and I suspect this error caused the data transfer to be interrupted

Error Logs

2023/08/22 10:34:27 [error] 65#65: *34548 lua entry thread aborted: runtime error: /usr/local/apisix/apisix/plugins/ext-plugin-post-resp.lua:109: API disabled in the context of body_filter_by_lua*

stack traceback:

coroutine 0:

[C]: in function 'ngx_print'

/usr/local/apisix/apisix/plugins/ext-plugin-post-resp.lua:109: in function 'send_chunk'

/usr/local/apisix/apisix/plugins/ext-plugin-post-resp.lua:132: in function 'send_response'

/usr/local/apisix/apisix/plugins/ext-plugin-post-resp.lua:171: in function 'phase_func'

/usr/local/apisix/apisix/plugin.lua:1097: in function 'common_phase'

/usr/local/apisix/apisix/init.lua:507: in function 'handle_upstream'

/usr/local/apisix/apisix/init.lua:669: in function 'http_access_phase'

access_by_lua(nginx.conf:334):2: in main chunk, client: 11.18.1.47, server: _, request: "POST /1122/o8k8yu/jrsoap/soa/TradeInfoService HTTP/1.1", host: "xx.xxx.xx.xxx:10003"

11.18.1.47 - - [22/Aug/2023:10:34:27 +0800] xx.xxx.xx.xxx:10003 "POST /1122/o8k8yu/jrsoap/soa/TradeInfoService HTTP/1.1" 200 166436 0.757 "-" "PostmanRuntime-ApipostRuntime/1.1.0" - - - "http://xx.xxx.xx.xxx:10003/jrsoap/soa/TradeInfoService"

Steps to Reproduce

Create a running apisix image based on the official apisix image, and add the java plug-in jar package to the image.
Run the apisix docker image.
Configure routes and add the java ext-plugin-post-resp plugin.
Call the interface, simulate the request needs to return a relatively large packet, about about 1m.
The response is truncated, and the apisix log output an error log.

Environment

APISIX version (run apisix version): 3.3.0
Operating system (run uname -a): Linux apisix-v1-765cb69475-8s4xq 3.10.0-1160.el7.x86_64 #1 SMP Mon Oct 19 16:18:59 UTC 2020 x86_64 GNU/Linux
OpenResty / Nginx version (run openresty -V or nginx -V): openresty/1.21.4.1
etcd version, if relevant (run curl http://127.0.0.1:9090/v1/server_info): {"hostname":"apisix-v1-765cb69475-8s4xq","version":"3.3.0","etcd_version":"3.5.0","id":"cb46e64f-3cf9-47ad-819c-42183c9593e3","boot_time":1692671574}
APISIX Dashboard version, if relevant: 3.0.1
Plugin runner version, for issues related to plugin runners: 0.4.0 for java
LuaRocks version, for installation issues (run luarocks --version):

Guohao1020 commented 1 year ago

After the log debugging is enabled, you can see that all packets are printed. However, after [id: 0x0c308141] READ COMPLETE, an error occurs with ext-plugin-post-resp.lua:109.

If it is a small request response body does not have this problem.

2023/08/22 11:32:01 [warn] 103#103: *240 [lua] init.lua:953: 6e 6f 74 69 63 65 4e 6f 64 65 5c 22 3a 5c |\"noticeNode\":\|

|0000baa0| 22 52 45 53 55 4c 54 5f 4e 4f 54 49 43 45 5c 22 |"RESULT_NOTICE\"|

|0000bab0| 2c 5c 22 50 4c 41 54 49 44 5c 22 3a 6e 75 6c 6c |,\"PLATID\":null|

|0000bac0| 7d 5d 22 7d 3c 2f 72 65 73 75 6c 74 3e 3c 2f 6e |}]"}</result></n|

|, context: ngx.timer

2023/08/22 11:32:01 [warn] 103#103: *240 [lua] init.lua:953: 0000bad0| 73 32 3a 51 75 65 72 79 5f 4e 6f 74 69 63 65 52 |s2:Query_NoticeR|

|0000bae0| 65 73 70 6f 6e 73 65 3e 3c 2f 73 6f 61 70 3a 42 |esponse></soap:B|

|0000baf0| 6f 64 79 3e 3c 2f 73 6f 61 70 3a 45 6e 76 65 6c |ody></soap:Envel|

|0000bb00| 6f 70 65 3e |ope> |

+--------+-------------------------------------------------+----------------+

, context: ngx.timer

2023/08/22 11:32:02 [warn] 103#103: *240 [lua] init.lua:953: 2023-08-22 03:32:02.042 DEBUG 228 --- [tLoopGroup-10-2] i.n.h.l.LoggingHandler : [id: 0x0c308141] WRITE: 24B

+-------------------------------------------------+

| 0 1 2 3 4 5 6 7 8 9 a b c d e f |

+--------+-------------------------------------------------+----------------+

|00000000| 04 00 00 14 0c 00 00 00 00 00 06 00 08 00 04 00 |................|

|00000010| 06 00 00 00 02 00 00 01 |........ |

+--------+-------------------------------------------------+----------------+

, context: ngx.timer

2023/08/22 11:32:02 [warn] 103#103: *240 [lua] init.lua:953: 2023-08-22 03:32:02.042 DEBUG 228 --- [tLoopGroup-10-2] i.n.h.l.LoggingHandler : [id: 0x0c308141] FLUSH

, context: ngx.timer

2023/08/22 11:32:02 [warn] 103#103: *240 [lua] init.lua:953: 2023-08-22 03:32:02.043 DEBUG 228 --- [tLoopGroup-10-2] i.n.h.l.LoggingHandler : [id: 0x0c308141] READ COMPLETE

, context: ngx.timer

2023/08/22 11:32:02 [error] 50#50: *51520 lua entry thread aborted: runtime error: /usr/local/apisix/apisix/plugins/ext-plugin-post-resp.lua:109: API disabled in the context of body_filter_by_lua*

stack traceback:

coroutine 0:

[C]: in function 'ngx_print'

/usr/local/apisix/apisix/plugins/ext-plugin-post-resp.lua:109: in function 'send_chunk'

/usr/local/apisix/apisix/plugins/ext-plugin-post-resp.lua:132: in function 'send_response'

/usr/local/apisix/apisix/plugins/ext-plugin-post-resp.lua:171: in function 'phase_func'

/usr/local/apisix/apisix/plugin.lua:1097: in function 'common_phase'

/usr/local/apisix/apisix/init.lua:507: in function 'handle_upstream'

/usr/local/apisix/apisix/init.lua:669: in function 'http_access_phase'

access_by_lua(nginx.conf:334):2: in main chunk

Guohao1020 commented 1 year ago

Now that we have solved this problem, we have added response.setbody (request.getbody ()) to the first line of the postFiltermethod block, and there is no problem of the request response body being truncated.

But I don't understand why the response body of the request is normal when the packet is small.

现在已经解决这个问题，在postFilter 方法块第一行加入代码response.setBody(request.getBody())，没有出现请求响应体被截断的问题。但是我不明白，为什么在数据包小的时候，请求的响应体的正常的。

yuluo-yx commented 1 year ago

I guess it may be related to the request size limit of nginx, that is, the configuration of the client_body_buffer_size parameter. Further details need to be confirmed by debug analysis.

Revolyssup commented 1 year ago

I am still wondering about the error as to how did the ngx.print function got called in body_filter_by_lua phase when it's parent function is clearly called in access phase.

Revolyssup commented 1 year ago

Another reported issue: an error is triggered when the response body (a JSON string) is up to 100K bytes.

xiaolajiyhy commented 1 year ago

请问有临时的解决办法吗

Revolyssup commented 1 year ago

packet is small.

@xiaolajiyhy For now you can see if this solution works for you https://github.com/apache/apisix/issues/10069#issuecomment-1687405686

Revolyssup commented 1 year ago

send_chunk

@Guohao1020 This solution just overrides the original upstream response with request body. Was that your intended use case? So basically you solved the issue by changing the upstream response?

zhl11b commented 11 months ago

golang has same problem

Guohao1020 commented 11 months ago

In the Java plug-in, request.getbody () is not the request body, but the upstream response body. If the ext-plugin-post-resp plug-in is enabled, the plug-in must explicitly call the response.setbody (request.getbody ()) method. Even if the plug-in callback method does nothing, it must call the response.setbody (request.getbody ()) method. Of course, if not set, the plug-in will also return an upstream response to the Apisix gateway, but the request response body will be truncated. My solution is that the request response body of the plug-in must be set when the plug-in does not do anything. If the method is not manually overridden, the request response body is truncated.

@Revolyssup

apache / apisix