• 正确的记录日志

    正确的记录日志

    看过本章第一节的同学应该还记得，log_by_lua* 是一个请求经历的最后阶段。由于记日志跟应答内容无关，Nginx 通常在结束请求之后才更新访问日志。由此可见，如果我们有日志输出的情况，最好统一到 log_by_lua* 阶段。如果我们把记日志的操作放在 content_by_lua* 阶段，那么将线性的增加请求处理时间。

    在公司某个定制化项目中，Nginx 上的日志内容都要输送到 syslog 日志服务器。我们使用了lua-resty-logger-socket这个库。

    调用示例代码如下（有问题的）：

    1. -- lua_package_path "/path/to/lua-resty-logger-socket/lib/?.lua;;";
    2. --
    3. --    server {
    4. --        location / {
    5. --            content_by_lua_file lua/log.lua;
    6. --        }
    7. --    }
    9. -- lua/log.lua
    10. local logger = require "resty.logger.socket"
    11. if not logger.initted() then
    12.     local ok, err = logger.init{
    13.         host = 'xxx',
    14.         port = 1234,
    15.         flush_limit = 1,   --日志长度大于flush_limit的时候会将msg信息推送一次
    16.         drop_limit = 99999,
    17.     }
    18.     if not ok then
    19.         ngx.log(ngx.ERR, "failed to initialize the logger: ",err)
    20.         return
    21.     end
    22. end
    24. local msg = string.format(.....)
    25. local bytes, err = logger.log(msg)
    26. if err then
    27.     ngx.log(ngx.ERR, "failed to log message: ", err)
    28.     return
    29. end

    在实测过程中我们发现了些问题：

    • 缓存无效：如果 flush_limit 的值稍大一些（例如 2000），会导致某些体积比较小的日志出现莫名其妙的丢失，所以我们只能把 flush_limit 调整的很小
    • 自己拼写 msg 所有内容，比较辛苦

    那么我们来看lua-resty-logger-socket这个库的 log 函数是如何实现的呢，代码如下：

    1. function _M.log(msg)
    2.    ...
    4.     if (debug) then
    5.         ngx.update_time()
    6.         ngx_log(DEBUG, ngx.now(), ":log message length: " .. #msg)
    7.     end
    9.     local msg_len = #msg
    11.     if (is_exiting()) then
    12.         exiting = true
    13.         _write_buffer(msg)
    14.         _flush_buffer()
    15.         if (debug) then
    16.             ngx_log(DEBUG, "Nginx worker is exiting")
    17.         end
    18.         bytes = 0
    19.     elseif (msg_len + buffer_size < flush_limit) then  -- 历史日志大小+本地日志大小小于推送上限
    20.         _write_buffer(msg)
    21.         bytes = msg_len
    22.     elseif (msg_len + buffer_size <= drop_limit) then
    23.         _write_buffer(msg)
    24.         _flush_buffer()
    25.         bytes = msg_len
    26.     else
    27.         _flush_buffer()
    28.         if (debug) then
    29.             ngx_log(DEBUG, "logger buffer is full, this log message will be "
    30.                     .. "dropped")
    31.         end
    32.         bytes = 0
    33.         --- this log message doesn't fit in buffer, drop it
    35.         ...

    由于在 content_by_lua* 阶段变量的生命周期会随着请求的终结而终结，所以当日志量小于 flush_limit 的情况下这些日志就不能被累积，也不会触发 _flush_buffer 函数，所以小日志会丢失。

    这些坑回头看来这么明显，所有的问题都是因为我们把 lua/log.lua 用错阶段了，应该放到 log_by_lua* 阶段，所有的问题都不复存在。

    修正后：

    1.  lua_package_path "/path/to/lua-resty-logger-socket/lib/?.lua;;";
    3.     server {
    4.         location / {
    5.             content_by_lua_file lua/content.lua;
    6.             log_by_lua_file lua/log.lua;
    7.         }
    8.     }

    这里有个新问题，如果我的 log 里面需要输出一些 content 的临时变量，两阶段之间如何传递参数呢？

    方法肯定有，推荐下面这个：

    1.     location /test {
    2.         rewrite_by_lua_block {
    3.             ngx.say("foo = ", ngx.ctx.foo)
    4.             ngx.ctx.foo = 76
    5.         }
    6.         access_by_lua_block {
    7.             ngx.ctx.foo = ngx.ctx.foo + 3
    8.         }
    9.         content_by_lua_block {
    10.             ngx.say(ngx.ctx.foo)
    11.         }
    12.     }

    更多有关 ngx.ctx 信息，请看这里。