cxf client在后台不通且chunk设置为false的时候不能在控制台输出请求日志

Posted 2020-07-09

场景：

服务编排框架支持编排webservice服务。call webservice的client是基于cxf做的。为了使用服务编排的开发者调试与定位问题方便，需要将webservice的请求与响应报文打出来。

这个诉求不是很复杂加上LoggingInInterceptor(打印响应报文)与LoggingOutInterceptor(打印请求报文)两个拦截器即可。

好，开始考虑异常场景，当提供webservice的服务后台不通时，理论上也是应该可以打出请求报文的，但是在对cxf的client的httpClientPolicy的chunk设置成false之后，请求的报文就不会被打出了。

 

分析：

分析源码后发现cxf依赖大量的拦截器，可以说对拦截器这个pattern用的还是比较深入的：

1. 拦截的phase有很多

2.触发拦截后还可以注册回调

3.拦截器形成自己的chain

4.触发拦截器执行过程中还可以动态增加拦截器

 

触发拦截器调用逻辑的代码在

org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(Message)

的255行： currentInterceptor.handleMessage(message);

通过调用堆栈不难发现，触发输出日志动作是在执行org.apache.cxf.inte[email protected]17d602ac这个拦截器时。

可以猜测在chunk设置成false是没有成功执行到这个拦截器的。

好，对比两种场景下执行的拦截器的情况

----------------------------------------------

在chunk未关闭的时候：

[email protected]
    [email protected]
    [email protected]eeb41
    org.apa[email protected]3b8d3ecd
    org.ap[email protected]50f36fcb
    [email protected]
    [email protected]
    [email protected]
    [email protected]
    [email protected]8d5
    [email protected]
    [email protected]
    org.apache.cxf.bindi[email protected]54babeeb
    org.apache.cxf.interceptor.S[email protected]
    org.apache.cxf.inte[email protected]17d602ac

===========================

在chunk设置成false关闭时：

[email protected]
    [email protected]
    [email protected]493c7
    org.apa[email protected]2c661664
    org.ap[email protected]6e1c8760
    [email protected]
    [email protected]
    [email protected]
    [email protected]
    [email protected]1fe

----------------------------------------------

 

果然很清晰的发现在org.apache.cxf.binding.soap.interceptor.SoapOutInterceptor执行时出现了异常，使得拦截器执行不下去了，日志如下，显而易见，服务不通：

exception, unwinding now
org.apache.cxf.binding.soap.SoapFault: Error writing to XMLStreamWriter.
    at org.apache.cxf.binding.soap.interceptor.SoapOutInterceptor.writeSoapEnvelopeStart(SoapOutInterceptor.java:175)
    at org.apache.cxf.binding.soap.interceptor.SoapOutInterceptor.handleMessage(SoapOutInterceptor.java:81)
    at org.apache.cxf.binding.soap.interceptor.SoapOutInterceptor.handleMessage(SoapOutInterceptor.java:61)
    at org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:255)
    at org.apache.cxf.endpoint.ClientImpl.invoke(ClientImpl.java:544)
    at org.apache.cxf.endpoint.ClientImpl.invoke(ClientImpl.java:341)
    at org.apache.cxf.endpoint.ClientImpl.invoke(ClientImpl.java:294)
    at org.apache.cxf.frontend.ClientProxy.invokeSync(ClientProxy.java:73)
    at org.apache.cxf.jaxws.JaxWsClientProxy.invoke(JaxWsClientProxy.java:124)
    at com.sun.proxy.$Proxy26.queryUser(Unknown Source)
    at org.simonme.demo.cxf.client.user.UserService_UserServicePort_Client.main(UserService_UserServicePort_Client.java:77)
Caused by: javax.xml.stream.XMLStreamException: java.net.ConnectException: Connection refused: connect
    at com.sun.xml.internal.stream.writers.XMLStreamWriterImpl.writeStartElement(XMLStreamWriterImpl.java:1344)
    at org.apache.cxf.binding.soap.interceptor.SoapOutInterceptor.writeSoapEnvelopeStart(SoapOutInterceptor.java:122)
    ... 10 more
Caused by: java.net.ConnectException: Connection refused: connect
    at java.net.DualStackPlainSocketImpl.waitForConnect(Native Method)
    at java.net.DualStackPlainSocketImpl.socketConnect(DualStackPlainSocketImpl.java:85)
    at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:339)
    at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:200)
    at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:182)
    at java.net.PlainSocketImpl.connect(PlainSocketImpl.java:172)
    at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
    at java.net.Socket.connect(Socket.java:579)

 

org.apache.cxf.io.AbstractThresholdOutputStream.write(int)
    

@Override
    public void write(int b) throws IOException {
        if (buffer != null) {
            buffer.write(b);
            if (buffer.size() >= threshold) {
                thresholdReached();
                unBuffer();
            }
            return;
        }
        super.write(b);
    }

   
    threshold 在chunk设置成false时 为0 ，不设置时(默认true) 为4096

当设置成0时，一定会触发unBuffer逻辑，这个逻辑会去请求后台，此时后台又不通 那么就出现了异常。具体可以看上面日志的异常栈。
   
    如何设置的4096
    看org.apache.cxf.transports.http.configuration.HTTPClientPolicy.getChunkingThreshold()
   
threshold 如何设置的0
       

if (csPolicy.isAllowChunking() 
            && isChunkingSupported(message, connection.getRequestMethod())) {
            //TODO: The chunking mode be configured or at least some
            // documented client constant.
            //use -1 and allow the URL connection to pick a default value
            isChunking = true;
            chunkThreshold = csPolicy.getChunkingThreshold();
            if (chunkThreshold <= 0) {
                chunkThreshold = 0;
                connection.setChunkedStreamingMode(-1);                    
            }
        }

        org.apache.cxf.transport.http.HTTPConduit.prepare(Message)
        方法中chunkThreshold初始值为0  因为isAllowChunking为false 所以上面逻辑不会进入，所以chunkThreshold依然为0
       
        为什么设置启用chunk，就要设置成4096？
        you’ll be receiving in some arbitrary chunk size, (4096 or 8192 is frequently a good match for network buffer sizes)
       
        还有些类库 默认是2048的
        The default chunk size in Apache HttpClient 4.3 is set to 2048 bytes.

如何解决这个问题，可以考虑修改(重写)这个拦截器的触发时机等。