Logging with NGINX

In a previous post we setup a reverse proxy with NGINX, for talking to OpenStack API endpoints from our S-VNFMs. If we are to get our hands dirty in any type of API integration, especially with OpenStack, troubleshooting is inevitable.

Although OpenStack implement comprehensive logging features, those logs are usually distributed across different locations in OpenStack controller nodes, so our reverse proxy would serve as the ideal central location for collecting all API logs.

NGINX is equipped with a dedicated module, ngx_http_log_module for logging HTTP requests. With just two directives in NGINX config, we can start logging all our API requests.

log_format

The log_format directive defines the format of the log file. It takes the form log_format <format_name> format_string;. Here’s a sample configuration, which we include within the http context in the main configuration file nginx.conf.

log_format brief_log '$time_local, $remote_addr, $server_port, $request, status: $status;'

log_format detailed_log '$time_local, $remote_addr, $server_port, $request, status: $status, req_body: $request_body';

The format_string defines the format of the log file as a string. The strings proceeded by $ are the variables in NGINX, and the available variables can be found at log_format and variable_index in NGINX documentation.

The log_format directive must always be included within the http context.

access_log

access_log defines where to write our log files. We can place this directive within http or server contexts. NGINX log files are written immediately after a request is processed, so what is placed in server context takes priority.

We are using a dummy python app, to test our logging function. The Python app is listening on port 5000 and we have configured 5001 as the reverse proxy port.

#python app
server{
    listen 5001;
    client_max_body_size 0;
    
    access_log /var/log/nginx/access_myapp.log detailed_log;
    location / {
        proxy_pass http://127.0.0.1:5000;
    }
}

Use curl to issue HTTP request:

curl -X POST http://127.0.0.1:5001/long_request -d '""param1": "value"'

Check the log file:

$ cat /var/log/nginx/access_myapp.log
05/Feb/2020:13:46:27 +0000, 127.0.0.1, 5001, POST /long_request HTTP/1.1, status: 200, req_body: \x22\x22param1\x22: \x22value\x22

You may notice that that x22 (unicode value) is used to escape the quotation mark in json. For OpenStack APIs with a lot of parameters in json format, this will make the log files look cluttered.

So, we will update the log_format as below.

log_format detailed_log escape=none '$time_local, $remote_addr, $server_port, $request, status: $status, req_body: $request_body';

Make a new HTTP request with curl, and check the log file. The json parameters will be written to the log with the quotation marks, making it more readable.

$ cat /var/log/nginx/access_myapp.log
05/Feb/2020:13:46:27 +0000, 127.0.0.1, 5001, POST /long_request HTTP/1.1, status: 200, req_body: \x22\x22param1\x22: \x22value\x22
05/Feb/2020:13:54:49 +0000, 127.0.0.1, 5001, POST /long_request HTTP/1.1, status: 200, req_body: ""param1": "value""

In this post we tested the logging function in NGINX server, with a dummy Python app. The same concepts can be applied to enable logging for OpenStack reverse proxy, which we hope, will make life easier for you in the NFV journey.