[CXF-7712] LoggingInInterceptor

• Type: Bug
• Status: Closed
• Priority: Major
• Resolution: Later
• Affects Version/s: 3.1.1, 3.1.15
• Component/s: JAX-WS Runtime
• Estimated Complexity: Unknown
• Assignee: Unassigned
• Reporter: Muni
• Created: 17/Apr/18 20:55
• Updated: 20/Apr/18 16:06
• Resolved: 20/Apr/18 16:06

Description

I am not  a pro working with CXF, but I can confidently say that there is some help required.

Issue:

After we migrated to CXF3.1.0 from 2.7.4 (along with Java8), we started observing that the payload response entity is not being read correctly and sent back calling service. Instead it's being sent back as java.io.SequenceInputStream (in case of errors >= 400) as per code exist in ClientProxyImpl.java CXF class.

In case of success responses we have specific check exists (i.e., checkresponse() method for errors status >= 400) and if it is < 400, we get thru the readBody() method and read the response entity contents to send back the response. But in case of response codes >= 400, we don't have any associated response entity reading in current CXF 3.1.0 code to pick the payload correctly (this is happening because we now have LoggingInInterceptor->logInputSream() method doing bis=new SequenceInputStream(.....), which now have an object structure on Java8.

In older versions we had bis=new InputStream(bos) in LoggingInInterceptor, when calling writingPayLoad(), so it was straightforward to get the response payload from ResponseImpl object contents (ref to my screenshots).

The reason I request someone to help on this, because we process the detailed error message we get in case of 400 responses.

 

Logs:

2018-04-16 09:34:33,697 DEBUG [tomcat-http--6] {} org.springframework.integration.channel.DirectChannel - preSend on channel 'authorizeUserResponseRouter', message: GenericMessage [payload=java.io.SequenceInputStream@2dd8abaf, headers=

{responseRootElement=authorizeUsersResponse, replyChannel=org.springframework.messaging.core.GenericMessagingTemplate$TemporaryReplyChannel@7f2b737a, errorChannel=org.springframework.messaging.core.GenericMessagingTemplate$TemporaryReplyChannel@7f2b737a, id=dd33d939-0daa-0bc6-c578-d34aece33c4a, MESSAGE_INFORMATION_HOLDER=javax.xml.ws.Holder@68c33562, timestamp=1523889273697}

]
-------------------------------------
ID: 5
Response-Code: 400
Encoding: ISO-8859-1
Content-Type: application/xml
Headers:

{connection=[close], content-type=[application/xml], Date=[Mon, 16 Apr 2018 14:34:33 GMT], exception=[User not eligible], Server=[Apache-Coyote/1.1], transfer-encoding=[chunked], x-security-app-name=[clientapp-rest:1.0.41-1599], x-security-correlation-id=[cccc4e4e-f7f3-4ba4-9b72-4d32538ecf02], x-security-host=[server001], x-security-msg-id=[bacb9976-ac58-4546-9379-1332e2530d00], x-security-msg-version=[1], x-security-response-code=[200], x-security-service-version=[1.0.41-1599], x-security-timestamp=[XXXXXXXXX3652]}

Payload: <?xml version="1.0" encoding="UTF-8" standalone="yes"?><ErrorResponse xmlns="namespacev1"><title>Bad Request</title><code>422</code><message>User not eligible</message></ErrorResponse>
--------------------------------------
2018-04-16 09:34:33,662 DEBUG [tomcat-http--6] {} org.apache.cxf.phase.PhaseInterceptorChain - Invoking handleMessage on interceptor myapp.client.security.client.penta.HttpHeaderInInterceptor@696f1a06
2018-04-16 09:34:33,666 DEBUG [tomcat-http--6] {} org.apache.cxf.phase.PhaseInterceptorChain - Invoking handleMessage on interceptor org.apache.cxf.jaxrs.client.spec.ClientResponseFilterInterceptor@452f892b
2018-04-16 09:34:33,681 DEBUG [tomcat-http--6] {} org.apache.cxf.phase.PhaseInterceptorChain - Adding interceptor org.apache.cxf.ws.policy.ClientPolicyInFaultInterceptor@3201c39f to phase receive
2018-04-16 09:34:33,681 DEBUG [tomcat-http--6] {} org.apache.cxf.phase.PhaseInterceptorChain - Adding interceptor org.apache.cxf.ws.policy.PolicyVerificationInFaultInterceptor@925feb4 to phase pre-invoke
2018-04-16 09:34:33,681 DEBUG [tomcat-http--6] {} org.apache.cxf.phase.PhaseInterceptorChain - Adding interceptor org.apache.cxf.interceptor.LoggingInInterceptor@f56e35b to phase receive
2018-04-16 09:34:33,681 DEBUG [tomcat-http--6] {} org.apache.cxf.phase.PhaseInterceptorChain - Adding interceptor org.apache.cxf.interceptor.ClientFaultConverter@38b4d45b to phase unmarshal
2018-04-16 09:34:33,681 DEBUG [tomcat-http--6] {} org.apache.cxf.phase.PhaseInterceptorChain - Chain org.apache.cxf.phase.PhaseInterceptorChain@1cba32cd was created. Current flow:
receive [ClientPolicyInFaultInterceptor, LoggingInInterceptor]
unmarshal [ClientFaultConverter]
pre-invoke [PolicyVerificationInFaultInterceptor]

