Logging HTTP Request Metadata With Nginx, Lua, Logstash, and Elasticsearch

Introduction

This blog post shows how to use Nginx, Lua, Logstash, and Elasticsearch to log, store, and analyze HTTP request and response metadata. The metadata can either be generated by Nginx or by any upstream service that Nginx proxies to. For example, the metadata could be the request time, response size, or any information the upstream returns to log for purposes such as analytics.

First, a small example web service behind an Nginx server generates some data that we’d like to analyze via Elasticsearch. Nginx, with the help of Lua, parses and logs statistics returned by the example upstream service as it receives the response to send back to the client. This leads us to Logstash, which parses these logged statistics and forwards them to Elasticsearch for storage and analysis.

This post doesn’t cover how to install each individual tool. Please refer to their respective documentation for more information on that process.

A Small Example Upstream Service

The example upstream service below uses Python 2.7 and flask. It exposes a single endpoint that adds an HTTP header to the response which contains additional metadata to log for later analysis.

from calendar import timegm<br>from datetime import datetime, timedelta import json<br>from flask import Flask<br><br><br>app = Flask(__name__)<br><br><br>@app.route("/")<br>def metadata():<br>    request_start = datetime.utcnow() - timedelta(seconds=5)<br>    metadata = {<br>        'duration': (datetime.utcnow() - request_start).total_seconds(),<br>        'request_id': 456,<br>        'start': timegm(request_start.timetuple()),<br>        'user_id': 123,<br>    }<br>    return ('Hello!', {'X-Service-Metadata': json.dumps(metadata)}) 

Now that the service includes metadata in its HTTP response, Nginx can be configured to log it.

Logging With Nginx and Lua

Logstash works out of the box with structured JSON objects, so it’s ideal for Nginx to parse the upstream response’s HTTP headers and log the data in a JSON format. This avoids having to configure a Logstash pattern that matches a custom log line format.

Below is the first half of an Nginx configuration file, which sets up the format to log data in:

lua_package_path "/usr/local/lib/lua/?.lua;;";

upstream service {
    server 127.0.0.1:5000;
}

init_by_lua '
    JSON = require "JSON"
';

# The log message format to use
log_format log_json
    '{'
        '"timestamp": "$time_iso8601",'
        '"request_time": $request_time,'
        '"remote_addr": "$remote_addr",'
        '"x_forwarded_for": "$http_x_forwarded_for",'
        '"vhost": "$server_name",'
        '"method": "$request_method",'
        '"uri": "$uri",'
        '"query_parameters": "$query_string",'
        '"protocol": "$server_protocol",'
        '"status": $status,'
        '"bytes_sent": $body_bytes_sent,'
        '"request_length": $request_length,'
        '"request_id": "$request_id",'
        '"referer": "$http_referer",'
        '"user_agent": "$http_user_agent",'
        '"user_id": $user_id,'
        '"duration": $duration'
    '}';

The configuration file above first specifies lua_package_path to ensure Nginx can load and cache the third-party JSON module in the init_by_lua directive.

It then defines a log format for Nginx’s access log that happens to be a JSON string template as well, with Nginx variable names that will later be interpolated with corresponding values.

Nginx 1.11.8+ also supports the option escape=json, although this shouldn’t be included if the data being logged is itself in a JSON format, such as an array or nested object. If that’s the case, it’s better to encode the JSON data via Lua to avoid it being escaped twice. For example, log the JSON array ['dp1', 'dp2', 'dp3'] as shown below:

log_format log_json
    '{'
        ...
        '"an_array": $json_array'
    '}';

set $json_array '[]';

header_filter_by_lua '
    local metadata = json:decode(ngx.var.metadata)
    ngx.var.json_array = json:encode(metadata["json_array"])
';

Following the log format, the Nginx configuration specifies a server block to handle the incoming request and outgoing response. It sets default values for the metadata to log as well, to avoid errors if the metadata in the response is entirely absent. It’s also possible to define different log formats for individual servers or event locations if the response data varies by location.

server {
  listen 8080 default_server;
  server_name "metadata";

  # Default values for the metadata we are interested in
  set $duration -1;
  set $metadata '';
  set $request_id -1;
  set $user_id 0;

  # Configure how and where to log requests
  access_log /var/log/nginx/access.log log_json;

  location / {
    access_by_lua '
      ngx.req.set_header("Host", "metadata")
    ';

    proxy_pass http://service/;

    # This context allows us to access and modify the response of the upstream
    # service, which will then be sent back to the client.
    header_filter_by_lua '
      ngx.var.metadata = ngx.header["X-Service-Metadata"]
      ngx.header["X-Service-Metadata"] = nil  -- Don\'t want to expose internal data

      if ngx.var.metadata then
        local json = require "JSON"
        local metadata = json:decode(ngx.var.metadata)
        ngx.var.duration = metadata["duration"]
        ngx.var.request_id = metadata["request_id"]
        ngx.var.user_id = metadata["user_id"]
      end
    ';
  }
}

The location block includes the logic to retrieve the actual metadata and set the Nginx variables. Within it, the header_filter_by_lua block’s context has access to the upstream response HTTP response.

The Lua code above parses the raw JSON string received in the X-Service-Metadata header and assigns it to a local variable, metadata, as a Lua table. Individual fields can now easily be assigned to their corresponding Nginx variables.

Now that the metadata is being logged to the access log, Logstash can read and parse it to store in Elasticsearch.

Parsing and Forwarding With Logstash

Below is the Logstash configuration to handle the Nginx log entries:

input {
  file {
    path => ["/var/log/nginx/access.log"]
    mode => "tail"
  }
} 

filter {
  json {
    skip_on_invalid_json => true
    source               => "message"
    remove_field         => [ "message" ]
  }

  date {
    match => [ "timestamp", "ISO8601" ]
  }
  mutate {
    remove_field => [ "timestamp" ]
  }
}

output {
  elasticsearch {
    hosts              => ["http://localhost:9200"]
  }
}

Logstash’s json filter plugin easily parses the JSON log entries in the file. The original message field with the raw JSON string is no longer necessary after the parsed data is available in the event.

A date filter sets @timestamp to be the original message’s timestamp rather than when Logstash received the event. The configuration then removes the original timestamp field similar to the original message field.

The Logstash output sends filtered events to Elasticsearch using Logstash’s default index template and index-naming pattern. Please refer to the Elasticsearch plugin documentation for more information on configuring index-related settings.

Storage and Analysis With Elasticsearch

The default Elasticsearch configuration is sufficient for our example. With everything set up, the Elasticsearch Query API available on port 9200 enables us to query the Logstash indices. For example, to get a list of available indices:

curl -s http://127.0.0.1:9200/_cat/indices?v

An example query on the Logstash index:

curl -s -H 'Content-Type: application/json' \ 
  http://127.0.0.1:9200/logstash-2019.02.20/_search -d \
  '{"query": {"match": {"method": "GET"}}}' | \
  jq '[ .hits.hits[] | ._source | {"user_id": .user_id, "request_length": .request_length, "duration": .duration}]'

[
  {
    "user_id": 123,
    "request_length": 78,
    "duration": 5.000019
  },
  {
    "user_id": 123,
    "request_length": 78,
    "duration": 5.000007
  },
  ...
  {
    "user_id": 123,
    "request_length": 78,
    "duration": 5.00001
  }
]

Learn more here.