I know I’ve written about consuming web services before. In this blog post I explained how ARS is able to consume web services, how the SOAP communication is handled and how you can follow this in the logs. But SOAP tends to get complicated and I decided to write a follow up on that blog post, but this time focusing on a real life example. I’m going to assume we’re all familiar with the basics of web services, or at least with the things I explained in my last article on the subject. If not, well, I’d encourage you to read it over. Okay, ready? Let’s jump straight in.
We’re consuming an external web service with ARS. No problem creating the filter on Developer Studio level, everything is mapped and is ready to go. This is what it looks like in Developer Studio:
Fairly basic setup. I’ve loaded the web service, there are lot of input fields and only one out response which I mapped as well. As far as the design process is concerned, there are no problems. The web service is interpreted as expected, no problems mapping anything, it’s all looking fine.
However during the various tests I’m running with the web service, the response is never coming through. Even in its most basic setup I can’t get it to work: A form, a filter, the minimal amount of fields for the input, but it’s still not coming through. Why is that happening?
Let’s check the various steps that are involved first. This is what happens when I click on that save button:
- Filter consumeTestWS is executed
- AR server constructs the XML based on the input elements and sends the relevant information on to the Java Plugin server
- The Plugin server uses the information received by AR server to create a proper SOAP request and sends it on
- We wait for the result and as soon as it comes in we extract the relevant XML
- The XML is sent back to AR server
- AR server uses the mapping information to map the result to the correct field
There are quite a few places where this can fail. It could be that the plugin server never receives it, that the data is not sent to AR server, there's a problem with the mapping or that the 3rd party web service never sends the answer.
So how do we check this? The answer won’t come as a surprise: we need to enable logs. I suggest we start with AR server’s Filter logging so we can see if the filter is executed as expected and with my favourite log in these occasions: the Java API log.
I included references at the bottom with more information on how to do this, but let’s check what we’re seeing here. I strongly feel you need to approach these sort of logs with a plan. Don’t just jump straight in and look for whatever error comes up - you need to have an idea of what you’re expecting to see. It has to be interpreted correctly, else it’s meaningless. In this case, I want to answer the following questions:
- Is the filter executed?
- Once the plugin server receives the request from AR server, how is it handled?
- What does the SOAP request look like we send to the web service?
- Do we get an answer?
- Does this answer make it back to AR server?
In order to do this I need to know what these logs show me. The filter log is straight forward: I know the name of the filter, I know the timestamp. That’s all I need. Let’s check this first.
That should answer question one, the filter is executed correctly. To answer question two, we need to check the Plugin log. What we’re looking for is the moment the Plugin server first receives the request and then we follow it until the answer from the web service.
The logs tend to look a bit daunting, but on a higher level, this is what I’m looking for:
1) Timestamp INFO [pool-PoolID-thread-ThreadID] … <ARSYS.ARF.WEBSERVICE>soapOperationDoc
Contains information on the Operation we’re going to use. The operation that goes out and what we’re expecting back from the 3rd party web service.
2) Timestamp INFO [pool-PoolID-thread-ThreadID] … <ARSYS.ARF.WEBSERVICE>soapInputMap
Shows the mapping information. What form is being used? What ARS fields are mapped to what web service fields?
3) Timestamp INFO [pool-PoolID-thread-ThreadID] … <ARSYS.ARF.WEBSERVICE>soapService
Next the log records the various bits and pieces it receives from AR server. The more relevant are:
- soapService: the name of the service we’re calling
- SoapMethod: the method of that service
- soapURL: the destination of the call. It’s called End Point in Developer Studio. This the URL the request will be send to.
4) Timestamp INFO [pool-PoolID-thread-ThreadID] … <ARSYS.ARF.WEBSERVICE> soapInputDocument
This is the XML data that AR server has sent to the Plugin server. It’s not ready yet to be sent to the web service. That will come later.
5) Timestamp INFO [pool-PoolID-thread-ThreadID] … <ARSYS.ARF.WEBSERVICE> soapAction
It won’t be mentioned in the logs anywhere but this is the point where the plugin server takes over. Up to this point it recorded whatever it received from AR server. Now it’s the plugin server’s turn: we need to create the actual SOAP request. It’s recording a few pieces of information (most of them have been recorded before) which aren’t of much interest, the next line is what we care about.
6) Timestamp INFO [pool-PoolID-thread-ThreadID] … <ARSYS.ARF.WEBSERVICE> Input Env
This is the request, ready to be sent to the 3rd party web service. It’s all wrapped in SOAP, the next line (About to Invoke) is the point where we send it and the one after that is where it’s done (Finished invoking).
7) Timestamp INFO [pool-PoolID-thread-ThreadID] … <ARSYS.ARF.WEBSERVICE> Output Envelope
It’s done sending, next we record the answer from the web service. This is the raw XML, the SOAP message as we received it.
8) Timestamp INFO [pool-PoolID-thread-ThreadID] … <ARSYS.ARF.WEBSERVICE>
There’s no name for this one, but this is the XML that the plugin server is going to send back to AR server.
I like to make sense of the log file and I need to know what exactly I’m looking for. That’s why I read it line by line, and using this overview I know exactly what to expect. One last point, if there’s a lot of stuff logged, use the Pool ID and the Thread ID to group calls. The communication will be done using the same pool and thread IDs so you can follow it. For example, it would look like pool-5-thread-23.
Back to our problem. Just to remind us, the web service seems to work but we never see the response in the actual field. We know the filter is executed, so let’s check the Plugin logs. Finding the start can be difficult, just look for something you know (the method, the URL, etc.) and use the pool and thread IDs to find the start. So here we go:
There it is. We’re using verifyAddress and we’re expecting verifyAddressResponse. Next the mapping overview. This doesn’t really interest us, it’s just the input mapping and we know that’s not a problem here. The same for most of the elements that follow. I’m making sure it’s all there and the values are correct (to the WSDL and what I mapped in Developer Studio). It looks fine. The soapURL is correct, so is the method and the service.
Now I know that AR server finished the first part: it sent all the data and the plugin server correctly identified it. Let’s check what happens next.
First we need to check if the SOAP request is correct. That’s called Input Env in our logs. I usually copy it and check if it all makes sense.
A good test is to compare it to something like SoapUI. Like ARS, SoapUI will interpret the SOAP request based on the WSDL. There are usually small differences, but it should look roughly the same.
The two look similar enough, ARS’s interpretation is correct. Let’s see what happens when it goes out. I’m looking for About to invoke and Finished invoking and the log entries that follow.
Looks okay, doesn’t it? Call goes out, answer comes back. So why doesn’t AR server receive it? Let’s check the last two entries again. First it’s the complete SOAP envelope as received by the plugin server. Next, it interprets it. It strips the SOAP tags and formats it to a useable response which it will send back to AR server. What it sends back is logged in the nameless last log entry. Let’s have a closer look at both of them.
What we receive looks okay, but what we send back to AR server suddenly misses a whole section. By the time it gets to AR server we miss the crucial part: the actual data. So from an AR server perspective there’s nothing to map.
That’s where this is failing. It’s the very last part. The filter is executed, the data is sent to the plugin server, it’s converted to a SOAP request and sent off. We get an answer, the SOAP is stripped but somehow we also stripped the actual data.
Have a look at it again, give it a few minutes. What’s wrong here? Not seeing it? Well, so didn’t I initially and I spent a lot of time figuring it out. I eventually used a reverse proxy to intercept the response and changed it until I found what’s wrong with it. I won’t go into the details how I did it, but I basically used the Fiddler trick I described earlier. I added elements, removed them, until the logs let it through.
Still not seeing it? Check the point where it’s cut off and then check this part in the original SOAP response. Then check the formatting.
See? It doesn’t add up. VerifyAddressResponse is closed and the data (Result) is orphaned. Earlier on ARS told the plugin server to get the data from VerifyAddressResponse, remember?
So that’s what it’s doing. It looks up VerifyAddressResponse, gets the data from that element and ignores the rest. The actual answer is orphaned, it doesn’t belong to anything, so it’s just discarded.
The answer? It’s not an ARS problem. The system behaves as expected, it’s the external web service that made a mistake formatting the response.
I hope you were able to follow me. I know a tendency to dive right in the deep, but what I want to get across is that you need to understand a log file, you need to able to read it. It needs to make sense, so if a problem occurs you know how to analyse it.
That’s it from me. Next time, something completely different. Not quite sure what this is, but I'll let you know. If you have any suggestions, please leave a comment below.
Until next time,