openresty 日志输出的处理

最近出了个故障，有个接口的请求竟然出现了长达几十秒的处理时间，因为日志缺少，网络故障也解除了，就无法再重现这个故障了。为了能够在下次出现问题的时候能追查到问题，因此须要添加一些追踪日志。
添加这些追踪日志，我但愿可以达到以下几点：

一、只有请求超过必定时间才记录，否则请求太多，系统扛不住

二、添加的代码能够尽可能的少

三、对接口的影响尽可能小，好比不影响实际时延，甚至记录日志时出现了错误，也不影响系统正常运行

openresty这套工具，能够在nginx处理请求的每个阶段介入，编写代码进行逻辑处理。其可介入的流程以下图：

log Phase这个阶段，就是openresty能处理的最后阶段。到这个阶段的时候，实际上请求的响应已经发送给客户端了。因此使用 log_by_lua (知乎真特么蛋疼啊，左右下划线就自动斜体，还没提供转义功能)

log Phase这个阶段，就是openresty能处理的最后阶段。到这个阶段的时候，实际上请求的响应已经发送给客户端了。另外我也测试过了，即便在这个阶段发生了错误，如 io 错误，也不会影响接口的正常响应，因此使用 log_by_lua 非常符合需求。

好处不止如此， log_by_lua是一个请求的最后处理阶段，那么只要请求正常进行，好比会走到这一步，所以，在这一步，咱们就知道了这个请求的耗时了。另外，则是咱们的代码里有很多的 ngx.exit ，若是是在业务逻辑处理的时候就记录日志，那么每一个出现 ngx.exit 的地方，都须要插入写日志到硬盘的操做，大大增长了代码量。

写日志到硬盘的这一步操做，能够在 log_by_lua 这个阶段来完成，剩下的另外一个问题就是每一步记录的日志如何传递到 log_by_lua 这一阶段来了。

我处理的方式是使用ngx.ctx, 每个请求，都会有本身独立的 ngx.ctx, 这个 ngx.ctx 会贯穿整个请求的始终，简单的log函数以下：

logger.lua
--------------------------
local _M = {}

function _M.log(format, ...)
   if ngx.ctx.log_slot == nil then
        ngx.ctx.log_slot = {}
   end
   arg = {...}
   local logstr = ""
   if arg == nil then
       logstr = format
   else
       logstr = string.format(format, unpack(arg))
   end
   logstr = logstr .. "\t" .. ngx.now()
   table.insert(ngx.ctx.log_slot, logstr)
end

return _M

到了 log_by_lua 阶段要把追踪日志写入到硬盘里，处理代码以下：

log_slot.lua
---------------------
local request_time = ngx.var.request_time
if request_time < 1 then
    return  --- 小于1秒的请求不记录
end
local slot = ngx.ctx.log_slot
if slot == nil or type(slot) ~= "table" then
    return
end
local logs = table.concat(slot, "\n")
local f = assert(io.open("/logs/trace", "a"))
f:write(logs .. "\n")
f:close()

log_by_lua 能够用在 http 模块，也能够用在server模块，也能直接精确到location模块，即只到某个请求。因此你能够在nginx.conf 里的http里添加:

http{
    log_by_lua_file '/code/log_slot.lua';
}

也能够在server的配置里添加：

server {
    log_by_lua_file '/code/log_slot.lua';
}

更能直接在某个接口里添加：

/v1/test {
    content_by_lua_file '/code/v1/test.lua';
    log_by_lua_file '/code/log_slot.lua';
}

http里添加，则对全部的server； server里添加，则只针对此server；location里添加，就只针对这个接口。

可是，比较坑爹的是，log_by_lua 不像 access log，能够多层级使用。log_by_lua 在某层使用了以后，上层的 log_by_lua 就对此一层无效了。好比 /v1/test 接口添加了 log_by_lua， 那么 http 或者 server 里添加的 log_by_lua 在接受/v1/test接口的请求时都不会被用到。

正是由于这个坑，浪费了我很多的时间来解决。咱们的系统里，http 模块是配置了 log_by_lua 的，用来作接口监控，监控返回的错误码，处理的时延等。若是我在 /v1/test 里添加了只针对 /v1/test 的追踪日志，那么接口监控就没法正常运行了。

不过天无绝人之路，我想到了一个处理方法以下：

monitor_log.lua
---------------------
local _M = {}

function _M.monitor_log()
    local f = _M.api_monitor_log_func
    if f == nil then
        f, err = loadfile("/code/monitor.lua")
        if f == nil then
            ngx.log(ngx.ERR, "/code/monitor.lua, ", err)
            --- 若是不存在接口监控，直接给一个空函数
            f = function() end
        end
        _M.api_monitor_log_func = f
    end
    local status, err = pcall(f)
    if not status then
        ngx.log(ngx.ERR, "run api monitor /code/monitor.lua failed", err)
    end
end

return _M

修改log_slot.lua代码以下：

local logger = require "code.monitor"
local request_time = ngx.var.request_time
logger.monitor_log()
if request_time < 1 then
    return  --- 小于1秒的请求不记录
end
local slot = ngx.ctx.log_slot
if slot == nil or type(slot) ~= "table" then
    return
end
local logs = table.concat(slot, "\n")
local f = assert(io.open("/logs/trace", "a"))
f:write(logs .. "\n")
f:close()

如上，就能够进行其余层级的 log_by_lua 代码运行了，皆大欢喜，问题解决了。当系统并发请求较低的时候，worker够用，则使用 log_by_lua 能够说是毫无坏处。固然，一旦 log_by_lua 出现了故障，如死循环，则会长时间占用worker，形成整个系统崩溃掉。