CODEWITHSUNDEEP
javahttpclientspring-wsexchangewebservices
Drew Wills
Drew Wills

Reputation: 8446

Baffled by SoapFaultClientException using Spring WS, HttpClient, and Exchange WS

I am attempting to call the Exchange WS 2010 API with Spring WS + HttpClient. I get the following error...

Jun/27 11:39:06,825 controller.AjaxCalendarController.[] - Unknown Error
org.springframework.ws.soap.client.SoapFaultClientException: The request is invalid.
    at org.springframework.ws.soap.client.core.SoapFaultMessageResolver.resolveFault(SoapFaultMessageResolver.java:37)
    at org.springframework.ws.client.core.WebServiceTemplate.handleFault(WebServiceTemplate.java:774)
    at org.springframework.ws.client.core.WebServiceTemplate.doSendAndReceive(WebServiceTemplate.java:600)
    at org.springframework.ws.client.core.WebServiceTemplate.sendAndReceive(WebServiceTemplate.java:537)
    at org.springframework.ws.client.core.WebServiceTemplate.marshalSendAndReceive(WebServiceTemplate.java:384)
    at org.springframework.ws.client.core.WebServiceTemplate.marshalSendAndReceive(WebServiceTemplate.java:378)
    at org.jasig.portlet.calendar.adapter.ExchangeCalendarAdapter.retrieveExchangeEvents(ExchangeCalendarAdapter.java:171)
    at org.jasig.portlet.calendar.adapter.ExchangeCalendarAdapter.getEvents(ExchangeCalendarAdapter.java:132)
    at org.jasig.portlet.calendar.adapter.CalendarEventsDao.getEvents(CalendarEventsDao.java:74)
    at org.jasig.portlet.calendar.mvc.controller.AjaxCalendarController.getEventList(AjaxCalendarController.java:127)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
    at java.lang.reflect.Method.invoke(Method.java:597)
    at org.springframework.web.bind.annotation.support.HandlerMethodInvoker.invokeHandlerMethod(HandlerMethodInvoker.java:176)
    at org.springframework.web.portlet.mvc.annotation.AnnotationMethodHandlerAdapter.invokeHandlerMethod(AnnotationMethodHandlerAdapter.java:358)
    at org.springframework.web.portlet.mvc.annotation.AnnotationMethodHandlerAdapter.doHandle(AnnotationMethodHandlerAdapter.java:345)
    at org.springframework.web.portlet.mvc.annotation.AnnotationMethodHandlerAdapter.handleResource(AnnotationMethodHandlerAdapter.java:293)
    at org.springframework.web.portlet.DispatcherPortlet.doResourceService(DispatcherPortlet.java:825)
    at org.springframework.web.portlet.FrameworkPortlet.processRequest(FrameworkPortlet.java:525)
    at org.springframework.web.portlet.FrameworkPortlet.serveResource(FrameworkPortlet.java:477)
    at org.jasig.portal.portlet.container.FilterChainImpl.doFilter(FilterChainImpl.java:212)
    at org.jasig.portal.portlet.container.FilterChainImpl.processFilter(FilterChainImpl.java:84)
    at org.jasig.portal.portlet.container.FilterManagerImpl.processFilter(FilterManagerImpl.java:103)
    at org.apache.pluto.container.driver.PortletServlet.dispatch(PortletServlet.java:350)
    at org.apache.pluto.container.driver.PortletServlet.doGet(PortletServlet.java:261)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:690)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:803)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
    at org.apache.catalina.core.ApplicationDispatcher.invoke(ApplicationDispatcher.java:630)
    at org.apache.catalina.core.ApplicationDispatcher.processRequest(ApplicationDispatcher.java:436)
    at org.apache.catalina.core.ApplicationDispatcher.doForward(ApplicationDispatcher.java:374)
    at org.apache.catalina.core.ApplicationDispatcher.forward(ApplicationDispatcher.java:302)
    at org.apache.pluto.driver.container.DefaultPortletInvokerService.invoke(DefaultPortletInvokerService.java:229)
    at org.apache.pluto.driver.container.DefaultPortletInvokerService.serveResource(DefaultPortletInvokerService.java:149)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
    at java.lang.reflect.Method.invoke(Method.java:597)
    at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:318)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
    at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:90)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
    at org.springframework.aop.aspectj.MethodInvocationProceedingJoinPoint.proceed(MethodInvocationProceedingJoinPoint.java:80)
    at org.jasig.portal.portlet.dao.jpa.ThreadContextClassLoaderAspect.doThreadContextClassLoaderUpdate(ThreadContextClassLoaderAspect.java:63)
    at sun.reflect.GeneratedMethodAccessor101.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
    at java.lang.reflect.Method.invoke(Method.java:597)
    at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethodWithGivenArgs(AbstractAspectJAdvice.java:621)
    at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethod(AbstractAspectJAdvice.java:610)
    at org.springframework.aop.aspectj.AspectJAroundAdvice.invoke(AspectJAroundAdvice.java:65)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
    at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202)
    at $Proxy210.serveResource(Unknown Source)
    at org.apache.pluto.container.impl.PortletContainerImpl.doServeResource(PortletContainerImpl.java:203)
    at org.jasig.portal.portlet.rendering.PortletRendererImpl.doServeResource(PortletRendererImpl.java:598)
    at org.jasig.portal.portlet.rendering.worker.PortletResourceExecutionWorker.callInternal(PortletResourceExecutionWorker.java:54)
    at org.jasig.portal.portlet.rendering.worker.PortletResourceExecutionWorker.callInternal(PortletResourceExecutionWorker.java:32)
    at org.jasig.portal.portlet.rendering.worker.PortletExecutionWorker$1.call(PortletExecutionWorker.java:165)
    at org.jasig.portal.portlet.rendering.worker.PortletExecutionCallable.call(PortletExecutionCallable.java:119)
    at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
    at java.util.concurrent.FutureTask.run(FutureTask.java:138)
    at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
    at java.lang.Thread.run(Thread.java:662)

