I worked on many web applications which relied on other Web Services (some XML Soap, some JSON Rest API, some custom-made ones...). The ability to check the current and past behavior of these WS was very important, as they were a prime source of trouble. Having extensive and readable logs of the WS requests helps to rapidly identify a broken WS and redirect a ticket to the right team, providing them meaningful information.
In this article, I share my recommendations for efficient logging of Web Services calls.

Why should I log the WS calls ?

Imagine my manager come see me about a long-time customer complaining his account doesn't show any fidelity points. These points are retrieved from a WS managed by another company, in partnership with my employer. My first thought is always “It's certainly the Web Service that returned a wrong number of points” (aka “My app never fails”). But "certainly" is not enough for my manager, he needs a proof.

Without any log of the WS, it could be a long back-and-forth dialog with the partner company, or I'll have to call the WS myself in the production environment, which is usually not easy (and not recommended). On the contrary, if I can quickly find the WS call for this particular customer in the logs, confirm the number of points is wrong, and send the request/response/timestamp to the WS maintainers, 2 minutes later it's not my problem anymore and my manager is happy 😃 ... unless if the number is right in the WS, then there's a bug somewhere else in my app... I'm not so happy, but at least I've eliminated one possible culprit.

For this article, I suppose my app is logging into a file, which is the default logging storage of most frameworks. Depending on the infrastructure and the amount of data to log, it may not be the best solution - but it won't be discussed in this article. That's no big deal, most of the tips are relevant, whatever is the log storage.

First, what to log ?

Log as much as possible. Better have some information that will never be used, than being stuck because important information has not been written. I log the 6 following elements for each WS call :

Some context

Start with a plain-text indication of the purpose of the WS call : this will help to understand the chaining of WS requests when scanning the log file later. It can also be used to quickly jump to a specific WS call when I know what I'm looking for, so I give some thought about this message to include the key context about the call.

Verb + URL

Logging the URL is particularly useful when deploying a new WS to spot incorrect configuration (anyone ever tried to call a DEV web service from the PRODUCTION environment ? Certainly not me 😃).

Headers

Only if they're relevant, I log the headers of the request. They will be handy if I later need to replay the call manually. If they haven't been written, most of the time I will forget them.

Request content

Of course, write the data sent to the WS. In case of trouble with the WS provider, I'll need both the sent data and received data to clarify the situation with them and hopefully spot what was wrong.

These 4 first log lines are written before the request is sent; The 2 next ones are created after the response is received.

Response status code

As soon as the request is finished, I log the HTTP status code of the response, so I know the WS isn't still hanging out (and at this stage I can infer the WS total call time). If an error occurred, the HTTP status code of the response will give a hint of the problem.

Response content

Finally, log the received data, even in case of error. I'll give some tips on how to write the data later in the article.

These 6 lines gives a complete picture of the different stages of the WS call. They will come handy later if I need to troubleshoot any problem with the WS.

Each log line must have a “call token”

What I mean by “call token” is an ID that will be shared by all the log lines of the same WS call. Thanks to the call token, I can extract all the related lines with a simple grep, and untangle overlapping WS requests and responses.

In the context of a web application, I like to create the token using both the session ID and the HTTP request ID. This way, I can also easily find all the WS calls for the session of a given user. In the example below abc is the shortened session ID, and 123 the HTTP request ID.

Log input and output on a single line

In the log files, I always write the minified version of the request/response data, whether it is JSON or XML, so it fits on a single line. It's easier to scan the logs when every WS call has the same number of lines and the flow of text is not disrupted with large bunks of JSON/XML data.
For this purpose, I disabled the line wrapping of long lines in my text editor. If I'm scanning logs from a terminal, I use less -S for the same result (the -S option disables the wrapping of long lines).

When I need to explore the content of a request or response, I use a formatter (obviously I'm using Format Express). From a terminal, I use the Format Express API from the command line with curl.

Log the errors

Developers must always make sure that their app is handling nicely the errors of a Web Service by :

• showing a user-friendly message to the user that something went wrong (and what to do).
• logging a developer-friendly message indicating what went wrong.

Early in the WS integration, I try to deliberately send invalid data to the WS : check how it reacts, and make sure to log the response code and the returned data. I do it again by calling an erroneous URL, or with a wrong verb... The log should clearly indicate what happened (has the WS been reached ? what was returned ?). Never wait to have an error in production to discover how are handled 4xx and 5xx errors.

Rule of thumb: log whatever the WS is responding. The app may be expecting JSON, but received HTML, write it nonetheless. For sure, it contains useful information to fix the problem with the WS provider (the output will different for a proxy error than for an application error). The more information you can provide to the WS maintainer, the quicker the problem will be solved.

Hide sensitive data

If the WS is manipulating sensitive data, like credit card numbers or password, they must be removed from the logs. What's the point of encrypting password in DB if they're in plain text in the logs ? So systematically replace sensitive data with ***** or [filtered].

Truncate when the data is too large

Sometimes the input/output is too large to be logged, for example Web Services handling files in Base64 notation. I don't want to write the full file for each request, so the field is truncated : I keep only the first few chars and write the total size.

Before

After

In the example above, I kept the 25 first chars, and appended a clear message indicating the field has been truncated for the logs. This way, I can quickly acknowledge if the file was present or not (the most common problem is the file missing). The total size and the beginning can give a hint of the content of the file (in the example above, decoding the Base64 indicates it's a PDF).

Any other tip ?

Feel free to add your own best practices about logging Web Services calls on Reddit.