add tests

Author: Revolyssup

src/ngx_http_apisix_module.c

@@ -854,12 +854,12 @@ ngx_http_apisix_error_log_handler(ngx_http_request_t *r, u_char *buf, size_t len
 
 		loc_conf = ngx_http_get_module_loc_conf(r, ngx_http_apisix_module);
 		if (loc_conf->request_id_var_index == NGX_CONF_UNSET) {
-				return buf;
+			return buf;
 		}
 
 		request_id_var = ngx_http_get_indexed_variable(r, loc_conf->request_id_var_index);
 		if (request_id_var == NULL || request_id_var->not_found) {
-				return buf;
+			return buf;
 		}
 		buf = ngx_snprintf(buf, len, ", request_id: \"%v\"", request_id_var);
 		return buf;
@@ -875,23 +875,23 @@ ngx_http_apisix_error_log_handler(ngx_http_request_t *r, u_char *buf, size_t len
 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;
+    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;
-		}
+    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;
+    //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;
+    //Apisix log handler
+    buf = ngx_http_apisix_error_log_handler(r, buf, len);
+    return buf;
 }
 
 
@@ -900,47 +900,47 @@ ngx_http_apisix_combined_error_log_handler(ngx_http_request_t *r, ngx_http_reque
 static ngx_int_t
 ngx_http_apisix_replace_error_log_handler(ngx_http_request_t *r)
 {
-		ngx_http_apisix_ctx_t *ctx;
+    ngx_http_apisix_ctx_t *ctx;
 
-		ctx = ngx_http_apisix_get_module_ctx(r);
-		if (ctx == NULL) {
-				return NGX_OK;
-		}
+    ctx = ngx_http_apisix_get_module_ctx(r);
+    if (ctx == NULL) {
+        return NGX_OK;
+    }
 
-		if (r->log_handler == NULL){
-				return NGX_DECLINED;
-		}
+    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;
+/*
+    * 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;
+    return NGX_DECLINED;
 }
 
 //This function is part of postconfiguration passed to module context and will override the post_read_phase with custom log handler.
 // It extracts the pointer to log handler from the post read phase handlers and then override that with new function address.
 char *
 ngx_http_apisix_error_log_init(ngx_conf_t *cf)
 {
-		ngx_http_handler_pt *h;
-		ngx_http_core_main_conf_t *cmcf;
+    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;
-    }
+    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;
+    *h = ngx_http_apisix_replace_error_log_handler;
 
-		return NGX_CONF_OK;
+    return NGX_CONF_OK;
 }
 
 // This function does the translation of the configuration file to the internal representation.
@@ -949,22 +949,22 @@ 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;
+    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 = 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++;
+    value[1].len--;
+    value[1].data++;
 
-		loc_conf->request_id_var_index = ngx_http_get_variable_index(cf, &value[1]);
-		if (loc_conf->request_id_var_index == NGX_ERROR) {
-				return NGX_CONF_ERROR;
-		}
+    loc_conf->request_id_var_index = ngx_http_get_variable_index(cf, &value[1]);
+    if (loc_conf->request_id_var_index == NGX_ERROR) {
+        return NGX_CONF_ERROR;
+    }
 
-		return NGX_CONF_OK;
+    return NGX_CONF_OK;
 }
 

t/request-id-err-log.t

@@ -15,10 +15,170 @@ __DATA__
         }
     }
 --- request
-GET /test
+GET /t
 --- error_log eval
 qr/log_msg.*request_id: "1234"$/
 --- no_error_log
 [error]
 [crit]
 [alert]
+
+
+
+=== TEST 2: request_id in error log set when a runtime error occurs
+--- config
+    location /t {
+		set $request_id_new 1234;
+        apisix_request_id_var $request_id_new;
+        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_req_id {
+        set $req_id_a 123456;
+        apisix_request_id_var $req_id_a;
+        content_by_lua_block {
+            ngx.log(ngx.INFO, "log_msg")
+            ngx.exit(200)
+        }
+    }
+    location /append_method {
+        set $req_id_b 654321;
+        apisix_request_id_var $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 4: scoping: value is NOT appended to error logs for the location where the directive is NOT defined
+--- config
+    location /append {
+        set $req_id 123456;
+        apisix_request_id_var $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 5: scoping: value is appended correctly to error logs when the directive is in the main configuration
+--- http_config
+    apisix_request_id_var $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 6: scoping: value is appended correctly to error logs and the local directive overrides the global one
+--- http_config
+    apisix_request_id_var $req_id_global;
+--- config
+    set $req_id_global global;
+    set $req_id_local local;
+
+    location = /test {
+        apisix_request_id_var $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 7: Request ID variable changes are applied to the error log output
+--- config
+    location = /test {
+        set $my_var "";
+        apisix_request_id_var $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]