diff --git a/doc/acid/category_log.md b/doc/acid/category_log.md new file mode 100644 index 0000000..ae30fa9 --- /dev/null +++ b/doc/acid/category_log.md @@ -0,0 +1,121 @@ + + +# Table of Content + +- [Name](#name) +- [Status](#status) +- [Description](#description) +- [Synopsis](#synopsis) +- [Methods](#methods) + - [new](#new) + - [write_log](#write_log) +- [Author](#author) +- [Copyright and License](#copyright-and-license) + + + +# Name + +acid.category_log + +# Status + +This library is considered production ready. + +# Description + +This lua module is used to write error log of different requst to +different log file. Error logs can be separated by response status +or something else. + +It is implementd by wrapping the ngx.log function, +besides logging to the original log file normally, it also save logs +in memory, and at nginx log phase, it finally write to a proper log file. + +# Synopsis + +```lua +# nginx.conf + +http { + init_worker_by_lua_block { + local category_log = require('acid.category_log') + + local get_category_file = function() + return string.format('front_%d_error.log', ngx.status) + end + + local opts = { + get_category_file = get_category_file, + max_repeat_n = 64, + max_entry_n = 256, + } + + category_log.wrap_log(opts) + } + + server { + ... + + log_by_lua_block { + local category_log = require('acid.category_log') + category_log.write_log() + } + + location = /t { + rewrite_by_lua_block { + ... + ngx.log(ngx.ERR, 'test_error_log') + ngx.status = 500 + ngx.exit(ngx.HTTP_OK) + } + } + } +} +``` + +# Methods + +## new + +**syntax**: +`category_log.wrap_log(opts)` + +**arguments**: + +- `opts`: + The options table should contain the following fields: + + - `get_category_file`: a callback function, have no argument, + should return the log file to which the logs of this request + should write, return nil indicate not write to any log file. + + - `max_repeat_n`: set how many logs on same source file and same + line number will be saved. + + - `max_entry_n`: set the max total number of logs to save. + + - `log_level`: set level of logging, the default is `ngx.INFO`. + +**return**: +do not have return value + +## write_log + +**syntax**: +`category_log:write_log()` + +write logs saved in memory to proper log file. + +**return**: +do not have return value + +# Author + +Renzhi (任稚) + +# Copyright and License + +The MIT License (MIT) + +Copyright (c) 2015 Renzhi (任稚) diff --git a/lib/acid/category_log.lua b/lib/acid/category_log.lua new file mode 100644 index 0000000..d7a25e7 --- /dev/null +++ b/lib/acid/category_log.lua @@ -0,0 +1,199 @@ +local strutil = require('acid.strutil') +local time = require('acid.time') + + +local to_str = strutil.to_str + + +local _M = {} + + +local level_to_str = { + [ngx.DEBUG] = '[debug]', + [ngx.INFO] = '[info]', + [ngx.NOTICE] = '[notice]', + [ngx.WARN] = '[warn]', + [ngx.ERR] = '[error]', + [ngx.CRIT] = '[crit]', + [ngx.ALERT] = '[alert]', + [ngx.EMERG] = '[emerg]', +} + + +local function write_to_file(log_path, log_ctx) + if log_ctx == nil then + return + end + + table.insert(log_ctx.log_entry, to_str(log_ctx.counter) .. '\n') + + local data = table.concat(log_ctx.log_entry, '') + + local f = io.open(log_path, 'a+') + f:write(data) + f:close() +end + + +local function feed_log_entry(level, repeat_n, prefix, args) + local log_ctx = ngx.ctx.category_log + local log_entry = log_ctx.log_entry + + if #log_entry >= _M.max_entry_n then + return + end + + if repeat_n > _M.max_repeat_n then + return + end + + local time_str = time.format(ngx.time(), 'nginxerrorlog') + local level_str = level_to_str[level] + + local parts = {time_str, level_str, ngx.worker.pid(), prefix} + + for _, v in ipairs(args) do + table.insert(parts, tostring(v)) + end + + local log_line = table.concat(parts, ', ') .. '\n' + + table.insert(log_entry, log_line) + + return +end + + +local function _get_request_id() + local request_id = ngx.var.requestid + return request_id +end + + +local function get_request_id() + local ok, request_id = pcall(_get_request_id) + if not ok then + return + end + + return request_id +end + + +local function log_by_category(level, src_file_name, line_number, prefix, args) + local log_ctx = ngx.ctx.category_log + + local counter = log_ctx.counter + + local ident = string.format('%s_%d', src_file_name, line_number) + counter[ident] = (counter[ident] or 0) + 1 + + local repeat_n = counter[ident] + + feed_log_entry(level, repeat_n, prefix, args) + + return +end + + +local function _category_log(level, ...) + if ngx.ctx.category_log == nil then + ngx.ctx.category_log = { + -- contain log entries. + log_entry = {}, + -- save how many times a log on same source file + -- and same line nubmer have repeated. + counter = {}, + } + end + + local log_ctx = ngx.ctx.category_log + + if log_ctx.request_id == nil then + log_ctx.request_id = get_request_id() + end + + -- get info of function at level 4 of the call stack, which is the + -- function called ngx.log + local debug_info = debug.getinfo(4) + local path_parts = strutil.rsplit(debug_info.short_src, '/', + {plain=true, maxsplit=1}) + local src_file_name = path_parts[#path_parts] + local line_number = debug_info.currentline + local func_name = debug_info.name + + local prefix = string.format('%s %s:%d %s() ', log_ctx.request_id, + src_file_name, line_number, func_name) + + _M.origin_log(level, prefix, ...) + + if level > _M.log_level then + return + end + + log_by_category(level, src_file_name, line_number, prefix, {...}) + + return +end + + +local function category_log(level, ...) + local ok, err = pcall(_category_log, level, ...) + if not ok then + _M.origin_log(ngx.ERR, 'failed to do category log: %s' .. err) + end +end + + +function _M.wrap_log(opts) + if _M.origin_log ~= nil then + ngx.log(ngx.ERR, 'ngx.log can be wrapped only once') + return + end + + _M.origin_log = ngx.log + + if opts == nil then + opts = {} + end + + _M.get_category_file = opts.get_category_file + _M.max_repeat_n = opts.max_repeat_n + _M.max_entry_n = opts.max_entry_n + _M.log_level = opts.log_level or ngx.INFO + + ngx.log = category_log + + return +end + + +local function write_log_timer(premature, log_path, log_ctx) + if premature then + _M.origin_log(ngx.WARN, 'write log timer premature') + return + end + + write_to_file(log_path, log_ctx) +end + + +function _M.write_log() + local log_ctx = ngx.ctx.category_log + if log_ctx == nil then + return + end + + local log_path = _M.get_category_file() + if log_path == nil then + return + end + + local ok, err = ngx.timer.at(0, write_log_timer, log_path, log_ctx) + if not ok then + _M.origin_log(ngx.ERR, 'failed to add write log timer: ' .. err) + end +end + + +return _M diff --git a/t/category_log_test.t b/t/category_log_test.t new file mode 100644 index 0000000..8c2fd8d --- /dev/null +++ b/t/category_log_test.t @@ -0,0 +1,294 @@ +# vim:set ft=lua ts=4 sw=4 et: + +use Test::Nginx::Socket 'no_plan'; + +use Cwd qw(cwd); +my $pwd = cwd(); + +no_long_string(); + +our $HttpConfig = qq{ + lua_package_path "$pwd/lib/?.lua;;"; + lua_package_cpath "$pwd/lib/?.so;;"; + init_worker_by_lua_block { + local category_log = require('acid.category_log') + local function get_category_file() + return ngx.ctx.category_log_file + end + + local opts = { + get_category_file = get_category_file, + max_repeat_n = 2, + max_entry_n = 4, + } + category_log.wrap_log(opts) + } + + log_by_lua_block { + local category_log = require('acid.category_log') + category_log.write_log() + } +}; + +run_tests(); + +__DATA__ + +=== TEST 1: test original error log +--- http_config eval: $::HttpConfig +--- config + location /t { + lua_check_client_abort on; + + rewrite_by_lua_block { + ngx.log(ngx.ERR, 'test_error_log', 'foo', 'bar') + ngx.exit(ngx.HTTP_OK) + } + } + +--- request +GET /t + +--- error_log +test_error_logfoobar + + +=== TEST 2: test category log basic +--- http_config eval: $::HttpConfig +--- config + location /t { + lua_check_client_abort on; + + rewrite_by_lua_block { + ngx.ctx.category_log_file = 'category_log_test_2.error.log' + ngx.log(ngx.ERR, 'test_error_log', 'foo', 'bar') + ngx.say('ok') + ngx.exit(ngx.HTTP_OK) + } + } + + location /check_category_log { + rewrite_by_lua_block { + local log_file_name = 'category_log_test_2.error.log' + os.execute('echo 3 > /proc/sys/vm/drop_caches') + os.execute('sync') + + ngx.sleep(1) + local f, err = io.open(log_file_name, 'r') + if err ~= nil then + ngx.say('open file error: ' .. err) + ngx.exit(ngx.HTTP_OK) + end + + local data = f:read('*a') + + local expected = 'test_error_log, foo, bar' + local m, err = ngx.re.match(data, expected) + if err ~= nil then + ngx.say('ngx.re.match error: ' .. err) + ngx.exit(ngx.HTTP_OK) + end + + if m == nil then + ngx.say('not match') + ngx.exit(ngx.HTTP_OK) + end + + if m[0] ~= expected then + ngx.say('not in category log') + ngx.exit(ngx.HTTP_OK) + end + + ngx.say('check ok') + + os.remove(log_file_name) + ngx.exit(ngx.HTTP_OK) + } + } + +--- pipelined_requests eval +["GET /t", "GET /check_category_log"] + +--- response_body eval +["ok\n", "check ok\n"] + +--- timeout: 6000 + + +=== TEST 3: test client abort +--- http_config eval: $::HttpConfig +--- config + location /t { + lua_check_client_abort on; + + rewrite_by_lua_block { + local ok, err = ngx.on_abort(function () + ngx.log(ngx.ERR, 'on abort handler called') + ngx.exit(ngx.HTTP_OK) + end) + + if not ok then + ngx.say('cannot set on abort: ' .. err) + ngx.exit(ngx.HTTP_OK) + end + + ngx.ctx.category_log_file = 'category_log_test_3.error.log' + ngx.log(ngx.ERR, 'test_client_abort', 'foo', 'bar') + ngx.sleep(1) + ngx.exit(ngx.HTTP_OK) + } + } + +--- request +GET /t + +--- timeout: 0.6 +--- abort +--- ignore_response + + +=== TEST 4: test max_entry_n and max_repeat_n +--- http_config eval: $::HttpConfig +--- config + location /t { + lua_check_client_abort on; + + rewrite_by_lua_block { + ngx.ctx.category_log_file = 'category_log_test_4.error.log' + + ngx.log(ngx.ERR, 'only once log') + + for i = 1, 5 do + ngx.log(ngx.ERR, 'repeat log1') + end + + for i = 1, 5 do + ngx.log(ngx.ERR, 'repeat log2') + end + + ngx.say('ok') + ngx.exit(ngx.HTTP_OK) + } + } + + location /check_category_log { + rewrite_by_lua_block { + local strutil = require('acid.strutil') + local log_file_name = 'category_log_test_4.error.log' + os.execute('echo 3 > /proc/sys/vm/drop_caches') + os.execute('sync') + + ngx.sleep(1) + local f, err = io.open(log_file_name, 'r') + if err ~= nil then + ngx.say('open file error: ' .. err) + ngx.exit(ngx.HTTP_OK) + end + + local data = f:read('*a') + + parts = strutil.split(data, "\n", {plain=true}) + if #parts - 1 ~= 5 then + ngx.say('number fo lines is not 5') + ngx.exit(ngx.HTTP_OK) + end + + local m = ngx.re.match(parts[1], 'only once log') + if m == nil then + ngx.say('only once log not found') + ngx.exit(ngx.HTTP_OK) + end + + local m = ngx.re.match(parts[3], 'repeat log1') + if m == nil then + ngx.say('repeat log1 not found') + ngx.exit(ngx.HTTP_OK) + end + + local m = ngx.re.match(parts[4], 'repeat log2') + if m == nil then + ngx.say('repeat log2 not found') + ngx.exit(ngx.HTTP_OK) + end + ngx.say('check ok') + + os.remove(log_file_name) + ngx.exit(ngx.HTTP_OK) + } + } + +--- pipelined_requests eval +["GET /t", "GET /check_category_log"] + +--- response_body eval +["ok\n", "check ok\n"] + +--- timeout: 6000 + + +=== TEST 5: test log in timer +--- http_config eval: $::HttpConfig +--- config + location /t { + lua_check_client_abort on; + + rewrite_by_lua_block { + ngx.ctx.category_log_file = 'category_log_test_5.error.log' + + local ok, err = ngx.timer.at(0, function() + ngx.log(ngx.ERR, 'log in timer') + end) + if not ok then + ngx.say('set timer error: ' .. err) + ngx.exit(ngx.HTTP_OK) + end + + ngx.sleep(0.2) + + ngx.log(ngx.ERR, 'normal log') + ngx.say('ok') + ngx.exit(ngx.HTTP_OK) + } + } + + location /check_category_log { + rewrite_by_lua_block { + local log_file_name = 'category_log_test_5.error.log' + os.execute('echo 3 > /proc/sys/vm/drop_caches') + os.execute('sync') + + ngx.sleep(1) + local f, err = io.open(log_file_name, 'r') + if err ~= nil then + ngx.say('open file error: ' .. err) + ngx.exit(ngx.HTTP_OK) + end + + local data = f:read('*a') + + local m = ngx.re.match(data, 'log in timer') + if m ~= nil then + ngx.say('log in timer should not in category log') + ngx.exit(ngx.HTTP_OK) + end + + local m = ngx.re.match(data, 'normal log') + if m == nil then + ngx.say('normal log not in category log') + ngx.exit(ngx.HTTP_OK) + end + + ngx.say('check ok') + + os.remove(log_file_name) + ngx.exit(ngx.HTTP_OK) + } + } + +--- pipelined_requests eval +["GET /t", "GET /check_category_log"] + +--- response_body eval +["ok\n", "check ok\n"] + +--- timeout: 6000