fix(log-rotate): after enabling compression collect log exceptions

apisix/plugins/log-rotate.lua

@@ -22,20 +22,33 @@ local process = require("ngx.process")
 local signal = require("resty.signal")
 local shell = require("resty.shell")
 local ngx = ngx
+local ngx_time = ngx.time
+local ngx_update_time = ngx.update_time
 local lfs = require("lfs")
-local io = io
-local os = os
-local table = table
-local string = string
-local str_find = core.string.find
+local type = type
+local io_open = io.open
+local os_date = os.date
+local os_remove = os.remove
+local os_rename = os.rename
+local str_sub = string.sub
+local str_find = string.find
+local str_format = string.format
+local str_reverse = string.reverse
+local tab_insert = table.insert
+local tab_sort = table.sort
+
 local local_conf
 
 
 local plugin_name = "log-rotate"
 local INTERVAL = 60 * 60    -- rotate interval (unit: second)
 local MAX_KEPT = 24 * 7     -- max number of log files will be kept
 local COMPRESSION_FILE_SUFFIX = ".tar.gz" -- compression file suffix
+local rotate_time
+local default_logs
 local enable_compression = false
+local DEFAULT_ACCESS_LOG_FILENAME = "access.log"
+local DEFAULT_ERROR_LOG_FILENAME = "error.log"
 
 local schema = {
     type = "object",
@@ -53,7 +66,7 @@ local _M = {
 
 
 local function file_exists(path)
-    local file = io.open(path, "r")
+    local file = io_open(path, "r")
     if file then
         file:close()
     end
@@ -62,7 +75,7 @@ end
 
 
 local function get_last_index(str, key)
-    local rev = string.reverse(str)
+    local rev = str_reverse(str)
     local _, idx = str_find(rev, key)
     local n
     if idx then
@@ -88,15 +101,15 @@ local function get_log_path_info(file_type)
     local prefix = ngx.config.prefix()
 
     if conf_path then
-        local root = string.sub(conf_path, 1, 1)
+        local root = str_sub(conf_path, 1, 1)
         -- relative path
         if root ~= "/" then
             conf_path = prefix .. conf_path
         end
         local n = get_last_index(conf_path, "/")
         if n ~= nil and n ~= #conf_path then
-            local dir = string.sub(conf_path, 1, n)
-            local name = string.sub(conf_path, n + 1)
+            local dir = str_sub(conf_path, 1, n)
+            local name = str_sub(conf_path, n + 1)
             return dir, name
         end
     end
@@ -105,50 +118,11 @@ local function get_log_path_info(file_type)
 end
 
 
-local function rotate_file(date_str, file_type)
-    local log_dir, filename = get_log_path_info(file_type)
-
-    core.log.info("rotate log_dir:", log_dir)
-    core.log.info("rotate filename:", filename)
-
-    local new_filename = date_str .. "__" .. filename
-    local file_path = log_dir .. new_filename
-    if file_exists(file_path) then
-        core.log.info("file exist: ", file_path)
-        return false
-    end
-
-    local file_path_org = log_dir .. filename
-    local ok, msg = os.rename(file_path_org, file_path)
-    core.log.info("move file from ", file_path_org, " to ", file_path,
-                  " res:", ok, " msg:", msg)
-
-    if ok and enable_compression then
-        local compression_filename = new_filename .. COMPRESSION_FILE_SUFFIX
-        local cmd = string.format("cd %s && tar -zcf %s %s",
-            log_dir, compression_filename, new_filename)
-        core.log.info("log file compress command: " .. cmd)
-        local ok, stdout, stderr, reason, status = shell.run(cmd)
-        core.log.info("compress log file from ", new_filename, " to ", compression_filename,
-            " res:", ok)
-
-        if ok then
-            ok = os.remove(file_path)
-            core.log.warn("remove uncompressed log file: ", file_path, " ret: ", ok)
-        else
-            core.log.error("failed to compress log file: ", new_filename, " ret: ", ok,
-                " stdout: ", stdout, " stderr: ", stderr, " reason: ", reason, " status: ", status)
-        end
-    end
-
-    return true
-end
-
-
-local function tab_sort(a, b)
+local function tab_sort_comp(a, b)
     return a > b
 end
 
+
 local function scan_log_folder()
     local t = {
         access = {},
@@ -168,19 +142,83 @@ local function scan_log_folder()
         if n ~= nil then
             local log_type = file:sub(n + 2)
             if log_type == access_name then
-                table.insert(t.access, file)
+                tab_insert(t.access, file)
             elseif log_type == error_name then
-                table.insert(t.error, file)
+                tab_insert(t.error, file)
             end
         end
     end
 
-    table.sort(t.access, tab_sort)
-    table.sort(t.error, tab_sort)
+    tab_sort(t.access, tab_sort_comp)
+    tab_sort(t.error, tab_sort_comp)
     return t, log_dir
 end
 
 
+local function rename_file(log, date_str)
+    local new_file
+    if not log.new_file then
+        core.log.warn(log.type, " is off")
+        return
+    end
+
+    new_file = str_format(log.new_file, date_str)
+    if file_exists(new_file) then
+        core.log.info("file exist: ", new_file)
+        return new_file
+    end
+
+    local ok, err = os_rename(log.file, new_file)
+    if not ok then
+        core.log.error("move file from ", log.file, " to ", new_file,
+                       " res:", ok, " msg:", err)
+        return
+    end
+
+    return new_file
+end
+
+
+local function compression_file(new_file)
+    if not new_file or type(new_file) ~= "string" then
+        core.log.info("compression file: ", new_file, " invalid")
+        return
+    end
+
+    local n = get_last_index(new_file, "/")
+    local new_filepath = str_sub(new_file, 1, n)
+    local new_filename = str_sub(new_file, n + 1)
+    local com_filename = new_filename .. COMPRESSION_FILE_SUFFIX
+    local cmd = str_format("cd %s && tar -zcf %s %s", new_filepath,
+            com_filename, new_filename)
+    core.log.info("log file compress command: " .. cmd)
+
+    local ok, stdout, stderr, reason, status = shell.run(cmd)
+    if not ok then
+        core.log.error("compress log file from ", new_filename, " to ", com_filename,
+                       " fail, stdout: ", stdout, " stderr: ", stderr, " reason: ", reason,
+                       " status: ", status)
+        return
+    end
+
+    ok, stderr = os_remove(new_file)
+    if stderr then
+        core.log.error("remove uncompressed log file: ", new_file,
+                       " fail, err: ", stderr, "  res:", ok)
+    end
+end
+
+
+local function init_default_logs(logs_info, log_type)
+    local filepath, filename = get_log_path_info(log_type)
+    logs_info[log_type] = { type = log_type }
+    if filename ~= "off" then
+        logs_info[log_type].file = filepath .. filename
+        logs_info[log_type].new_file = filepath .. "/%s__" .. filename
+    end
+end
+
+
 local function rotate()
     local interval = INTERVAL
     local max_kept = MAX_KEPT
@@ -194,18 +232,34 @@ local function rotate()
     core.log.info("rotate interval:", interval)
     core.log.info("rotate max keep:", max_kept)
 
-    local time = ngx.time()
-    if time % interval == 0 then
-        time = time - interval
-    else
-        time = time - time % interval
+    if not default_logs then
+        -- first init default log filepath and filename
+        default_logs = {}
+        init_default_logs(default_logs, DEFAULT_ACCESS_LOG_FILENAME)
+        init_default_logs(default_logs, DEFAULT_ERROR_LOG_FILENAME)
     end
 
-    local date_str = os.date("%Y-%m-%d_%H-%M-%S", time)
+    ngx_update_time()
+    local now_time = ngx_time()
+    if not rotate_time then
+        -- first init rotate time
+        rotate_time = now_time + interval
+        core.log.info("first init rotate time is: ", rotate_time)
+        return
+    end
+
+    if now_time < rotate_time then
+        -- did not reach the rotate time
+        core.log.info("rotate time: ", rotate_time, " now time: ", now_time)
+        return
+    end
 
-    local ok1 = rotate_file(date_str, "access.log")
-    local ok2 = rotate_file(date_str, "error.log")
-    if not ok1 and not ok2 then
+    local now_date = os_date("%Y-%m-%d_%H-%M-%S", now_time)
+    local access_new_file = rename_file(default_logs[DEFAULT_ACCESS_LOG_FILENAME], now_date)
+    local error_new_file = rename_file(default_logs[DEFAULT_ERROR_LOG_FILENAME], now_date)
+    if not access_new_file and not error_new_file then
+        -- reset rotate time
+        rotate_time = rotate_time + interval
         return
     end
 
@@ -216,19 +270,31 @@ local function rotate()
         core.log.error("failed to send USR1 signal for reopening log file: ", err)
     end
 
+    if enable_compression then
+        compression_file(access_new_file)
+        compression_file(error_new_file)
+    end
+
     -- clean the oldest file
     local log_list, log_dir = scan_log_folder()
     for i = max_kept + 1, #log_list.error do
         local path = log_dir .. log_list.error[i]
-        local ok = os.remove(path)
-        core.log.warn("remove old error file: ", path, " ret: ", ok)
+        ok, err = os_remove(path)
+        if err then
+           core.log.error("remove old error file: ", path, " err: ", err, "  res:", ok)
+        end
     end
 
     for i = max_kept + 1, #log_list.access do
         local path = log_dir .. log_list.access[i]
-        local ok = os.remove(path)
-        core.log.warn("remove old access file: ", path, " ret: ", ok)
+        ok, err = os_remove(path)
+        if err then
+           core.log.error("remove old error file: ", path, " err: ", err, "  res:", ok)
+        end
     end
+
+    -- reset rotate time
+    rotate_time = rotate_time + interval
 end
 
 

t/plugin/log-rotate.t

@@ -40,7 +40,16 @@ plugin_attr:
 _EOC_
 
     $block->set_value("yaml_config", $user_yaml_config);
-    $block->set_value("request", "GET /t");
+
+
+    if ((!defined $block->error_log) && (!defined $block->no_error_log)) {
+        $block->set_value("no_error_log", "[error]");
+    }
+
+    if (!defined $block->request) {
+        $block->set_value("request", "GET /t");
+    }
+
 });
 
 run_tests;
@@ -81,8 +90,6 @@ __DATA__
     }
 --- error_code eval
 [200]
