{"id":10725,"date":"2016-09-28T04:47:11","date_gmt":"2016-09-27T19:47:11","guid":{"rendered":"https:\/\/jirak.net\/wp\/application-tracing-with-nginx-and-nginx-plus\/"},"modified":"2016-09-28T05:37:37","modified_gmt":"2016-09-27T20:37:37","slug":"application-tracing-with-nginx-and-nginx-plus","status":"publish","type":"post","link":"https:\/\/jirak.net\/wp\/application-tracing-with-nginx-and-nginx-plus\/","title":{"rendered":"Application Tracing with NGINX and NGINX\u00a0Plus"},"content":{"rendered":"

Application Tracing with NGINX and NGINX\u00a0Plus
\n<\/p>\n

\"The
Photo: WordPress.org<\/a><\/figcaption><\/figure>\n

Using variables for application performance management<\/em><\/h3>\n

Variables are an important and sometimes overlooked aspect of NGINX configuration. With approximately 150 variables<\/a> available, there are variables to enhance every part of your configuration. In this blog post we discuss how to use NGINX variables for application tracing and application performance management (APM), with a focus on uncovering performance bottlenecks in your application. This post applies to both the open source NGINX software and NGINX Plus. For brevity we’ll refer to NGINX Plus throughout except when there is a difference between the two products.<\/p>\n

The Application Delivery Environment<\/h2>\n

In our sample application delivery environment, NGINX Plus is working as a reverse proxy for our application. The application itself is comprised of a web frontend behind which sit a number of microservices.<\/p>\n

\"In
Sample application delivery environment<\/figcaption><\/figure>\n

Tracing Requests End‑to‑End<\/h2>\n

NGINX Plus R10 (and NGINX 1.11.0) introduces the $request_id<\/code><\/a> variable, which is a randomly generated string of 32 hexadecimal characters automatically assigned to each HTTP request as it arrives (for example, 444535f9378a3dfa1b8604bc9e05a303<\/code>). This deceptively simple mechanism unlocks a powerful tool for tracing and troubleshooting. By configuring NGINX Plus and all backend services to pass the $request_id<\/code> value, you can trace every request end‑to‑end. This sample config is for our frontend NGINX Plus server.<\/p>\n

upstream app_server {
\n    server 10.0.0.1:80;
\n}<\/p>\n
server {
\n    listen 80;
\n    add_header X-Request-ID $request_id; # Return to client
\n    location \/ {
\n        proxy_pass http:\/\/app_server;
\n        proxy_set_header X-Request-ID $request_id; # Pass to app server
\n    }
\n}<\/pre>\n
<\/code><\/p>\n
To configure NGINX Plus for request tracing, we first define the network location of the application server in the upstream<\/code><\/a> block. For simplicity we only show a single application server<\/code><\/a> here, but we would normally use several, for high availability and load balancing purposes. <\/p>\n
The server<\/code><\/a> block defines how NGINX Plus handles incoming HTTP requests. The listen<\/code><\/a> directive tells NGINX Plus to listen on port 80 – the default for HTTP traffic, but a production configuration normally uses use SSL\/TLS to protect data in transit<\/a>.<\/p>\n
The add_header<\/code><\/a> directive sends the $request_id<\/code> value back to the client as a custom header in the response. This is useful for testing and also for client applications that generate their own logs, such as mobile apps, so that a client‑side error can be matched precisely to the server logs.<\/p>\n
Finally, the location<\/code><\/a> block applies to the entire application space (\/<\/strong>) and the proxy_pass<\/code><\/a> directive simply proxies all requests to the application server. The proxy_set_header<\/code> <\/a> directive modifies the proxied request by adding an HTTP header that is passed to the application. In this case we create a new header called X‑Request‑ID<\/code>  and assign to it the value of the $request_id<\/code>  variable. So our application receives the request ID that was generated by NGINX Plus.<\/p>\n
Logging $request_id<\/code> End‑to‑End<\/h2>\n
Our goal with application tracing is to identify performance bottlenecks in the request‑processing lifecycle as part of application performance management. We do this by logging significant events during processing so we can analyze them later for unexpected or unreasonable delays.<\/p>\n
Configuring NGINX Plus<\/h3>\n
We start by configuring the frontend NGINX Plus server to include $request_id<\/code> in a custom logging format, trace<\/code>, which is used for the access_trace.log<\/strong> file.<\/p>\n
log_format trace<\/strong> '$remote_addr - $remote_user [$time_local] \"$request\" '
\n                 '$status $body_bytes_sent \"$http_referer\" \"$http_user_agent\" '
\n                 '\"$http_x_forwarded_for\" $request_id<\/strong>';<\/p>\n
upstream app_server {
\n    server 10.0.0.1;
\n}<\/p>\n
server {
\n    listen 80;
\n    add_header X-Request-ID $request_id; # Return to client
\n    location \/ {
\n        proxy_pass http:\/\/app_server;
\n        proxy_set_header X-Request-ID $request_id;        # Pass to app server
\n        access_log \/var\/log\/nginx\/access_trace.log trace<\/strong>; # Log $request_id
\n    }
\n}<\/pre>\n
<\/code><\/p>\n
Configuring the Backend Application<\/h3>\n
Passing the Request ID to your application is all well and good, but does not actually help with application tracing unless the application does something with it. In this example we have a Python application managed by uWSGI<\/a>. Let\u2019s modify the application entry point to grab the Request ID as a logging variable.<\/p>\n
from<\/span> uwsgi<\/span> import<\/span> set_logvar<\/span><\/p>\n
def<\/span> main<\/span>(environ, start_response):
\n    set_logvar<\/span>('requestid'<\/span>, environ['X_REQUEST_ID'<\/span>])<\/pre>\n
<\/code><\/p>\n
Then we can modify the uWSGI configuration to include the Request ID in the standard log file.<\/p>\n
log-format = %(addr) - %(user) [%(ltime)] \"%(method) %(uri) %(proto)\" %(status)
\n%(size) \"%(referer)\" \"%(uagent)\" %(requestid)<\/strong><\/pre>\n
<\/code><\/p>\n
With this configuration in place we are now producing log files which can be linked to a single request across numerous systems.<\/p>\n
Log entry from NGINX:<\/p>\n
172.17.0.1 - - [02\/Aug\/2016:14:26:33 +0000] \"GET \/ HTTP\/1.1\" 200 90 \"-\" \"-\" \"-\" 5f222ae5938482c32a822dbf15e19f0f<\/pre>\n
<\/code><\/p>\n
Log entry from application:<\/p>\n
192.168.91.1 - - [02\/Aug\/2016:14:26:34 +0000] \"GET \/ HTTP\/1.0\" 200 123 \"-\" \"-\" 5f222ae5938482c32a822dbf15e19f0f<\/pre>\n
<\/code><\/p>\n
By matching transactions against the Request ID fields, tools like Splunk<\/a> and Kibana<\/a> allow us to identify performance bottlenecks. For example, we can search for requests that took more than two seconds to complete. However, the default time resolution of one second in regular timestamps is insufficient for most real‑world analysis.<\/p>\n
High‑Precision Timing<\/h2>\n
In order to accurately measure requests end‑to‑end we need timestamps with millisecond‑level precision. By including the $msec<\/code> variable in log entries, we get millisecond resolution on the timestamp for each entry. Adding millisecond timestamps to our application log allows us to look for requests that took more than 200 milliseconds to complete rather than 2 seconds. <\/p>\n
But even then we are not getting the full picture, because NGINX Plus writes the $msec<\/code> timestamp only at the end of processing each request. Fortunately, there are several other NGINX Plus timing variables with millisecond precision that give us more insight into the processing itself:<\/p>\n