最近出了個(gè)故障，有個(gè)接口的請(qǐng)求居然出現(xiàn)了長(zhǎng)達(dá)幾十秒的處理時(shí)間，由于日志缺乏，網(wǎng)絡(luò)故障也解除了，就沒法再重現(xiàn)這個(gè)故障了。為了可以在下次出現(xiàn)問題的時(shí)候能追查到問題，所以需要添加一些追蹤日志。
添加這些追蹤日志，我希望能夠達(dá)到如下幾點(diǎn)：

1、只有請(qǐng)求超過一定時(shí)間才記錄，不然請(qǐng)求太多，系統(tǒng)扛不住

2、添加的代碼可以盡量的少

3、對(duì)接口的影響盡量小，比如不影響實(shí)際時(shí)延，甚至記錄日志時(shí)出現(xiàn)了錯(cuò)誤，也不影響系統(tǒng)正常運(yùn)行

openresty這套工具，可以在nginx處理請(qǐng)求的每一個(gè)階段介入，編寫代碼進(jìn)行邏輯處理。其可介入的流程如下圖：

log Phase這個(gè)階段，就是openresty能處理的最后階段。到這個(gè)階段的時(shí)候，實(shí)際上請(qǐng)求的響應(yīng)已經(jīng)發(fā)送給客戶端了。所以使用 log_by_lua (知乎真特么蛋疼啊，左右下劃線就自動(dòng)斜體，還沒提供轉(zhuǎn)義功能)

log Phase這個(gè)階段，就是openresty能處理的最后階段。到這個(gè)階段的時(shí)候，實(shí)際上請(qǐng)求的響應(yīng)已經(jīng)發(fā)送給客戶端了。另外我也測(cè)試過了，即使在這個(gè)階段發(fā)生了錯(cuò)誤，如 io 錯(cuò)誤，也不會(huì)影響接口的正常響應(yīng)，所以使用 log_by_lua 很是符合需求。

好處不止如此， log_by_lua是一個(gè)請(qǐng)求的最后處理階段，那么只要請(qǐng)求正常進(jìn)行，比如會(huì)走到這一步，因此，在這一步，我們就知道了這個(gè)請(qǐng)求的耗時(shí)了。另外，則是我們的代碼里有不少的 ngx.exit ，如果是在業(yè)務(wù)邏輯處理的時(shí)候就記錄日志，那么每個(gè)出現(xiàn) ngx.exit 的地方，都需要插入寫日志到硬盤的操作，大大增加了代碼量。

寫日志到硬盤的這一步操作，可以在 log_by_lua 這個(gè)階段來(lái)完成，剩下的另一個(gè)問題就是每一步記錄的日志如何傳遞到 log_by_lua 這一階段來(lái)了。

我處理的方式是使用ngx.ctx, 每一個(gè)請(qǐng)求，都會(huì)有自己獨(dú)立的 ngx.ctx, 這個(gè) ngx.ctx 會(huì)貫穿整個(gè)請(qǐng)求的始終，簡(jiǎn)單的log函數(shù)如下：

logger.lua -------------------------- local _M = {}function _M.log(format, ...)if ngx.ctx.log_slot == nil thenngx.ctx.log_slot = {}endarg = {...}local logstr = ""if arg == nil thenlogstr = formatelselogstr = string.format(format, unpack(arg))endlogstr = logstr .. "\t" .. ngx.now()table.insert(ngx.ctx.log_slot, logstr) endreturn _M

到了 log_by_lua 階段要把追蹤日志寫入到硬盤里，處理代碼如下：

log_slot.lua --------------------- local request_time = ngx.var.request_time if request_time < 1 thenreturn --- 小于1秒的請(qǐng)求不記錄 end local slot = ngx.ctx.log_slot if slot == nil or type(slot) ~= "table" thenreturn 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模塊，即只到某個(gè)請(qǐng)求。所以你可以在nginx.conf 里的http里添加:

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

也可以在server的配置里添加：

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

更能直接在某個(gè)接口里添加：

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

http里添加，則對(duì)所有的server； server里添加，則只針對(duì)此server；location里添加，就只針對(duì)這個(gè)接口。

但是，比較坑爹的是，log_by_lua 不像 access log，可以多層級(jí)使用。log_by_lua 在某層使用了之后，上層的 log_by_lua 就對(duì)此一層無(wú)效了。比如 /v1/test 接口添加了 log_by_lua， 那么 http 或者 server 里添加的 log_by_lua 在接受/v1/test接口的請(qǐng)求時(shí)都不會(huì)被用到。

正是因?yàn)檫@個(gè)坑，浪費(fèi)了我不少的時(shí)間來(lái)解決。我們的系統(tǒng)里，http 模塊是配置了 log_by_lua 的，用來(lái)做接口監(jiān)控，監(jiān)控返回的錯(cuò)誤碼，處理的時(shí)延等。如果我在 /v1/test 里添加了只針對(duì) /v1/test 的追蹤日志，那么接口監(jiān)控就無(wú)法正常運(yùn)行了。

不過天無(wú)絕人之路，我想到了一個(gè)處理方法如下：

monitor_log.lua --------------------- local _M = {}function _M.monitor_log()local f = _M.api_monitor_log_funcif f == nil thenf, err = loadfile("/code/monitor.lua")if f == nil thenngx.log(ngx.ERR, "/code/monitor.lua, ", err)--- 如果不存在接口監(jiān)控，直接給一個(gè)空函數(shù)f = function() endend_M.api_monitor_log_func = fendlocal status, err = pcall(f)if not status thenngx.log(ngx.ERR, "run api monitor /code/monitor.lua failed", err)end endreturn _M

修改log_slot.lua代碼如下：

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

如上，就可以進(jìn)行其他層級(jí)的 log_by_lua 代碼運(yùn)行了，皆大歡喜，問題解決了。
當(dāng)系統(tǒng)并發(fā)請(qǐng)求較低的時(shí)候，worker夠用，則使用 log_by_lua 可以說(shuō)是毫無(wú)壞處。當(dāng)然，一旦 log_by_lua 出現(xiàn)了故障，如死循環(huán)，則會(huì)長(zhǎng)時(shí)間占用worker，造成整個(gè)系統(tǒng)崩潰掉。

總結(jié)

以上是生活随笔為你收集整理的openresty 日志输出的处理的全部?jī)?nèi)容，希望文章能夠幫你解決所遇到的問題。

如果覺得生活随笔網(wǎng)站內(nèi)容還不錯(cuò)，歡迎將生活随笔推薦給好友。