In one of our projects we wanted to capture and document incoming traffic to our server. The requirements for recording/capturing the incoming traffic were as below
- Capture both GET and POST requests
- Capture only certain locations
- Back-end service involved were PHP, Java and some NodeJS also
- Capture Response Code, Response Text and Duration also
- Mask certain sensitive data like emails, credit card numbers
The plan was to use this data for creating simulated production replay and make sure any changes made to code doesn’t impact existing working flows.
Our first thought was to update our code to log the calls, but this meant changing different projects and unnecessary code changes to production for our experimentation.
So we wanted to come up with a more generic approach, which is when I stumbled upon LuaJIT and its integration with Nginx. I have already discussed about setting up the same in a previous article
We would use openresty/openresty docker image for starting our request capturing. The available features for Nginx lua module can be looked upon at openresty/lua-nginx-module.
We are interested in a log_by_lua_file directive, which allows us to specify a lua file which would be executed when request completes.
We will create a very simple server which will echo the URL back as its content for our testing purpose.
Sample Server Config
First we create a docker-compose.yml file
docker-compose.yml
version: '2'
services:
nginx:
image: openresty/openresty:jessie
ports:
- "8080:80"
volumes:
- ./nginx.conf:/usr/local/openresty/nginx/conf/nginx.conf
- ./nginx.conf.d/:/usr/local/openresty/nginx/conf/conf.d/
nginx.conf
A simpe nginx.conf which loads all *.conf file in conf.d directory
worker_processes 1;
events {
worker_connections 1024;
}
http {
include mime.types;
default_type application/octet-stream;
sendfile on;
keepalive_timeout 65;
include conf.d/*.conf;
}
main.conf
This config file will create a main front facing server on port 80 and another dummy echo server on port 8080. Each request would be recieved on port 80 and proxy passe to port 8080
nginx.conf.d/main.conf
server {
listen 80;
location / {
proxy_pass http://127.0.0.1:8081/;
}
}
server {
listen 8081;
location / {
add_header Content-Type "text/html";
echo "$request_method $uri $args";
}
}
Testing the server
$ curl "http://192.168.33.100:8080/abc?x=2&y=z"
GET /abc x=2&y=z
Note:
192.168.33.100is the docker host ip in my case
Now let us update our main.conf to use the log_by_lua_file
server {
listen 80;
# This will make sure that any changes to the lua code file is picked up
# without reloading or restarting nginx
lua_code_cache off;
location / {
proxy_pass http://127.0.0.1:8081/;
log_by_lua_file lua/request_logger.lua;
}
}
server {
listen 8081;
location / {
add_header Content-Type "text/html";
echo "$request_method $uri $args";
}
}
lua/request_logger.lua
ngx.log(ngx.ERR, "REQUEST capturing started")
json = require("json")
function getval(v, def)
if v == nil then
return def
end
return v
end
local data = {request={}, response={}}
local req = data["request"]
local resp = data["response"]
req["host"] = ngx.var.host
req["uri"] = ngx.var.uri
req["headers"] = ngx.req.get_headers()
req["time"] = ngx.req.start_time()
req["method"] = ngx.req.get_method()
req["get_args"] = ngx.req.get_uri_args()
req["post_args"] = ngx.req.get_post_args()
req["body"] = ngx.var.request_body
content_type = getval(ngx.var.CONTENT_TYPE, "")
resp["headers"] = ngx.resp.get_headers()
resp["status"] = ngx.status
resp["duration"] = ngx.var.upstream_response_time
resp["time"] = ngx.now()
resp["body"] = ngx.var.response_body
ngx.log(ngx.CRIT, json.encode(data));
We have used require("json") in our code, but json is not a built-in lua module. The good part about the openresty docker image is that it comes pre-packaged with luarocks. LuaRocks is a package manager for Lua. Now we need to install a json module, so we introduce a Dockerfile as well to customize the openresty image
Dockerfile
FROM openresty/openresty:jessie
RUN luarocks install luajson
We update our docker-compose.yml to build the Dockerfile instead of using a direct image
docker-compose.yml
version: '2'
services:
nginx:
#image: openresty/openresty
build: .
ports:
- "8080:80"
volumes:
- ./nginx.conf:/usr/local/openresty/nginx/conf/nginx.conf
- ./nginx.conf.d/:/usr/local/openresty/nginx/conf/conf.d/
- ./lua:/usr/local/openresty/nginx/lua
Once we run the latest composition and hit a test url again
$ curl "http://192.168.33.100:8080/abc?x=2&y=z"
GET /abc x=2&y=z
We would see a entry in our docker logs
[crit] 5#5: *4 [lua] request_logger.lua:35: {"response":{"time":1495433636.68,"headers":{"connection":"close","content-type":"text\/html","transfer-encoding":"chunked"},"status":200,"duration":"0.000"},"request":{"host":"192.168.33.100","uri":"\/abc","post_args":{},"method":"GET","headers":{"host":"192.168.33.100:8080","accept":"*\/*","user-agent":"curl\/7.51.0"},"get_args":{"y":"z","x":"2"},"time":1495433636.68}} while logging request, client: 192.168.33.1, server: , request: "GET /abc?x=2&y=z HTTP/1.1", upstream: "http://127.0.0.1:8081/abc?x=2&y=z", host: "192.168.33.100:8080"
If we do a POST to the same url
$ curl -X POST -d name=tarun "http://192.168.33.100:8080/abc?x=2&y=z"
POST /abc x=2&y=z
The log entry would be
[crit] 5#5: *7 [lua] request_logger.lua:35: {"response":{"time":1495434620.413,"headers":{"connection":"close","content-type":"text\/html","transfer-encoding":"chunked"},"status":200,"duration":"0.000"},"request":{"host":"192.168.33.100","body":"name=tarun","uri":"\/abc","post_args":{"name":"tarun"},"method":"POST","headers":{"host":"192.168.33.100:8080","content-length":"10","user-agent":"curl\/7.51.0","accept":"*\/*","content-type":"application\/x-www-form-urlencoded"},"get_args":{"y":"z","x":"2"},"time":1495434620.413}} while logging request, client: 192.168.33.1, server: , request: "POST /abc?x=2&y=z HTTP/1.1", upstream: "http://127.0.0.1:8081/abc?x=2&y=z", host: "192.168.33.100:8080
We are able to capture a lot of details about the request, but not the response body as of now. Response doesn’t get stored anywhere by default. So we need to put some code around to gather response body. Nginx uses buffered response, so we have to collect each buffer and combine into a single one to get a complete response.
To do this we update our main.conf and add a body_filter_by_lua_block directive.
#we must declare variables first, we cannot create vars in lua
set $response_body '';
body_filter_by_lua_block {
-- arg[1] contains a chunk of response content
local resp_body = string.sub(ngx.arg[1], 1, 1000)
ngx.ctx.buffered = string.sub((ngx.ctx.buffered or "") .. resp_body, 1, 1000)
-- arg[2] is true if this is the last chunk
if ngx.arg[2] then
ngx.var.response_body = ngx.ctx.buffered
end
}
Then we update our request_logger.lua to include the code for adding body
resp["body"] = ngx.var.response_body
Now if we restart and run the test again, the log entry would be
[crit] 5#5: *1 [lua] request_logger.lua:35: {"response":{"time":1495436040.177,"body":"POST \/abc x=2&y=z\n","headers":{"connection":"close","content-type":"text\/html","transfer-encoding":"chunked"},"status":200,"duration":"0.000"},"request":{"host":"192.168.33.100","body":"name=tarun","uri":"\/abc","post_args":{"name":"tarun"},"method":"POST","headers":{"host":"192.168.33.100:8080","content-length":"10","user-agent":"curl\/7.51.0","accept":"*\/*","content-type":"application\/x-www-form-urlencoded"},"get_args":{"y":"z","x":"2"},"time":1495436040.177}} while logging request, client: 192.168.33.1, server: , request: "POST /abc?x=2&y=z HTTP/1.1", upstream: "http://127.0.0.1:8081/abc?x=2&y=z", host: "192.168.33.100:8080"
As you would notice "body":"POST \/abc x=2&y=z\n" also got captured. Now we can easily use rsyslog to read the nginx logs and pass this information onto some other stack like ElasticSearch or Kafka etc’
You can download the code for above article at tarunlalwani/nginx-lua-request-capture.git