diff --git a/src/ngx_http_apisix_module.c b/src/ngx_http_apisix_module.c index 024e5ea..260d839 100644 --- a/src/ngx_http_apisix_module.c +++ b/src/ngx_http_apisix_module.c @@ -19,12 +19,20 @@ static ngx_str_t remote_port = ngx_string("remote_port"); static ngx_str_t realip_remote_addr = ngx_string("realip_remote_addr"); static ngx_str_t realip_remote_port = ngx_string("realip_remote_port"); - +static ngx_int_t ngx_http_apisix_init(ngx_conf_t *cf); static void *ngx_http_apisix_create_main_conf(ngx_conf_t *cf); static void *ngx_http_apisix_create_loc_conf(ngx_conf_t *cf); static char *ngx_http_apisix_merge_loc_conf(ngx_conf_t *cf, void *parent, void *child); +static ngx_int_t +ngx_http_apisix_init(ngx_conf_t *cf) +{ + if (ngx_http_apisix_error_log_init(cf) != NGX_CONF_OK) { + return NGX_ERROR; + } + return NGX_OK; +} static ngx_command_t ngx_http_apisix_cmds[] = { { ngx_string("apisix_delay_client_max_body_check"), @@ -33,14 +41,20 @@ static ngx_command_t ngx_http_apisix_cmds[] = { NGX_HTTP_LOC_CONF_OFFSET, offsetof(ngx_http_apisix_loc_conf_t, delay_client_max_body_check), NULL }, - + { + ngx_string("lua_error_log_request_id"), + NGX_HTTP_MAIN_CONF|NGX_HTTP_SRV_CONF|NGX_HTTP_LOC_CONF|NGX_CONF_TAKE1, + ngx_http_apisix_error_log_request_id, + NGX_HTTP_LOC_CONF_OFFSET, + offsetof(ngx_http_apisix_loc_conf_t, apisix_request_id_var_index), + NULL + }, ngx_null_command }; - static ngx_http_module_t ngx_http_apisix_module_ctx = { NULL, /* preconfiguration */ - NULL, /* postconfiguration */ + ngx_http_apisix_init, /* postconfiguration */ ngx_http_apisix_create_main_conf, /* create main configuration */ NULL, /* init main configuration */ @@ -88,7 +102,6 @@ ngx_http_apisix_create_main_conf(ngx_conf_t *cf) return acf; } - static void * ngx_http_apisix_create_loc_conf(ngx_conf_t *cf) { @@ -100,7 +113,7 @@ ngx_http_apisix_create_loc_conf(ngx_conf_t *cf) } conf->delay_client_max_body_check = NGX_CONF_UNSET; - + conf->apisix_request_id_var_index = NGX_CONF_UNSET; return conf; } @@ -111,6 +124,7 @@ ngx_http_apisix_merge_loc_conf(ngx_conf_t *cf, void *parent, void *child) ngx_http_apisix_loc_conf_t *prev = parent; ngx_http_apisix_loc_conf_t *conf = child; + ngx_conf_merge_value(conf->apisix_request_id_var_index, prev->apisix_request_id_var_index, NGX_CONF_UNSET); ngx_conf_merge_value(conf->delay_client_max_body_check, prev->delay_client_max_body_check, 0); @@ -825,3 +839,117 @@ ngx_http_apisix_is_ntls_enabled(ngx_http_conf_ctx_t *conf_ctx) acf = ngx_http_get_module_main_conf(conf_ctx, ngx_http_apisix_module); return acf->enable_ntls; } + +/*******************Log handler***************** */ +static u_char* +ngx_http_apisix_error_log_handler(ngx_http_request_t *r, u_char *buf, size_t len) +{ + ngx_http_variable_value_t *request_id_var; + ngx_http_apisix_loc_conf_t *loc_conf; + + loc_conf = ngx_http_get_module_loc_conf(r, ngx_http_apisix_module); + if (loc_conf->apisix_request_id_var_index == NGX_CONF_UNSET) { + return buf; + } + + request_id_var = ngx_http_get_indexed_variable(r, loc_conf->apisix_request_id_var_index); + if (request_id_var == NULL || request_id_var->not_found) { + return buf; + } + buf = ngx_snprintf(buf, len, ", request_id: \"%v\"", request_id_var); + return buf; +} + + +static u_char* +ngx_http_apisix_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_apisix_ctx_t *ctx; + + ctx = ngx_http_apisix_get_module_ctx(r); + if (ctx == NULL || ctx->orig_log_handler == NULL) { + return buf; + } + + //Get the original log message + p = ctx->orig_log_handler(r, sr, buf, len); + //p - buf calculates the number of bytes written by the original log handler into the buffer. + //len -= (p - buf) reduces the remaining buffer length by the amount already used. + len -= p-buf; + + //Apisix log handler + buf = ngx_http_apisix_error_log_handler(r, buf, len); + return buf; +} + + +static ngx_int_t +ngx_http_apisix_replace_error_log_handler(ngx_http_request_t *r) +{ + ngx_http_apisix_ctx_t *ctx; + + ctx = ngx_http_apisix_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_apisix_combined_error_log_handler; + + return NGX_DECLINED; +} + + +char * +ngx_http_apisix_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_apisix_replace_error_log_handler; + + return NGX_CONF_OK; +} + + +char * +ngx_http_apisix_error_log_request_id(ngx_conf_t *cf, ngx_command_t *cmd, void *conf) +{ + ngx_str_t *value; + ngx_http_apisix_loc_conf_t *loc_conf = 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++; + + loc_conf->apisix_request_id_var_index = ngx_http_get_variable_index(cf, &value[1]); + if (loc_conf->apisix_request_id_var_index == NGX_ERROR) { + return NGX_CONF_ERROR; + } + + return NGX_CONF_OK; +} + diff --git a/src/ngx_http_apisix_module.h b/src/ngx_http_apisix_module.h index a363e8f..1677951 100644 --- a/src/ngx_http_apisix_module.h +++ b/src/ngx_http_apisix_module.h @@ -7,6 +7,8 @@ typedef struct { ngx_flag_t delay_client_max_body_check; + ngx_int_t apisix_request_id_var_index; + } ngx_http_apisix_loc_conf_t; @@ -24,7 +26,7 @@ typedef struct { off_t client_max_body_size; ngx_http_apisix_gzip_t *gzip; - + ngx_http_log_handler_pt orig_log_handler; unsigned client_max_body_size_set:1; unsigned mirror_enabled:1; unsigned request_buffering:1; @@ -57,5 +59,7 @@ ngx_int_t ngx_http_apisix_is_body_filter_by_lua_skipped(ngx_http_request_t *r); ngx_flag_t ngx_http_apisix_is_ntls_enabled(ngx_http_conf_ctx_t *conf_ctx); - +char * ngx_http_apisix_error_log_request_id(ngx_conf_t *cf, ngx_command_t *cmd, void *conf); +char * ngx_http_apisix_error_log_init(ngx_conf_t *cf); +char * ngx_http_apisix_error_log_request_id(ngx_conf_t *cf, ngx_command_t *cmd, void *conf); #endif /* _NGX_HTTP_APISIX_H_INCLUDED_ */ diff --git a/t/request-id-err-log.t b/t/request-id-err-log.t new file mode 100644 index 0000000..6818749 --- /dev/null +++ b/t/request-id-err-log.t @@ -0,0 +1,192 @@ +use t::APISIX_NGINX 'no_plan'; + +run_tests; + +__DATA__ + +=== TEST 1: apisix_request_id in error log set +--- config + location /t { + set $apisix_request_id 1234; + lua_error_log_request_id $apisix_request_id; + content_by_lua_block { + ngx.log(ngx.INFO, "log_msg") + ngx.exit(200) + } + } +--- request +GET /t +--- error_log eval +qr/log_msg.*request_id: "1234"$/ +--- no_error_log +[error] +[crit] +[alert] + + + +=== TEST 2: apisix_request_id in error log set when a runtime error occurs +--- config + location /t { + set $apisix_request_id 1234; + lua_error_log_request_id $apisix_request_id; + content_by_lua_block { + error("error_message") + } + } +--- request +GET /t +--- error_code: 500 +--- error_log eval +qr/.*request_id: "1234".*$/ + + + +=== TEST 3: scoping: value is appended correctly to error logs based on the location where the directive is defined +--- config + location = /append_method { + set $apisix_request_id_b 654321; + lua_error_log_request_id $apisix_request_id_b; + content_by_lua_block { + ngx.log(ngx.INFO, "log_msg") + ngx.exit(200) + } + } + location = /append_req_id { + set $apisix_request_id_a 123456; + lua_error_log_request_id $apisix_request_id_a; + content_by_lua_block { + ngx.log(ngx.INFO, "log_msg") + ngx.exit(200) + } + } +--- request +GET /append_method +--- error_log eval +qr/log_msg.*request_id: "654321"$/ +--- no_error_log +[error] +[crit] +[alert] + + + +=== TEST 4: Send request to different location +--- request +GET /append_req_id +--- error_log eval +qr/log_msg.*request_id: "123456"$/ +--- 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 +--- config + location /append { + set $apisix_request_id 123456; + lua_error_log_request_id $apisix_request_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_error_log_request_id $apisix_request_id; +--- config + set $apisix_request_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_error_log_request_id $apisix_request_id_global; +--- config + set $apisix_request_id_global global; + set $apisix_request_id_local local; + + location = /test { + lua_error_log_request_id $apisix_request_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 +--- config + location = /test { + set $my_var ""; + lua_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]