Using Lua in Nginx for unique request IDs and millisecond times in logs

Nginx is awesome, but it’s missing some common features. For instance, a common thing to add to access logs is a unique ID per request, so that you can track the flow of a single request through multiple services. Another thing it’s missing is the ability to log request_time in milliseconds, rather than seconds with a millisecond granularity. Using Lua, we can add these features ourselves.

I’ll show the whole solution, then I’ll break it down into parts:

http {
...

        map $host $request_time_ms {
            default '';
        }
        map $host $uuid {
            default '';
        }

        lua_package_path '/etc/nginx/uuid4.lua';
        init_by_lua '
            uuid4 = require "uuid4"
            math = require "math"
        ';

        log_by_lua '
          ngx.var.request_time_ms = math.floor(tonumber(ngx.var.request_time) * 1000)
        ';

        log_format mycustomformat '[$time_local] "$request" $status $request_length $bytes_sent $request_time_ms $uuid';
        access_log /var/log/nginx/access.log mycustomformat;

...
}

server {
...

  set_by_lua $uuid '
    if ngx.var.http_x_request_id == nil then
        return uuid4.getUUID()
    else
        return ngx.var.http_x_request_id
    end
  ';

...
}

It’s necessary to set variables before we use them in Lua. Using map is a trick to set variables in the http context (you can’t use set $variable ” in http). For the case of uuid, we are going to set it in the server section (during the rewrite context), but in case it’s not set, we want to avoid throwing errors. Here’s how we set these variables:

        map $host $request_time_ms {
            default '';
        }
        map $host $uuid {
            default '';
        }

Next we add a uuid4 library to our path, and include the libraries into our context:

        lua_package_path '/etc/nginx/uuid4.lua';
        init_by_lua '
            uuid4 = require "uuid4"
            math = require "math"
        ';

Using the log_by_lua function, we’ll set the request_time_ms variable we’ll use in the log_format config. This Lua function is called in the log context, before logs are written, allowing us to make the variables available to it:

        log_by_lua '
            ngx.var.request_time_ms = math.floor(tonumber(ngx.var.request_time) * 1000)
        ';

Next we set the log format, and use it for the access log:

        log_format mycustomformat '[$time_local] "$request" $status $request_length $bytes_sent $request_time_ms $uuid';
        access_log /var/log/nginx/access.log mycustomformat;

Lastly, we set the uuid during the rewrite context in the server section, using set_by_lua. To facilitate following a request across services, we’ll reuse the header if it’s already set. If the header isn’t set, then this request didn’t come from another service, so we’ll generate a UUID:

server {
...

  set_by_lua $uuid '
    if ngx.var.http_x_request_id == nil then
        return uuid4.getUUID()
    else
        return ngx.var.http_x_request_id
    end
  '

...
}

If you’re trusting this header data in any way, you should be sure to filter/restrict that header appropriately so that the client can’t change it.

Update (Thursday December 11 2014): Edited the post to move the uuid generation into the server section and using set_by_lua, so that the uuid can be set to/from the header to flow through the stacks properly. Shout out to Asher Feldman for working out a better solution with me.

  • asher

    Does calling uuid4.getUUID() from the log context mean it isn’t passed down the stack in this example?

    • Doh! Yep. That’s the case.

    • I really should be generating this in the request context so that I can properly add it to headers for proxypass. As we’ve discussed offline, it’s good to also set the uuid to the value of a header, if passed in so you can track it across services. I hadn’t added that to this post, but maybe I’ll update this post with that added.

  • Andrey

    Hey, thanks for a tip on using uuid4 with Lua.

    But, there is a catch: I get lots of duplicated uuids with that approach (almost every uuid is repeated at least once during a day). I’m not sure what’s causing it. Any ideas?

    • Hm. Interesting. Looks like this uuid library uses os.time(), which has a 1 second granularity. It’s likely better to use this lua library instead: https://github.com/Tieske/uuid

      • Andrey

        Cool, that might help.

        Meanwhile, I have several of observations:

        Duplication happens because I have several nginx workers that are spawned simultaneously and all get the same seed (as you suggested), every uid is generated once by each worker.

        The most correct way to handle this would be to use $pid or some other worker-specific info. But init_by_lua doesn’t have access to ngx context or $pid.

        Bleeding edge nginx has new method init_worker_by_lua (http://wiki.nginx.org/HttpLuaModule#init_worker_by_lua) which is exactly what we need. So, I’m considering upgrading to v0.9.5 or higher.

        Currently I solved uniqueness problem by appending $pid, so that $request_id = “$uuid-$pid”, this way request id is unique.

        • Awesome. Thanks for all the followup!

  • Cosmo Kramer

    or you could just do something like
    set_by_lua_block $uuid {
    if ngx.var.http_x_nl_request_id == nil then
    return io.open(“/proc/sys/kernel/random/uuid”):read()
    else
    return ngx.var.http_x_nl_request_id
    end
    }

  • Mayank

    I use this[https://gist.github.com/loneops/6de4709bc0ec7a343b81#file-uuid4-lua] with init_worker_by_lua_block, haven’t seen any UUID duplication yet!