---- no_error_log
-[error]
 
 
 
@@ -97,8 +104,6 @@ __DATA__
     }
 --- response_body
 done
---- no_error_log
-[error]
 --- error_log
 start xxxxxx
 
@@ -139,8 +144,6 @@ start xxxxxx
     }
 --- response_body
 done
---- no_error_log
-[error]
 
 
 
@@ -181,5 +184,43 @@ plugins:
 --- response_body
 done
 true
---- no_error_log
-[error]
+
+
+
+=== TEST 5: check file changes (disable compression)
+--- config
+    location /t {
+        content_by_lua_block {
+            ngx.sleep(2)
+
+            local default_logs = {}
+            for file_name in lfs.dir(ngx.config.prefix() .. "/logs/") do
+                if string.match(file_name, "__error.log$") or string.match(file_name, "__access.log$") then
+                    local filepath = ngx.config.prefix() .. "/logs/" .. file_name
+                    local attr = lfs.attributes(filepath)
+                    if attr then
+                        default_logs[filepath] = { change = attr.change, size = attr.size }
+                    end
+                end
+            end
+
+            ngx.sleep(1)
+
+            local passed = false
+            for filepath, origin_attr in pairs(default_logs) do
+                local check_attr = lfs.attributes(filepath)
+                if check_attr.change == origin_attr.change and check_attr.size == origin_attr.size then
+                    passed = true
+                else
+                    passed = false
+                    break
+                end
+            end
+
+            if passed then
+                ngx.say("passed")
+            end
+        }
+    }
+--- response_body
+passed