Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

feat: add file-logger plugin #5831

Merged
merged 30 commits into from Jan 21, 2022
Merged

Conversation

guoqqqi
Copy link
Member

@guoqqqi guoqqqi commented Dec 16, 2021

What this PR does / why we need it:

  1. add file-logger plugin

Related: Discuss on the mailing list

Pre-submission checklist:

  • Did you explain what problem does this PR solve? Or what new features have been added?
  • Have you added corresponding test cases?
  • Have you modified the corresponding document?
  • Is this PR backward compatible? If it is not backward compatible, please discuss on the mailing list first

@juzhiyuan
Copy link
Member

Hi, maybe you'd better add a TODO checklist in this PR's description 🤔

@guoqqqi
Copy link
Member Author

guoqqqi commented Dec 20, 2021

TODO:

  • add control API
  • test
  • docs

Wait for the review to be completed and add the English document

@guoqqqi guoqqqi marked this pull request as ready for review December 29, 2021 10:01
"file-logger": {
"path": "logs/file.log",
"custom_fields_by_lua": {"route_id": "return nil"}
}
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Hi, could we use 2 spaces here?

local plugin = require("apisix.plugin")
local ffi = require("ffi")
local bit = require("bit")

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Please don't use a blank line between localized functions.

local io_open = io.open

local plugin_name = "file-logger"
local O_CREAT = 00000040 -- create and open
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Why not use Lua's std file library? That one is much simpler. See https://www.tutorialspoint.com/lua/lua_file_io.htm

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The reason for using ffi to call write is that I do not want to use the cached io.write. For more information on this, see the:

  1. https://m.yisu.com/zixun/194893.html
  2. https://github.com/Kong/kong/blob/master/kong/plugins/file-log/handler.lua

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

To bypass the user-space cache, there is already a flush method for it.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

file:flush()

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Hi, @spacewander I am trying to use io.write and file:flush to write logs, but I find that io.open returns a userdata and my attempts to store and read it fail, how do I go about it?
image

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The error msg indicates that you can't log a userdata.

