From 58358671f23155ec7844fe8faa5c72333138ea36 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?=E5=B8=85=E8=BF=9B=E8=B6=85?= Date: Wed, 15 Dec 2021 15:30:43 +0800 Subject: [PATCH 1/5] fix(sls-logger): log entry unable get millisecond timestamp --- apisix/plugins/slslog/rfc5424.lua | 9 ++--- t/plugin/sls-logger.t | 67 ++++++++++++++++++++++--------- 2 files changed, 53 insertions(+), 23 deletions(-) diff --git a/apisix/plugins/slslog/rfc5424.lua b/apisix/plugins/slslog/rfc5424.lua index ff73d1983e9a..5d09a58a5165 100644 --- a/apisix/plugins/slslog/rfc5424.lua +++ b/apisix/plugins/slslog/rfc5424.lua @@ -78,16 +78,15 @@ local Severity = { DEBUG = LOG_DEBUG, } -local os_date = os.date -local ngx = ngx -local rfc5424_timestamp_format = "!%Y-%m-%dT%H:%M:%S.000Z" +local log_util = require("apisix.utils.log-util") + + local _M = { version = 0.1 } function _M.encode(facility, severity, hostname, appname, pid, project, logstore, access_key_id, access_key_secret, msg) local pri = (Facility[facility] * 8 + Severity[severity]) - ngx.update_time() - local t = os_date(rfc5424_timestamp_format, ngx.now()) + local t = log_util.get_rfc3339_zulu_timestamp() if not hostname then hostname = "-" end diff --git a/t/plugin/sls-logger.t b/t/plugin/sls-logger.t index 7e8b1eb8a373..54fafdeede5d 100644 --- a/t/plugin/sls-logger.t +++ b/t/plugin/sls-logger.t @@ -19,7 +19,21 @@ use t::APISIX 'no_plan'; repeat_each(1); no_long_string(); no_root_location(); -run_tests; + +add_block_preprocessor(sub { + my ($block) = @_; + + 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(); __DATA__ @@ -37,12 +51,8 @@ __DATA__ ngx.say("done") } } ---- request -GET /t --- response_body done ---- no_error_log -[error] @@ -60,13 +70,9 @@ done ngx.say("done") } } ---- request -GET /t --- response_body property "access_key_secret" is required done ---- no_error_log -[error] @@ -84,13 +90,9 @@ done ngx.say("done") } } ---- request -GET /t --- response_body property "timeout" validation failed: wrong type: expected integer, got string done ---- no_error_log -[error] @@ -155,12 +157,8 @@ done ngx.say(body) } } ---- request -GET /t --- response_body passed ---- no_error_log -[error] @@ -188,9 +186,42 @@ hello world ngx.say(data) } } +--- response_body +123 + + + +=== TEST 7: sls log get milliseconds +--- config + location /t { + content_by_lua_block { + local function get_syslog_timestamp_millisecond(sls_log) + local first_idx = string.find(sls_log, " ") + 1 + local last_idx2 = string.find(sls_log, " ", first_idx) + local rfc3339_date = string.sub(sls_log, first_idx, last_idx2) + local rfc3339_len = string.len(rfc3339_date) + local rfc3339_millisecond = string.sub(rfc3339_date, rfc3339_len - 4, rfc3339_len - 2) + return tonumber(rfc3339_millisecond) + end + + local rfc5424 = require("apisix.plugins.slslog.rfc5424") + local m = 0 + for _ = 1, 10 do + local sls_log = rfc5424.encode("SYSLOG", "INFO", "localhost", "apisix", + 123456, "apisix.apache.org", "apisix.apache.log", + "apisix.sls.logger", "BD274822-96AA-4DA6-90EC-15940FB24444", + "hello world") + m = get_syslog_timestamp_millisecond(sls_log) + m + end + + if m > 0 then + ngx.say("passed") + end + } + } --- request GET /t --- response_body -123 +passed --- no_error_log [error] From cba09c5dc1ed8bf5a0c6ad0fb8c2ac1f7dce1f48 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?=E5=B8=85=E8=BF=9B=E8=B6=85?= Date: Wed, 15 Dec 2021 15:36:44 +0800 Subject: [PATCH 2/5] chore(sls-logger): remove redundancy tag --- t/plugin/sls-logger.t | 6 ------ 1 file changed, 6 deletions(-) diff --git a/t/plugin/sls-logger.t b/t/plugin/sls-logger.t index 54fafdeede5d..8558de95685a 100644 --- a/t/plugin/sls-logger.t +++ b/t/plugin/sls-logger.t @@ -167,8 +167,6 @@ passed GET /hello --- response_body hello world ---- no_error_log -[error] --- wait: 1 @@ -219,9 +217,5 @@ hello world end } } ---- request -GET /t --- response_body passed ---- no_error_log -[error] From db8942239afe46188821c690eb2c75636773b9de Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?=E5=B8=85=E8=BF=9B=E8=B6=85?= Date: Wed, 15 Dec 2021 20:17:31 +0800 Subject: [PATCH 3/5] fix(sls-logger): update unit case --- t/plugin/sls-logger.t | 20 +++++++++++--------- 1 file changed, 11 insertions(+), 9 deletions(-) diff --git a/t/plugin/sls-logger.t b/t/plugin/sls-logger.t index 8558de95685a..b11b4d819521 100644 --- a/t/plugin/sls-logger.t +++ b/t/plugin/sls-logger.t @@ -193,23 +193,25 @@ hello world --- config location /t { content_by_lua_block { - local function get_syslog_timestamp_millisecond(sls_log) - local first_idx = string.find(sls_log, " ") + 1 - local last_idx2 = string.find(sls_log, " ", first_idx) - local rfc3339_date = string.sub(sls_log, first_idx, last_idx2) + local function get_syslog_timestamp_millisecond(log_entry) + local first_idx = string.find(log_entry, " ") + 1 + local last_idx2 = string.find(log_entry, " ", first_idx) + local rfc3339_date = string.sub(log_entry, first_idx, last_idx2) local rfc3339_len = string.len(rfc3339_date) local rfc3339_millisecond = string.sub(rfc3339_date, rfc3339_len - 4, rfc3339_len - 2) return tonumber(rfc3339_millisecond) end + math.randomseed(os.time()) local rfc5424 = require("apisix.plugins.slslog.rfc5424") local m = 0 for _ = 1, 10 do - local sls_log = rfc5424.encode("SYSLOG", "INFO", "localhost", "apisix", - 123456, "apisix.apache.org", "apisix.apache.log", - "apisix.sls.logger", "BD274822-96AA-4DA6-90EC-15940FB24444", - "hello world") - m = get_syslog_timestamp_millisecond(sls_log) + m + local log_entry = rfc5424.encode("SYSLOG", "INFO", "localhost", "apisix", + 123456, "apisix.apache.org", "apisix.apache.log", + "apisix.sls.logger", "BD274822-96AA-4DA6-90EC-15940FB24444", + "hello world") + m = get_syslog_timestamp_millisecond(log_entry) + m + ngx.sleep(math.random()) end if m > 0 then From 2d4bf980ee6fde11acb2883758f21c69587a7c70 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?=E5=B8=85=E8=BF=9B=E8=B6=85?= Date: Thu, 16 Dec 2021 09:55:59 +0800 Subject: [PATCH 4/5] fix(sls-logger): add timeout for case --- t/plugin/sls-logger.t | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-) diff --git a/t/plugin/sls-logger.t b/t/plugin/sls-logger.t index b11b4d819521..a837f7925d6c 100644 --- a/t/plugin/sls-logger.t +++ b/t/plugin/sls-logger.t @@ -205,13 +205,13 @@ hello world math.randomseed(os.time()) local rfc5424 = require("apisix.plugins.slslog.rfc5424") local m = 0 - for _ = 1, 10 do + for i = 1, 5 do + ngx.sleep(string.format("%0.3f", math.random())) local log_entry = rfc5424.encode("SYSLOG", "INFO", "localhost", "apisix", 123456, "apisix.apache.org", "apisix.apache.log", "apisix.sls.logger", "BD274822-96AA-4DA6-90EC-15940FB24444", "hello world") m = get_syslog_timestamp_millisecond(log_entry) + m - ngx.sleep(math.random()) end if m > 0 then @@ -221,3 +221,4 @@ hello world } --- response_body passed +--- timeout: 5 From d509051b33c56cf990a8c75437a39e5906c68bec Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?=E5=B8=85=E8=BF=9B=E8=B6=85?= Date: Thu, 16 Dec 2021 17:16:09 +0800 Subject: [PATCH 5/5] fix(sls-logger): add comment for test case --- t/plugin/sls-logger.t | 2 ++ 1 file changed, 2 insertions(+) diff --git a/t/plugin/sls-logger.t b/t/plugin/sls-logger.t index a837f7925d6c..296372c6235f 100644 --- a/t/plugin/sls-logger.t +++ b/t/plugin/sls-logger.t @@ -205,6 +205,8 @@ hello world math.randomseed(os.time()) local rfc5424 = require("apisix.plugins.slslog.rfc5424") local m = 0 + -- because the millisecond value obtained by `ngx.now` may be `0` + -- it is executed multiple times to ensure the accuracy of the test for i = 1, 5 do ngx.sleep(string.format("%0.3f", math.random())) local log_entry = rfc5424.encode("SYSLOG", "INFO", "localhost", "apisix",