2018-04-16 09:34:33,681 DEBUG [tomcat-http--6] {} org.apache.cxf.phase.PhaseInterceptorChain - Invoking handleMessage on interceptor org.apache.cxf.ws.policy.ClientPolicyInFaultInterceptor@3201c39f
2018-04-16 09:34:33,682 DEBUG [tomcat-http--6] {} org.apache.cxf.ws.policy.ClientPolicyInFaultInterceptor - conduit: conduit: class org.apache.cxf.transport.http.URLConnectionHTTPConduit538646526target: https://server001.myapp.com/v1/AuthorizationService/entitlements/authorizations
2018-04-16 09:34:33,682 DEBUG [tomcat-http--6] {} org.apache.cxf.ws.policy.ClientPolicyInFaultInterceptor - ep: org.apache.cxf.ws.policy.EndpointPolicyImpl@6ed8d17
2018-04-16 09:34:33,682 DEBUG [tomcat-http--6] {} org.apache.cxf.ws.policy.ClientPolicyInFaultInterceptor - faultInterceptors: []
2018-04-16 09:34:33,682 DEBUG [tomcat-http--6] {} org.apache.cxf.phase.PhaseInterceptorChain - Invoking handleMessage on interceptor org.apache.cxf.interceptor.LoggingInInterceptor@f56e35b
2018-04-16 09:34:33,682 INFO [tomcat-http--6] {} org.apache.cxf.interceptor.LoggingInInterceptor - Inbound Message
----------------------------
ID: 5
Address: https://server001.myapp.com/v1/AuthorizationService/entitlements/authorizations
Http-Method: POST
Content-Type: application/xml
Headers:

{Accept=[application/xml], Context-Type=[application/xml], Content-Type=[application/xml], x-security-header-signature=[QliBhrMwTdlczMysN/OEBFDUXHZgvGzl9VvvK4OOaloEtmMVxSbRcNAx1mydZJ4kT0/sFUh/dkZlbtzLRLaPLgPvuSAy7Kve0fnwYMdW4ad86l3KwUbH46nLJi3GCKm0anT+tmb68HXXqLRw4Ph6sy4Lcwgvo5OY+7u36X0dckw=], x-security-msg-version=[1], x-security-host=[SY4-67HSN22], x-security-msg-id=[bacb9976-ac58-4546-9379-1332e2530d00], x-security-app-name=[ebs-non-revenue-gateway:3.2.4-SNAPSHOT-SNAPSHOT], x-security-payload-signature=[MPubxRTbdTzdRUu96hKMyc+uHVUHMxHRQBWXkXcj6jXkbqae0m23IgaF6VanzHYd4HpV4n/WyhqbVnnTBW/Eo+b6GhGbTdtjl0+r9gNoofjCgZMUQkj6Wj3kE3fyfsYAyr5i2Ae2YUYuV46PWbXjWY5H+hN/cJVghZQaQm5Hv+8=], x-security-correlation-id=[cccc4e4e-f7f3-4ba4-9b72-4d32538ecf02], x-security-service-version=[1.0.0], x-security-timestamp=[1523889273497], x-security-security-token=[249d0ce2-73cf-409f-a295-e298c0ba92c2:amcyY2JzdGQ:eGxkdGZzMTA:LmRldi4:3]}

--------------------------------------
2018-04-16 09:34:33,682 DEBUG [tomcat-http--6] {} org.apache.cxf.phase.PhaseInterceptorChain - Invoking handleMessage on interceptor org.apache.cxf.interceptor.ClientFaultConverter@38b4d45b
2018-04-16 09:34:33,682 DEBUG [tomcat-http--6] {} org.apache.cxf.phase.PhaseInterceptorChain - Invoking handleMessage on interceptor org.apache.cxf.ws.policy.PolicyVerificationInFaultInterceptor@925feb4
2018-04-16 09:34:33,684 INFO [tomcat-http--6] {} myapp.client.security.client.penta.SecurityInvocationHandler - Error Code:400 Error Message:java.io.SequenceInputStream@2dd8abaf
2018-04-16 09:34:33,684 DEBUG [tomcat-http--6] {} myapp.core.service.authorize.ServiceOutboundGatewayImpl - Authorize Service errorjava.io.SequenceInputStream@2dd8abaf
javax.ws.rs.BadRequestException: HTTP 400 Bad Request
at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)

 

 

NOTE:

1. **There is no problem with Interceptors being invoked, everything looks good on that part.
2. Only difference is, in case of success we have code that reads the response body (entity) by checking response code (not  >= 400).
3. In case of an error response which has response-code >=400, are being treated as faults and the respective interceptors are being invoked correctly. But the issue is earlier version had directly mapping complete response in message.getContents(), but now that's no longer working as this code in CXF classes gets me response payload=java.io.SequenceInputStream@2dd8abaf, which is causing a problem with my response handling, as I was totally dependent on CXF response body in case of these 400 error responses.