properties = {
path = {
type = "string",
require = true,
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This is not a valid JSON schema syntax. Please take a look at https://github.com/apache/apisix/blob/master/apisix/schema_def.lua



function _M.body_filter(conf, ctx)
log_util.collect_body(conf, ctx)
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Since the first version of file-logger doesn't support logging response body, we don't need to collect it.

entry = log_util.get_full_log(ngx, conf)
end

if conf.custom_fields_by_lua
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Look like we don't need to provide custom_fields_by_lua, as we already have "log_util.get_custom_format_log".

local pairs = pairs
local load_string = loadstring
local io_open = io.open

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Better to use two blank lines after localized functions.

return {
{
methods = {"GET"},
uris = {"/plugin/file-logger/reopen"},
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggested change
uris = {"/plugin/file-logger/reopen"},
uris = {"/v1/plugin/file-logger/reopen"},

would be better

function _M.control_api()
return {
{
methods = {"GET"},
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

schema = schema,
metadata_schema = metadata_schema
}

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Please use two blank lines to separate each section (localized functions, define module-level variables, define functions, return _M)



local function reopen()
local target_pointer, err = io_open('logs/file_pointer', 'r')
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

There is no need to track the status with a file in disk? We can just iterate all cache fds and reopen them.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

We also need to remove the stale cached data when a route used file-logger is deleted. It can be done with a timer:

timers.register_timer("plugin#server-info", fn, true)

timers.unregister_timer("plugin#server-info", true)

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Since only one worker can receive the reopen request, we can use worker event to trigger fd reopen in the other workers, like:

events = require("resty.worker.events")

local target_pointer, err = io_open('logs/file_pointer', 'r')
if not target_pointer then
core.log.error("failed to open file, error info: " .. err)
core.response.exit(400, {error_msg = "failed to open file, error info: " .. err})
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggested change
core.response.exit(400, {error_msg = "failed to open file, error info: " .. err})
return 400, {error_msg = "failed to open file, error info: " .. err}

reset_pointer:close()
end

core.response.exit(200, 'reopen file-logger successfully')
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Better to return a JSON response

@guoqqqi
Copy link
Member Author

guoqqqi commented Jan 13, 2022

Hi, can I finish the reopen function in another PR later? I may need to spend some time learning worker.events and timers

@spacewander
Copy link
Member

It's OK.

properties = {
path = {
type = "string",
match = [[^[^*&%%\`]+$]],
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The syntax is still incorrect. See #5831 (comment)

local fd = file_descriptors[conf.path]

if not fd then
local file = io_open(conf.path, 'a+')
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Please don't cache fd in this version. We don't have a way to remove it.

local io_open = io.open


local plugin_name = "file-logger"
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggested change
local plugin_name = "file-logger"
local plugin_name = "file-logger"

path = {
type = "string",
pattern = [[^[^*&%%\`]+$]],
err = "not a valid filename"
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

We don't have err in the jsonschema. BTW, we don't need to verify the path with regex? Different filesystems will have different requirements.

local msg = core.json.encode(log_message) .. "\n"

if not file then
file = io_open(conf.path, 'a+')
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggested change
file = io_open(conf.path, 'a+')
local file, err = io_open(conf.path, 'a+')

is enough? And remember to check the err.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Oops, I misunderstood here before, I thought this way of writing would cause the file to be reopened on every request

file = io_open(conf.path, 'a+')
end

file:write(msg)
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Ditto

| ---------------- | ------- | ------ | ------------- | ------- | ------------------------------------------------ |
| log_format | object | 可选 | {"host": "$host", "@timestamp": "$time_iso8601", "client_ip": "$remote_addr"} | | 以 JSON 格式的键值对来声明日志格式。对于值部分,仅支持字符串。如果是以 `$` 开头,则表明是要获取 __APISIX__ 变量或 [Nginx 内置变量](http://nginx.org/en/docs/varindex.html)。特别的,**该设置是全局生效的**,意味着指定 log_format 后,将对所有绑定 file-logger 的 Route 或 Service 生效。 |

**APISIX 变量**
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Please update the doc according to the latest http-logger.

local file, err = io_open(conf.path, 'a+')

if not file then
core.log.error("failed to open file: " .. conf.path .. ", error info: " .. err)
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggested change
core.log.error("failed to open file: " .. conf.path .. ", error info: " .. err)
core.log.error("failed to open file: ", conf.path, ", error info: ", err)

if not file then
core.log.error("failed to open file: " .. conf.path .. ", error info: " .. err)
else
file:write(msg)
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Need to handle the err.
And don't forget to close the file

else
file:write(msg)
file:flush()
local ok, error = file:write(msg)
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggested change
local ok, error = file:write(msg)
local ok, err = file:write(msg)

and we need to close the file even failed to write.

BTW, we can use file:write(msg, '\n') to avoid local msg = core.json.encode(log_message) .. "\n"

if not ok then
core.log.error("failed to write file: ", conf.path, ", error info: ", error)
file:close()
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

We should close the file whether the writing success or not.


## Name

`file-logger` is a plugin which push a stream of Log data to a specified location. For example, the output path can be customized: `logs/file.log`.
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggested change
`file-logger` is a plugin which push a stream of Log data to a specified location. For example, the output path can be customized: `logs/file.log`.
`file-logger` is a plugin that pushes a stream of log data to a specified file. For example, the output path can be customized: `logs/file.log`.

core.log.error("failed to write file: ", conf.path, ", error info: ", err)
else
file:flush()
file:close()
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

We can merge the two close into one

msg = fd:read()
fd:close()
else
fd:close()
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Ditto

fd:close()
core.log.error("failed to open file: logs/file.log, error info: ", err)
end
core.log.warn('msg: ', msg)
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Let's check the msg too

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Do I need to check all the fields and values in the msg, or do I just need to check a few specific values?

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Better to check them all, we can custom the format to avoid timestamps.

[[{
"plugins": {
"file-logger": {
"path": "file.log"
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Let's add a test that the path can't be opened.

ngx.say(body)
}
}
--- request
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Don't add redundant section

"client_ip": "$remote_addr"
}
}]],
[[{
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

We don't need to check the response, right?

@@ -84,7 +84,7 @@ You can then find the `file.log` file in the corresponding `logs` directory.
### Example

```shell
curl http://127.0.0.1:9080/apisix/admin/plugin_metadata/http-logger -H 'X-API-KEY: edd1c9f034335f136f87ad84b625c8f1' -X PUT -d '
curl http://127.0.0.1:9080/apisix/admin/plugin_metadata/file-logger -H 'X-API-KEY: edd1c9f034335f136f87ad84b625c8f1' -X PUT -d '
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Please sync to Chinese doc

if not ok then
return nil, err
end
return log_util.check_log_schema(conf)
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

we don't need this validation as the current file-logger schema doesn't contains any expression like include_resp_body_expr or include_req_body_expr

Comment on lines +68 to +83
local function write_file_data(conf, log_message)
local msg = core.json.encode(log_message)
local file, err = io_open(conf.path, 'a+')

if not file then
core.log.error("failed to open file: ", conf.path, ", error info: ", err)
else
local ok, err = file:write(msg, '\n')
if not ok then
core.log.error("failed to write file: ", conf.path, ", error info: ", err)
else
file:flush()
end
file:close()
end
end
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Instead of opening a file handle for each time we dump a log, can we optimize it a bit by keeping the fd open and caching it so that it can be reused (maybe with a timeout, so that it doesn't remain open indefinitely [do we really care about it?])? Because you know, writing something is cheap but opening a file handler for every logs and moving the fd to the EOF takes some resources.
Maybe it's a premature optimization. @spacewander WDYT?

Copy link
Member Author

@guoqqqi guoqqqi Jan 20, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Hi, @bisakhmondal I tried to add a reopen function to it to cache the fd, but I had some problems, so I wanted to finish it later. #5831 (comment)

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Okay, @guoqqqi. Thanks.



function _M.log(conf, ctx)
local metadata = plugin.plugin_metadata(plugin_name)
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

How about a gentle info log of the json serialized metadata after this line?

Comment on lines 39 to 73
=== TEST 1: sanity
--- config
location /t {
content_by_lua_block {
local plugin = require("apisix.plugins.file-logger")
local ok, err = plugin.check_schema({
path = "file.log"
})
if not ok then
ngx.say(err)
end

ngx.say("done")
}
}
--- response_body
done



=== TEST 2: path is missing check
--- config
location /t {
content_by_lua_block {
local plugin = require("apisix.plugins.file-logger")
local ok, err = plugin.check_schema()
if not ok then
ngx.say(err)
end

ngx.say("done")
}
}
--- no_error_log
property "path" is required
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

We can go with table-driven checks?

local configs = {
-- full configuration
{
endpoint = {
uri = "http://127.0.0.1:18088/services/collector",
token = "BD274822-96AA-4DA6-90EC-18940FB2414C",
channel = "FE0ECFAD-13D5-401B-847D-77833BD77131",
timeout = 60
},
max_retry_count = 0,
retry_delay = 1,
buffer_duration = 60,
inactive_timeout = 2,
batch_max_size = 10,
},
-- minimize configuration
{
endpoint = {
uri = "http://127.0.0.1:18088/services/collector",
token = "BD274822-96AA-4DA6-90EC-18940FB2414C",
}
},
-- property "uri" is required
{
endpoint = {
token = "BD274822-96AA-4DA6-90EC-18940FB2414C",
}
},
-- property "token" is required
{
endpoint = {
uri = "http://127.0.0.1:18088/services/collector",
}
},
-- property "uri" validation failed
{
endpoint = {
uri = "127.0.0.1:18088/services/collector",
token = "BD274822-96AA-4DA6-90EC-18940FB2414C",
}
}
}
local plugin = require("apisix.plugins.splunk-hec-logging")
for i = 1, #configs do
ok, err = plugin.check_schema(configs[i])
if err then
ngx.say(err)
else
ngx.say("passed")
end
end
}
}

}
}
--- error_log
failed to open file: /log/file.log, error info: /log/file.log: No such file or directory
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

In such a case, how about we try to create a file with the corresponding name. If that returns an error [maybe insufficient permission], we throw it away. Else it would not be a good user experience to create a file each time they create a log configuration. What do you think about it? Thank you

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Good idea, as I'm not particularly familiar with it, can I finish it with reopen function later?

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yes sure. Totally up to you. Thanks.

@@ -375,6 +375,7 @@ plugins: # plugin list (sorted by priority)
- rocketmq-logger # priority: 402
- syslog # priority: 401
- udp-logger # priority: 400
- file-logger # priority: 399
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The same type of plugin, the first number should be the same. 4xx is for logger plugins

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The same type of plugin, the first number should be the same. 4xx is for logger plugins

Ignore this, it looks like it's not the rule anymore

Copy link
Member

@shuaijinchao shuaijinchao left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

support for worker.event and batch queue can be record by opening issues.

Copy link
Member

@bisakhmondal bisakhmondal left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

lgtm

@spacewander spacewander merged commit 8114ca5 into apache:master Jan 21, 2022
@spacewander
Copy link
Member

Merged. Thanks!

@guoqqqi guoqqqi deleted the feat-file-logger-plugin branch January 21, 2022 10:13
@juzhiyuan
Copy link
Member

Hi @guoqqqi, please add this to README refer to @Baoyuantop's PR :)

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

6 participants