Debugging Web APIs (nginx)

And there I waited for weeks hoping to find inspiration to write something on this blog, to give this blog a sense of purpose coming nothing but empty handed. No more will I see this blog deserted due to lack of clarity to its purpose. I shall start adding content, and the purpose will surely follow.

Many a times, we require to test some live API, perhaps we need to add a new feature, or we have a new client who claims that our API is not working for them. In such scenarios, having access to both the request and response body helps in understanding the problem. In most scenarios making your backend application do the logging is not a good idea.

In such scenarios the following trick helps in logging complete request and response body for selective traffic only and only if you use nginx as a reverse proxy/frontend for your application (I mean, who doesn't).

We start with an nginx package that has lua support. For Debian and Ubuntu, the package to install is nginx-extras.

sudo apt install nginx-extras

If you are already using nginx as a reverse proxy, you do not need to worry, as nginx-extras is normal nginx bundled with a lot of useful modules. If you are using openresty you do not need to install anything. ^[1]

The following block of code does the real magic:

http {
...

    log_format bodylog escape=json '$remote_addr - $remote_user [$time_local] '
      '"$request" $status $body_bytes_sent '
      '"$http_referer" "$http_user_agent" $request_time '
      '<"$request_body" >"$resp_body"';

    lua_need_request_body on;

    map $host $loggable {
        random.com 1;
        default    0;
    }

    server {
        ...
    
        set $resp_body "";
        body_filter_by_lua '
            local resp_body = ngx.arg[1]
            ngx.ctx.buffered = (ngx.ctx.buffered or "") .. resp_body
            if ngx.arg[2] then
                ngx.var.resp_body = ngx.ctx.buffered
            end
        ';
        access_log /var/log/nginx/debuglogs.log bodylog if=$loggable;
        ...
    
    }
}

The ... indicate the other configs that you will have as you have already setup nginx.

Before you go copy pasting it and wondering why if does / does not work for you, remember this quote by a great DevOps Engineer:

You do not use in production what you do not understand.

Wise quote indeed. So lets dive into the explanation of why this works and how this works. Lets look at it in parts.

Defining the Log Format

The below section defines the log format named bodylog in nginx.

    log_format bodylog escape=json '$remote_addr - $remote_user [$time_local] '
      '"$request" $status $body_bytes_sent '
      '"$http_referer" "$http_user_agent" $request_time '
      '<"$request_body" >"$resp_body"';

    lua_need_request_body on;

The points to take note are:

1. There are variables $request_body and $resp_body which should contain the request and response of a request respectively. The $request_body variable is already available in nginx as documented in ^[2]. A point to note is that the variable is not always present and hence the lua_need_request_body on; is required to make sure that nginx always reads the request body.
2. The $resp_body is set in other part of the config.
3. The escape=json makes sure that the log would contain json escaped characters rather than base64 encoded ones. Note that this directive was introduced in nginx version 1.11.8^[3]. If you use the latest of latest software, you would love the escape=none directive introduced in version 1.13.10.

Getting the response body

To get the response body, we will need to use the lua module in the body phase of the request using body_filter_by_lua^[4] as follows:

        set $resp_body "";
        body_filter_by_lua '
            local resp_body = ngx.arg[1]
            ngx.ctx.buffered = (ngx.ctx.buffered or "") .. resp_body
            if ngx.arg[2] then
                ngx.var.resp_body = ngx.ctx.buffered
            end
        ';

This part of the code reads data chunk by chunk from the ngx.arg[1] variable, accumulates it in ngx.ctx.buffered and saves it to the $resp_body (which is accessed using ngx.var.resp_body in the lua code) when we know that the data is complete based on the value of ngx.arg[2]. If you do not want to log the complete response body, you may use local resp_body = string.sub(ngx.arg[1], 1, 1000) which would log only the first 1000 bytes of the response as normally responses are in a single chunk. This method of request repsonse logging (this complete post) was adapted from ^[5] and has been changed to make sure that the directives are in their proper places.

Selectively Logging

This is done by first creating a map to set the value of $loggable corresponding to another variable

    map $host $loggable {
        random.com 1;
        default    0;
    }

This would always set the $loggable variable to 1 when the $host variable which corresponds to Host HTTP Header is random.com. In all other scenarios, it will be set to 0. We can use any variable in place of $host. A few examples would be:

1. $remote_addr would allow differentiating between client IP addressess
2. $status will allow differentiating between status codes
3. $arg_hello will allow differentiating between the query parameter hello

The second part is to use a conditional access_log^[6] directive using the Log Format that we have already defined:

        access_log /var/log/nginx/debuglogs.log bodylog if=$loggable;

The logging to /var/log/nginx/debuglogs.log will only take place if $loggable is neither empty or 0. Adding both parts together, requests for the domain random.com will be the only ones logged with our extensive log format.

The possibilities are endless.

You do not necessarily have to use the above config with a proxy_pass directive, you can use it everywhere (Notify me if I am wrong).

I would be more motivated to write such articles if I get to know that people are being helped by them. I have not decided on a feedback channel yet, but you can always ping me on shoeb[dot]c[at]pm[dot]me

Share the post with your peers if you think it would help them, suggestions to make the post more accurate and/or friendly are welcome