feat(file-logger): cache & reopen file handler (apache#6721)

apisix/plugins/file-logger.lua

@@ -19,6 +19,7 @@ local core         =   require("apisix.core")
 local plugin       =   require("apisix.plugin")
 local ngx          =   ngx
 local io_open      =   io.open
+local is_apisix_or, process = pcall(require, "resty.apisix.process")
 
 
 local plugin_name = "file-logger"
@@ -60,9 +61,57 @@ function _M.check_schema(conf, schema_type)
 end
 
 
+local open_file_cache
+if is_apisix_or then
+    -- TODO: switch to a cache which supports inactive time,
+    -- so that unused files would not be cached
+    local path_to_file = core.lrucache.new({
+        type = "plugin",
+    })
+
+    local function open_file_handler(conf, handler)
+        local file, err = io_open(conf.path, 'a+')
+        if not file then
+            return nil, err
+        end
+
+        handler.file = file
+        handler.open_time = ngx.now() * 1000
+        return handler
+    end
+
+    function open_file_cache(conf)
+        local last_reopen_time = process.get_last_reopen_ms()
+
+        local handler, err = path_to_file(conf.path, 0, open_file_handler, conf, {})
+        if not handler then
+            return nil, err
+        end
+
+        if handler.open_time < last_reopen_time then
+            core.log.notice("reopen cached log file: ", conf.path)
+            handler.file:close()
+
+            local ok, err = open_file_handler(conf, handler)
+            if not ok then
+                return nil, err
+            end
+        end
+
+        return handler.file
+    end
+end
+
+
 local function write_file_data(conf, log_message)
     local msg = core.json.encode(log_message)
-    local file, err = io_open(conf.path, 'a+')
+
+    local file, err
+    if open_file_cache then
+        file, err = open_file_cache(conf)
+    else
+        file, err = io_open(conf.path, 'a+')
+    end
 
     if not file then
         core.log.error("failed to open file: ", conf.path, ", error info: ", err)
@@ -73,7 +122,11 @@ local function write_file_data(conf, log_message)
         else
             file:flush()
         end
-        file:close()
+
+        -- file will be closed by gc, if open_file_cache exists
+        if not open_file_cache then
+            file:close()
+        end
     end
 end
 

t/plugin/file-logger-reopen.t

@@ -0,0 +1,171 @@
+#
+# Licensed to the Apache Software Foundation (ASF) under one or more
+# contributor license agreements.  See the NOTICE file distributed with
+# this work for additional information regarding copyright ownership.
+# The ASF licenses this file to You under the Apache License, Version 2.0
+# (the "License"); you may not use this file except in compliance with
+# the License.  You may obtain a copy of the License at
+#
+#     http://www.apache.org/licenses/LICENSE-2.0
+#
+# Unless required by applicable law or agreed to in writing, software
+# distributed under the License is distributed on an "AS IS" BASIS,
+# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+# See the License for the specific language governing permissions and
+# limitations under the License.
+#
+use t::APISIX;
+
+my $nginx_binary = $ENV{'TEST_NGINX_BINARY'} || 'nginx';
+my $version = eval { `$nginx_binary -V 2>&1` };
+
+if ($version !~ m/\/apisix-nginx-module/) {
+    plan(skip_all => "apisix-nginx-module not installed");
+} else {
+    plan('no_plan');
+}
+
+no_long_string();
+no_root_location();
+
+add_block_preprocessor(sub {
+    my ($block) = @_;
+
+    if (! $block->request) {
+        $block->set_value("request", "GET /t");
+    }
+
+    if (! $block->no_error_log && ! $block->error_log) {
+        $block->set_value("no_error_log", "[error]");
+    }
+});
+
+
+run_tests;
+
+__DATA__
+
+=== TEST 1: prepare
+--- config
+    location /t {
+        content_by_lua_block {
+            local t = require("lib.test_admin").test
+            local code, body = t('/apisix/admin/plugin_metadata/file-logger',
+                ngx.HTTP_PUT,
+                [[{
+                    "log_format": {
+                        "host": "$host",
+                        "client_ip": "$remote_addr"
+                    }
+                }]]
+                )
+
+            if code >= 300 then
+                ngx.status = code
+                ngx.say(body)
+                return
+            end
+
+            local code, body = t('/apisix/admin/routes/1',
+                 ngx.HTTP_PUT,
+                 [[{
+                        "plugins": {
+                            "file-logger": {
+                                "path": "file.log"
+                            }
+                        },
+                        "upstream": {
+                            "nodes": {
+                                "127.0.0.1:1982": 1
+                            },
+                            "type": "roundrobin"
+                        },
+                        "uri": "/hello"
+                }]]
+                )
+
+            if code >= 300 then
+                ngx.status = code
+            end
+            ngx.say(body)
+        }
+    }
+--- response_body
+passed
+
+
+
+=== TEST 2: cache file
+--- config
+    location /t {
+        content_by_lua_block {
+            local core = require("apisix.core")
+            local t = require("lib.test_admin").test
+            local code = t("/hello", ngx.HTTP_GET)
+            assert(io.open("file.log", 'r'))
+            os.remove("file.log")
+            local code = t("/hello", ngx.HTTP_GET)
+            local _, err = io.open("file.log", 'r')
+            ngx.say(err)
+        }
+    }
+--- response_body
+file.log: No such file or directory
+
+
+
+=== TEST 3: reopen file
+--- config
+    location /t {
+        content_by_lua_block {
+            local core = require("apisix.core")
+            local t = require("lib.test_admin").test
+            local code = t("/hello", ngx.HTTP_GET)
+            assert(io.open("file.log", 'r'))
+            os.remove("file.log")
+
+            local process = require "ngx.process"
+            local resty_signal = require "resty.signal"
+            local pid = process.get_master_pid()
+
+            local ok, err = resty_signal.kill(pid, "USR1")
+            if not ok then
+                ngx.log(ngx.ERR, "failed to kill process of pid ", pid, ": ", err)
+                return
+            end
+
+            local code = t("/hello", ngx.HTTP_GET)
+
+            -- file is reopened
+            local fd, err = io.open("file.log", 'r')
+            local msg
+
+            if not fd then
+                core.log.error("failed to open file: file.log, error info: ", err)
+                return
+            end
+
+            msg = fd:read()
+
+            local new_msg = core.json.decode(msg)
+            if new_msg.client_ip == '127.0.0.1' and new_msg.route_id == '1'
+                and new_msg.host == '127.0.0.1'
+            then
+                msg = "write file log success"
+                ngx.status = code
+                ngx.say(msg)
+            end
+
+            os.remove("file.log")
+            local code = t("/hello", ngx.HTTP_GET)
+            local _, err = io.open("file.log", 'r')
+            ngx.say(err)
+        }
+    }
+--- response_body
+write file log success
+file.log: No such file or directory
+--- grep_error_log eval
+qr/reopen cached log file: file.log/
+--- grep_error_log_out
+reopen cached log file: file.log

t/plugin/file-logger.t

@@ -139,12 +139,12 @@ passed
             local fd, err = io.open("file.log", 'r')
             local msg
 
-            if fd then
-                msg = fd:read()
-            else
+            if not fd then
                 core.log.error("failed to open file: file.log, error info: ", err)
+                return
             end
-            fd:close()
+
+            msg = fd:read()
 
             local new_msg = core.json.decode(msg)
             if new_msg.client_ip == '127.0.0.1' and new_msg.route_id == '1'
@@ -154,10 +154,22 @@ passed
                 ngx.status = code
                 ngx.say(msg)
             end
+
+            --- a new request is logged
+            t("/hello", ngx.HTTP_GET)
+            msg = fd:read("*l")
+            local new_msg = core.json.decode(msg)
+            if new_msg.client_ip == '127.0.0.1' and new_msg.route_id == '1'
+                and new_msg.host == '127.0.0.1'
+            then
+                msg = "write file log success"
+                ngx.say(msg)
+            end
         }
     }
 --- response_body
 write file log success
+write file log success