It doesn't tell me anything about what it thinks is wrong with the request. :( On the server-side, both IIS and Exchange merely state that a request came through from me and an HTTP 500 was returned.

Here's is the SOAP envelope (captured from the logs):

<SOAP-ENV:Envelope xmlns:SOAP-ENV="http://schemas.xmlsoap.org/soap/envelope/">
    <SOAP-ENV:Header/>
    <SOAP-ENV:Body>
        <ns2:GetUserAvailabilityRequest xmlns:ns2="http://schemas.microsoft.com/exchange/services/2006/messages" xmlns:ns3="http://schemas.microsoft.com/exchange/services/2006/types">
            <ns3:TimeZone>
                <ns3:Bias>0</ns3:Bias>
                <ns3:StandardTime>
                    <ns3:Bias>0</ns3:Bias>
                    <ns3:Time>02:00:00</ns3:Time>
                    <ns3:DayOrder>1</ns3:DayOrder>
                    <ns3:Month>11</ns3:Month>
                    <ns3:DayOfWeek>Sunday</ns3:DayOfWeek>
                </ns3:StandardTime>
                <ns3:DaylightTime>
                    <ns3:Bias>0</ns3:Bias>
                    <ns3:Time>02:00:00</ns3:Time>
                    <ns3:DayOrder>1</ns3:DayOrder>
                    <ns3:Month>3</ns3:Month>
                    <ns3:DayOfWeek>Sunday</ns3:DayOfWeek>
                </ns3:DaylightTime>
            </ns3:TimeZone>
            <ns2:MailboxDataArray>
                <ns3:MailboxData>
                    <ns3:Email>
                        <ns3:Name>Drew Wills</ns3:Name>
                        <ns3:Address>[email protected]</ns3:Address>
                    </ns3:Email>
                    <ns3:AttendeeType>Required</ns3:AttendeeType>
                    <ns3:ExcludeConflicts>false</ns3:ExcludeConflicts>
                </ns3:MailboxData>
            </ns2:MailboxDataArray>
            <ns3:FreeBusyViewOptions>
                <ns3:TimeWindow>
                    <ns3:StartTime>2012-06-27T00:00:00.000</ns3:StartTime>
                    <ns3:EndTime>2012-07-04T00:00:00.000</ns3:EndTime>
                </ns3:TimeWindow>
                <ns3:MergedFreeBusyIntervalInMinutes>60</ns3:MergedFreeBusyIntervalInMinutes>
                <ns3:RequestedView>DetailedMerged</ns3:RequestedView>
            </ns3:FreeBusyViewOptions>
        </ns2:GetUserAvailabilityRequest>
    </SOAP-ENV:Body>
