diff --git a/.github/workflows/tests.yml b/.github/workflows/tests.yml index 07ba1772..10d24289 100644 --- a/.github/workflows/tests.yml +++ b/.github/workflows/tests.yml @@ -28,7 +28,7 @@ jobs: ref: ${{ env.KONG_VERSION }} path: kong - - name: Set the KONG_NGINX_MODULE_BRANCH in kong/.requirements + - name: Set the LUA_KONG_NGINX_MODULE in kong/.requirements run: | cd kong branch="" @@ -40,7 +40,7 @@ jobs: fi branch=$(echo "$branch" | sed 's/\//\\\//g') - sed -i "s/KONG_NGINX_MODULE_BRANCH=.\+/KONG_NGINX_MODULE_BRANCH=${branch}/" .requirements + sed -i "s/LUA_KONG_NGINX_MODULE=.\+/LUA_KONG_NGINX_MODULE=${branch}/" .requirements cat .requirements - name: Lookup build cache @@ -88,7 +88,7 @@ jobs: ref: ${{ env.KONG_VERSION }} path: kong - - name: Set the KONG_NGINX_MODULE_BRANCH in kong/.requirements + - name: Set the LUA_KONG_NGINX_MODULE in kong/.requirements run: | cd kong branch="" @@ -100,7 +100,7 @@ jobs: fi branch=$(echo "$branch" | sed 's/\//\\\//g') - sed -i "s/KONG_NGINX_MODULE_BRANCH=.\+/KONG_NGINX_MODULE_BRANCH=${branch}/" .requirements + sed -i "s/LUA_KONG_NGINX_MODULE=.\+/LUA_KONG_NGINX_MODULE=${branch}/" .requirements cat .requirements - name: Load build cache diff --git a/README.md b/README.md index 70a2ab4b..66786138 100644 --- a/README.md +++ b/README.md @@ -12,6 +12,7 @@ Table of Contents * [Directives](#directives) * [lua\_kong\_load\_var\_index](#lua_kong_load_var_index) * [lua\_kong\_set\_static\_tag](#lua_kong_set_static_tag) + * [lua\_kong\_error\_log\_request\_id](#lua_kong_error_log_request_id) * [Methods](#methods) * [resty.kong.tls.disable\_session\_reuse](#restykongtlsdisable_session_reuse) * [resty.kong.tls.get\_full\_client\_certificate\_chain](#restykongtlsget_full_client_certificate_chain) @@ -140,6 +141,25 @@ you will always get the value where your Lua code runs in but not others. [Back to TOC](#table-of-contents) +lua\_kong\_error\_log\_request\_id +------------------------------------------- +**syntax:** *lua_kong_error_log_request_id $variable;* + +**context:** *http* *server* *location* + +Append a Request ID to the standard error log format, load the ID value from `$variable`. `$variable` must be previously defined. + +For example, with this configuration: +``` +lua_kong_error_log_request_id $request_id; +``` +An error log line may look similar to the following: +``` +2023/09/06 11:33:36 [error] 94085#0: *6 [lua] content_by_lua(nginx.conf:27):7: hello world, client: 127.0.0.1, server: , request: "GET /foo HTTP/1.1", host: "localhost:8080", request_id: "cd7706e903db672ac5fac333bc8db5ed" +``` + +[Back to TOC](#table-of-contents) + Methods ======= @@ -446,7 +466,7 @@ License ======= ``` -Copyright 2020 Kong Inc. +Copyright 2020-2023 Kong Inc. Licensed under the Apache License, Version 2.0 (the "License"); you may not use this file except in compliance with the License. diff --git a/config b/config index aa2d484e..87aa299c 100644 --- a/config +++ b/config @@ -8,6 +8,7 @@ ngx_module_srcs=" \ $ngx_addon_dir/src/ngx_http_lua_kong_tag.c \ $ngx_addon_dir/src/ngx_http_lua_kong_module.c \ $ngx_addon_dir/src/ngx_http_lua_kong_log.c \ + $ngx_addon_dir/src/ngx_http_lua_kong_log_handler.c \ $ngx_addon_dir/src/ssl/ngx_lua_kong_ssl.c \ " diff --git a/src/ngx_http_lua_kong_common.h b/src/ngx_http_lua_kong_common.h index 96f2974b..f3058165 100644 --- a/src/ngx_http_lua_kong_common.h +++ b/src/ngx_http_lua_kong_common.h @@ -27,11 +27,13 @@ typedef struct { ngx_lua_kong_ssl_ctx_t ssl_ctx; ngx_str_t grpc_authority; + ngx_http_log_handler_pt orig_log_handler; } ngx_http_lua_kong_ctx_t; typedef struct { - ngx_str_t tag; + ngx_str_t tag; + ngx_int_t request_id_var_index; } ngx_http_lua_kong_loc_conf_t; @@ -47,4 +49,7 @@ extern ngx_module_t ngx_http_lua_kong_module; ngx_http_lua_kong_ctx_t *ngx_http_lua_kong_get_module_ctx( ngx_http_request_t *r); +char *ngx_http_lua_kong_error_log_init( + ngx_conf_t *cf); + #endif /* _NGX_HTTP_LUA_KONG_COMMON_H_INCLUDED_ */ diff --git a/src/ngx_http_lua_kong_directive.h b/src/ngx_http_lua_kong_directive.h index fe8c8fc5..7ba7aa98 100644 --- a/src/ngx_http_lua_kong_directive.h +++ b/src/ngx_http_lua_kong_directive.h @@ -26,4 +26,8 @@ char * ngx_http_lua_kong_load_var_index(ngx_conf_t *cf, ngx_command_t *cmd, void *conf); +char * +ngx_http_lua_kong_error_log_request_id(ngx_conf_t *cf, ngx_command_t *cmd, + void *conf); + #endif /* _NGX_HTTP_LUA_KONG_DIRECTIVE_H_INCLUDED_ */ diff --git a/src/ngx_http_lua_kong_log_handler.c b/src/ngx_http_lua_kong_log_handler.c new file mode 100644 index 00000000..380d8af3 --- /dev/null +++ b/src/ngx_http_lua_kong_log_handler.c @@ -0,0 +1,147 @@ +/** + * Copyright 2019-2023 Kong Inc. + + * Licensed 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. + */ + +#include "ngx_http_lua_kong_common.h" + + +/* + * This function contains the logic to append the Request ID to + * the error log line when being called + */ +static u_char * +ngx_http_lua_kong_error_log_handler(ngx_http_request_t *r, u_char *buf, size_t len) +{ + ngx_http_variable_value_t *value; + ngx_http_lua_kong_loc_conf_t *lcf; + + lcf = ngx_http_get_module_loc_conf(r, ngx_http_lua_kong_module); + if (lcf->request_id_var_index == NGX_CONF_UNSET) { + return buf; + } + + value = ngx_http_get_indexed_variable(r, lcf->request_id_var_index); + if (value == NULL || value->not_found) { + return buf; + } + + buf = ngx_snprintf(buf, len, ", request_id: \"%v\"", value); + + return buf; +} + + +/* + * This function replaces the original HTTP error + * log handler (r->log_handler). It executes the original logic + * and then our error log handler: ngx_http_lua_kong_error_log_handler + */ +static u_char * +ngx_http_lua_kong_combined_error_log_handler(ngx_http_request_t *r, + ngx_http_request_t *sr, u_char *buf, size_t len) +{ + u_char *p; + ngx_http_lua_kong_ctx_t *ctx; + + ctx = ngx_http_lua_kong_get_module_ctx(r); + if (ctx == NULL || ctx->orig_log_handler == NULL) { + return buf; + } + + /* original log handler */ + p = ctx->orig_log_handler(r, sr, buf, len); + len -= p - buf; + buf = p; + + /* Kong log handler */ + buf = ngx_http_lua_kong_error_log_handler(r, buf, len); + + return buf; +} + + +static ngx_int_t +ngx_http_lua_kong_replace_error_log_handler(ngx_http_request_t *r) +{ + ngx_http_lua_kong_ctx_t *ctx; + + ctx = ngx_http_lua_kong_get_module_ctx(r); + if (ctx == NULL) { + return NGX_ERROR; + } + + if (r->log_handler == NULL) { + return NGX_DECLINED; + } + + /* + * Store the original log handler in ctx->orig_log_handler, replace + * it with the combined log handler, which will execute the original + * handler's logic in addition to our own. + */ + ctx->orig_log_handler = r->log_handler; + r->log_handler = ngx_http_lua_kong_combined_error_log_handler; + + return NGX_DECLINED; +} + + +char * +ngx_http_lua_kong_error_log_init(ngx_conf_t *cf) +{ + ngx_http_handler_pt *h; + ngx_http_core_main_conf_t *cmcf; + + cmcf = ngx_http_conf_get_module_main_conf(cf, ngx_http_core_module); + + h = ngx_array_push(&cmcf->phases[NGX_HTTP_POST_READ_PHASE].handlers); + if (h == NULL) { + ngx_conf_log_error(NGX_LOG_EMERG, cf, 0, + "failed setting error log handler"); + return NGX_CONF_ERROR; + } + + *h = ngx_http_lua_kong_replace_error_log_handler; + + return NGX_CONF_OK; +} + + +char * +ngx_http_lua_kong_error_log_request_id(ngx_conf_t *cf, ngx_command_t *cmd, void *conf) +{ + ngx_str_t *value; + ngx_http_lua_kong_loc_conf_t *lcf = conf; + + value = cf->args->elts; + + if (value[1].data[0] != '$') { + ngx_conf_log_error(NGX_LOG_EMERG, cf, 0, + "invalid variable name \"%V\"", &value[1]); + return NGX_CONF_ERROR; + } + + value[1].len--; + value[1].data++; + + lcf->request_id_var_index = ngx_http_get_variable_index(cf, &value[1]); + if (lcf->request_id_var_index == NGX_ERROR) { + return NGX_CONF_ERROR; + } + + return NGX_CONF_OK; +} + + diff --git a/src/ngx_http_lua_kong_module.c b/src/ngx_http_lua_kong_module.c index 085bc498..81c698d8 100644 --- a/src/ngx_http_lua_kong_module.c +++ b/src/ngx_http_lua_kong_module.c @@ -20,6 +20,7 @@ static ngx_int_t ngx_http_lua_kong_init(ngx_conf_t *cf); static void* ngx_http_lua_kong_create_loc_conf(ngx_conf_t* cf); +static char* ngx_http_lua_kong_merge_loc_conf(ngx_conf_t *cf, void *parent, void *child); static ngx_http_module_t ngx_http_lua_kong_module_ctx = { @@ -33,7 +34,7 @@ static ngx_http_module_t ngx_http_lua_kong_module_ctx = { NULL, /* merge server configuration */ ngx_http_lua_kong_create_loc_conf, /* create location configuration */ - NULL /* merge location configuration */ + ngx_http_lua_kong_merge_loc_conf /* merge location configuration */ }; @@ -53,6 +54,13 @@ static ngx_command_t ngx_http_lua_kong_commands[] = { offsetof(ngx_http_lua_kong_loc_conf_t, tag), NULL }, + { ngx_string("lua_kong_error_log_request_id"), + NGX_HTTP_MAIN_CONF|NGX_HTTP_SRV_CONF|NGX_HTTP_LOC_CONF|NGX_CONF_TAKE1, + ngx_http_lua_kong_error_log_request_id, + NGX_HTTP_LOC_CONF_OFFSET, + offsetof(ngx_http_lua_kong_loc_conf_t, request_id_var_index), + NULL }, + ngx_null_command }; @@ -76,6 +84,10 @@ ngx_module_t ngx_http_lua_kong_module = { static ngx_int_t ngx_http_lua_kong_init(ngx_conf_t *cf) { + if (ngx_http_lua_kong_error_log_init(cf) != NGX_CONF_OK) { + return NGX_ERROR; + } + return ngx_lua_kong_ssl_init(cf); } @@ -128,7 +140,22 @@ ngx_http_lua_kong_create_loc_conf(ngx_conf_t* cf) return NULL; } + conf->request_id_var_index = NGX_CONF_UNSET; + return conf; } +static char* +ngx_http_lua_kong_merge_loc_conf(ngx_conf_t *cf, void *parent, void *child) +{ + ngx_http_lua_kong_loc_conf_t *prev = parent; + ngx_http_lua_kong_loc_conf_t *conf = child; + + /* conf->tag is NGX_HTTP_LOC_CONF only */ + ngx_conf_merge_value(conf->request_id_var_index, prev->request_id_var_index, NGX_CONF_UNSET); + + return NGX_CONF_OK; +} + + diff --git a/t/009-error-log-append.t b/t/009-error-log-append.t new file mode 100644 index 00000000..fff71039 --- /dev/null +++ b/t/009-error-log-append.t @@ -0,0 +1,235 @@ +use Test::Nginx::Socket::Lua; + +#worker_connections(1014); +#master_process_enabled(1); +#log_level('warn'); + +repeat_each(2); + +plan tests => repeat_each() * (blocks() * 5) + 10; + +#no_diff(); +no_long_string(); +#master_on(); +#workers(2); +check_accum_error_log(); +run_tests(); + +__DATA__ + + +=== TEST 1: sanity: without directive there is no appended request ID +and the original error log is preserved +--- http_config + lua_package_path "../lua-resty-core/lib/?.lua;lualib/?.lua;;"; +--- config + location = /test { + content_by_lua_block { + ngx.log(ngx.INFO, "log_msg") + ngx.exit(200) + } + } +--- request +GET /test +--- error_log eval +qr/log_msg.*client:.*server:.*request:.*host:.*$/ +--- no_error_log eval +[ + qr/log_msg.*request_id/, + "[error]", + "[crit]", + "[alert]", +] + + +=== TEST 2: value is appended correctly to error logs +--- http_config + lua_package_path "../lua-resty-core/lib/?.lua;lualib/?.lua;;"; +--- config + location = /test { + set $my_var "yay!"; + lua_kong_error_log_request_id $my_var; + content_by_lua_block { + ngx.log(ngx.INFO, "log_msg") + ngx.exit(200) + } + } +--- request +GET /test +--- error_log eval +qr/log_msg.*request_id: "yay!"$/ +--- no_error_log +[error] +[crit] +[alert] + + +=== TEST 3: value is appended correctly to error logs when a runtime error occurs +--- http_config + lua_package_path "../lua-resty-core/lib/?.lua;lualib/?.lua;;"; +--- config + location = /test { + set $req_id 123456; + lua_kong_error_log_request_id "$req_id"; + + content_by_lua_block { + error("error_message") + } + } +--- request +GET /test +--- error_code: 500 +--- error_log eval +qr/.*request_id: "123456".*$/ + + +=== TEST 4: scoping: value is appended correctly to error logs +based on the location where the directive is defined +--- http_config + lua_package_path "../lua-resty-core/lib/?.lua;lualib/?.lua;;"; +--- config + location = /append_req_id { + set $req_id_a 123456; + lua_kong_error_log_request_id $req_id_a; + + content_by_lua_block { + ngx.log(ngx.INFO, "log_msg") + ngx.exit(200) + } + } + location = /append_method { + set $req_id_b 654321; + lua_kong_error_log_request_id $req_id_b; + + content_by_lua_block { + ngx.log(ngx.INFO, "log_msg") + ngx.exit(200) + } + } +--- pipelined_requests eval +["GET /append_req_id", "GET /append_method"] +--- error_code eval +[200, 200, 200] +--- error_log eval +[ 'request_id: "123456"', 'request_id: "654321"' ] +--- no_error_log +[error] +[crit] +[alert] + + +=== TEST 5: scoping: value is NOT appended to error logs +for the location where the directive is NOT defined +--- http_config + lua_package_path "../lua-resty-core/lib/?.lua;lualib/?.lua;;"; +--- config + location = /append { + set $req_id 123456; + lua_kong_error_log_request_id $req_id; + + content_by_lua_block { + ngx.log(ngx.ERR, "log_msg") + ngx.exit(200) + } + } + + location = /no_append { + content_by_lua_block { + ngx.log(ngx.INFO, "log_msg") + ngx.exit(200) + } + } +--- request +GET /no_append +--- error_code: 200 +--- no_error_log eval +qr/log_msg.*request_id/ + + +=== TEST 6: scoping: value is appended correctly to error logs +when the directive is in the main configuration +--- http_config + lua_package_path "../lua-resty-core/lib/?.lua;lualib/?.lua;;"; + lua_kong_error_log_request_id $req_id; +--- config + set $req_id 123456; + location = /test { + content_by_lua_block { + ngx.log(ngx.INFO, "log_msg") + ngx.exit(200) + } + } +--- request +GET /test +--- error_code: 200 +--- error_log eval +qr/log_msg.*request_id: "123456"$/ +--- no_error_log +[error] +[crit] +[alert] + + +=== TEST 7: scoping: value is appended correctly to error logs +and the local directive overrides the global one +--- http_config + lua_package_path "../lua-resty-core/lib/?.lua;lualib/?.lua;;"; + lua_kong_error_log_request_id $req_id_global; +--- config + set $req_id_global global; + set $req_id_local local; + + location = /test { + lua_kong_error_log_request_id $req_id_local; + content_by_lua_block { + ngx.log(ngx.INFO, "log_msg") + ngx.exit(200) + } + } +--- request +GET /test +--- error_code: 200 +--- error_log eval +qr/log_msg.*request_id: "local"$/ +--- no_error_log eval +qr/log_msg.*request_id: "global"$/ + + +=== TEST 8: Request ID variable changes are applied to the error log output +--- http_config + lua_package_path "../lua-resty-core/lib/?.lua;lualib/?.lua;;"; +--- config + location = /test { + set $my_var ""; + lua_kong_error_log_request_id $my_var; + rewrite_by_lua_block { + ngx.log(ngx.INFO, "rewrite_0") + ngx.var.my_var = "changed_in_rewrite" + ngx.log(ngx.INFO, "rewrite_1") + ngx.var.my_var = "changed_in_rewrite_2" + ngx.log(ngx.INFO, "rewrite_2") + } + access_by_lua_block { + ngx.log(ngx.INFO, "access_0") + ngx.var.my_var = "changed_in_access" + ngx.log(ngx.INFO, "access_1") + ngx.var.my_var = "changed_in_access_2" + ngx.log(ngx.INFO, "access_2") + ngx.exit(200) + } + } +--- request +GET /test +--- error_log eval +[ + qr/rewrite_0.*request_id: ""$/, + qr/rewrite_1.*request_id: "changed_in_rewrite"$/, + qr/rewrite_2.*request_id: "changed_in_rewrite_2"$/, + qr/access_0.*request_id: "changed_in_rewrite_2"$/, + qr/access_1.*request_id: "changed_in_access"$/, + qr/access_2.*request_id: "changed_in_access_2"$/, +] +--- no_error_log +[error] +[crit] +[alert]