</SOAP-ENV:Envelope>

Here also is some trace logging that shows HTTP headers and so forth...

Jun/27 11:39:06,773 conn.DefaultClientConnection.[] - Sending request: POST /EWS/exchange.asmx HTTP/1.1
Jun/27 11:39:06,773 http.wire.[] - >> "POST /EWS/exchange.asmx HTTP/1.1[\r][\n]"
Jun/27 11:39:06,773 http.wire.[] - >> "Accept-Encoding: gzip[\r][\n]"
Jun/27 11:39:06,773 http.wire.[] - >> "Accept: text/xml, text/html, image/gif, image/jpeg, *; q=.2, */*; q=.2[\r][\n]"
Jun/27 11:39:06,773 http.wire.[] - >> "SOAPAction: "http://schemas.microsoft.com/exchange/services/2006/messages/GetUserAvailability"[\r][\n]"
Jun/27 11:39:06,773 http.wire.[] - >> "Content-Type: text/xml; charset=utf-8[\r][\n]"
Jun/27 11:39:06,773 http.wire.[] - >> "Content-Length: 1362[\r][\n]"
Jun/27 11:39:06,773 http.wire.[] - >> "Host: mail.stcloudstate.edu[\r][\n]"
Jun/27 11:39:06,774 http.wire.[] - >> "Connection: Keep-Alive[\r][\n]"
Jun/27 11:39:06,774 http.wire.[] - >> "User-Agent: Apache-HttpClient/4.1.1 (java 1.5)[\r][\n]"
Jun/27 11:39:06,774 http.wire.[] - >> "Cookie: exchangecookie=49398e25ac5b4b84a19f93d170b3eefa[\r][\n]"
Jun/27 11:39:06,774 http.wire.[] - >> "Cookie2: $Version=1[\r][\n]"
Jun/27 11:39:06,774 http.wire.[] - >> "Authorization: NTLM xxx[\r][\n]"
Jun/27 11:39:06,774 http.wire.[] - >> "[\r][\n]"
Jun/27 11:39:06,774 http.headers.[] - >> POST /EWS/exchange.asmx HTTP/1.1
Jun/27 11:39:06,774 http.headers.[] - >> Accept-Encoding: gzip
Jun/27 11:39:06,774 http.headers.[] - >> Accept: text/xml, text/html, image/gif, image/jpeg, *; q=.2, */*; q=.2
Jun/27 11:39:06,774 http.headers.[] - >> SOAPAction: "http://schemas.microsoft.com/exchange/services/2006/messages/GetUserAvailability"
Jun/27 11:39:06,774 http.headers.[] - >> Content-Type: text/xml; charset=utf-8
Jun/27 11:39:06,774 http.headers.[] - >> Content-Length: 1362
Jun/27 11:39:06,774 http.headers.[] - >> Host: mail.stcloudstate.edu
Jun/27 11:39:06,774 http.headers.[] - >> Connection: Keep-Alive
Jun/27 11:39:06,774 http.headers.[] - >> User-Agent: Apache-HttpClient/4.1.1 (java 1.5)
Jun/27 11:39:06,774 http.headers.[] - >> Cookie: exchangecookie=49398e25ac5b4b84a19f93d170b3eefa
Jun/27 11:39:06,775 http.headers.[] - >> Cookie2: $Version=1
Jun/27 11:39:06,775 http.headers.[] - >> Authorization: NTLM xxx
Jun/27 11:39:06,776 http.wire.[] - >> "<SOAP-ENV:Envelope xmlns:SOAP-ENV="http://schemas.xmlsoap.org/soap/envelope/"><SOAP-ENV:Header/><SOAP-ENV:Body><ns2:GetUserAvailabilityRequest xmlns:ns2="http://schemas.microsoft.com/exchange/services/2006/messages" xmlns:ns3="http://schemas.microsoft.com/exchange/services/2006/types"><ns3:TimeZone><ns3:Bias>0</ns3:Bias><ns3:StandardTime><ns3:Bias>0</ns3:Bias><ns3:Time>02:00:00</ns3:Time><ns3:DayOrder>1</ns3:DayOrder><ns3:Month>11</ns3:Month><ns3:DayOfWeek>Sunday</ns3:DayOfWeek></ns3:StandardTime><ns3:DaylightTime><ns3:Bias>0</ns3:Bias><ns3:Time>02:00:00</ns3:Time><ns3:DayOrder>1</ns3:DayOrder><ns3:Month>3</ns3:Month><ns3:DayOfWeek>Sunday</ns3:DayOfWeek></ns3:DaylightTime></ns3:TimeZone><ns2:MailboxDataArray><ns3:MailboxData><ns3:Email><ns3:Name>Drew Wills</ns3:Name><ns3:Address>[email protected]</ns3:Address></ns3:Email><ns3:AttendeeType>Required</ns3:AttendeeType><ns3:ExcludeConflicts>false</ns3:ExcludeConflicts></ns3:MailboxData></ns2:MailboxDataArray><ns3:FreeBusyViewOptions><ns3:TimeWindow><ns3:StartTime>2012-06-27T00:00:00.000</ns3:StartTime><ns3:EndTime>2012-07-04T00:00:00.000</ns3:EndTime></ns3:TimeWindow><ns3:MergedFreeBusyIntervalInMinutes>60</ns3:MergedFreeBusyIntervalInMinutes><ns3:RequestedView>DetailedMerged</ns3:RequestedView></ns3:FreeBusyViewOptions></ns2:GetUserAvailabilityRequest></SOAP-ENV:Body></SOAP-ENV:Envelope>"
Jun/27 11:39:06,801 http.wire.[] - << "HTTP/1.1 500 Internal Server Error[\r][\n]"
Jun/27 11:39:06,801 http.wire.[] - << "Cache-Control: private[\r][\n]"
Jun/27 11:39:06,801 http.wire.[] - << "Transfer-Encoding: chunked[\r][\n]"
Jun/27 11:39:06,801 http.wire.[] - << "Content-Type: text/xml; charset=utf-8[\r][\n]"
Jun/27 11:39:06,802 http.wire.[] - << "Server: Microsoft-IIS/7.5[\r][\n]"
Jun/27 11:39:06,802 http.wire.[] - << "X-AspNet-Version: 2.0.50727[\r][\n]"
Jun/27 11:39:06,802 http.wire.[] - << "Persistent-Auth: true[\r][\n]"
Jun/27 11:39:06,802 http.wire.[] - << "X-Powered-By: ASP.NET[\r][\n]"
Jun/27 11:39:06,802 http.wire.[] - << "Date: Wed, 27 Jun 2012 18:39:05 GMT[\r][\n]"
Jun/27 11:39:06,802 http.wire.[] - << "[\r][\n]"
Jun/27 11:39:06,802 conn.DefaultClientConnection.[] - Receiving response: HTTP/1.1 500 Internal Server Error
Jun/27 11:39:06,802 http.headers.[] - << HTTP/1.1 500 Internal Server Error
Jun/27 11:39:06,802 http.headers.[] - << Cache-Control: private
Jun/27 11:39:06,802 http.headers.[] - << Transfer-Encoding: chunked
Jun/27 11:39:06,802 http.headers.[] - << Content-Type: text/xml; charset=utf-8
Jun/27 11:39:06,802 http.headers.[] - << Server: Microsoft-IIS/7.5
Jun/27 11:39:06,802 http.headers.[] - << X-AspNet-Version: 2.0.50727
Jun/27 11:39:06,802 http.headers.[] - << Persistent-Auth: true
Jun/27 11:39:06,802 http.headers.[] - << X-Powered-By: ASP.NET
Jun/27 11:39:06,802 http.headers.[] - << Date: Wed, 27 Jun 2012 18:39:05 GMT
Jun/27 11:39:06,804 exchange.NtlmAuthHttpClient.[] - Connection can be kept alive indefinitely
Jun/27 11:39:06,808 http.wire.[] - << "247[\r][\n]"
Jun/27 11:39:06,808 http.wire.[] - << "<?xml version="1.0" encoding="utf-8"?><s:Envelope xmlns:s="http://schemas.xmlsoap.org/soap/envelope/"><s:Body><s:Fault><faultcode xmlns:a="http://schemas.microsoft.com/exchange/services/2006/types">a:ErrorInvalidRequest</faultcode><faultstring xml:lang="en-US">The request is invalid.</faultstring><detail><e:ResponseCode xmlns:e="http://schemas.microsoft.com/exchange/services/2006/errors">ErrorInvalidRequest</e:ResponseCode><e:Message xmlns:e="http://schemas.microsoft.com/exchange/services/2006/errors">The request is invalid.</e:Message></detail></s:Fault></s:Body></s:Envelope>"
Jun/27 11:39:06,808 http.wire.[] - << "[\r][\n]"
Jun/27 11:39:06,808 http.wire.[] - << "0[\r][\n]"
Jun/27 11:39:06,808 http.wire.[] - << "[\r][\n]"
Jun/27 11:39:06,809 tsccm.ThreadSafeClientConnManager.[] - Released connection is reusable.

Thank you mightily for any assistance with this thorny issue.

Upvotes: 2

Views: 28810

Answers (3)

lewen7er9
lewen7er9

Reputation: 21

I have been experiencing the same issue -- the EWS service for a local Exchange 2010 install rejects requests that include an empty "soap-env:header" element. I verified the issue using cURL with the following SOAP XML:

<SOAP-ENV:Envelope xmlns:SOAP-ENV="http://schemas.xmlsoap.org/soap/envelope/">
<SOAP-ENV:Header/>
<SOAP-ENV:Body>
    <ns2:GetFolder xmlns:ns2="http://schemas.microsoft.com/exchange/services/2006/messages"
                   xmlns:ns3="http://schemas.microsoft.com/exchange/services/2006/types">
        <ns2:FolderShape>
            <ns3:BaseShape>Default</ns3:BaseShape>
        </ns2:FolderShape>
        <ns2:FolderIds>
            <ns3:DistinguishedFolderId Id="inbox"/>
        </ns2:FolderIds>
    </ns2:GetFolder>
</SOAP-ENV:Body>

Oddly, I could get the EWS service to accept the request by making any of the following changes to the "SOAP-ENV:Header" element in the request:

  1. Add RequestServerVersion to header as described above
  2. Remove the "SOAP-ENV:Header" element entirely

  3. Replace the single-tag empty element with a "double-tag" empty element:

Seems to me like a bug in Exchange 2010 EWS.

Upvotes: 2

Drew Wills
Drew Wills

Reputation: 8446

I got it working -- here are the details...

I used SoapUI to gain some insights.. I wanted to test my SOAP envelope (generated by my code) but... "soapUI currently does not support NTLMv2, so if your server requires this you will either need to reconfigure the server to accept NTLMv1 (see...) or use a product like (...) to overcome this."

I wasn't much surprised. NTLM AuthN was the nightmare of the previous 2 days, and it's a monster to get working in Java. This article helped immesely, but in my case I also had to force my code to send NTLM creds for the "negotiate" (SPNEGO) scheme. (It would choose kerberos, but give up because it didn't have kerberos creds... argh!)

SoapUI also could generate a sample request, which I reviewed. It looked quite a bit like mine, but had additionally a few optional (seemingly) bits. Most were optional, but apparently one isn't.

The web service wanted this soap header:

<SOAP-ENV:Header><ns3:RequestServerVersion xmlns:ns3="http://schemas.microsoft.com/exchange/services/2006/types" Version="Exchange2010_SP2"/></SOAP-ENV:Header>

The MSDN API documentation says the soap header is optional, but it started working when I sent it.

Upvotes: 1

Elliot
Elliot

Reputation: 21

So if you take the client out of the picture, and simply mimic the request using curl, can you verify that you still get a 500 response?

That would at least isolate the problem to the server side.

You might be able to more easily debug the issue using curl by playing around with HTTP header values or the contents of the soap entity.

Upvotes: 2

Related Questions