feat(src): request id (#65 + #70) (#73)

* feat(error_log): custom error handler (#65)

* Defines a new error log handler and a directive
  lua_kong_error_log_request_id that enable configuring a Request ID
  from the value of an nginx variable, to append to the error log.
* includes tests for the new directive

* tests(*): fix github workflow

Co-authored-by: Chrono <[email protected]>
Co-authored-by: Datong Sun <[email protected]>

* tests(stream): fix mockbin failing tests

* feat(variables): add new variable `$kong_request_id` (#70)

Similar to `$request_id`, but from pseudo-random number source instead of OpenSSL's `RAND_bytes`
for better performance.

KAG-2734
---------
Co-authored-by: Chrono <[email protected]>
Co-authored-by: Datong Sun <[email protected]>

Author: 3 people

README.md

@@ -11,8 +11,11 @@ Table of Contents
 * [Install](#install)
 * [Directives](#directives)
     * [lua_kong_load_var_index](#lua_kong_load_var_index)
+    * [lua\_kong\_error\_log\_request\_id](#lua_kong_error_log_request_id)
 * [Methods](#methods)
     * [resty.kong.tls.request\_client\_certificate](#restykongtlsrequest_client_certificate)
+* [Variables](#variables)
+    * [$kong\_request\_id](#kong_request_id)
     * [resty.kong.tls.disable\_session\_reuse](#restykongtlsdisable_session_reuse)
     * [resty.kong.tls.get\_full\_client\_certificate\_chain](#restykongtlsget_full_client_certificate_chain)
     * [resty.kong.tls.set\_upstream\_cert\_and\_key](#restykongtlsset_upstream_cert_and_key)
@@ -121,6 +124,25 @@ indexed variable access.
 
 [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
 =======
 
@@ -147,6 +169,16 @@ This function returns `true` when the call is successful. Otherwise it returns
 
 [Back to TOC](#table-of-contents)
 
+Variables
+=========
+
+$kong\_request\_id
+------------------
+Unique request identifier generated from 16 pseudo-random bytes, in hexadecimal.
+This variable is indexed.
+
+[Back to TOC](#table-of-contents)
+
 resty.kong.tls.disable\_session\_reuse
 --------------------------------------
 **syntax:** *succ, err = resty.kong.tls.disable\_session\_reuse()*
@@ -398,7 +430,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.

config

@@ -4,8 +4,10 @@ ngx_module_srcs=" \
                 $ngx_addon_dir/src/ngx_http_lua_kong_apple_m1.c \
                 $ngx_addon_dir/src/ngx_http_lua_kong_grpc.c \
                 $ngx_addon_dir/src/ngx_http_lua_kong_ssl.c \
-                $ngx_addon_dir/src/ngx_http_lua_kong_var.c \
+                $ngx_addon_dir/src/ngx_http_lua_kong_var_index.c \
                 $ngx_addon_dir/src/ngx_http_lua_kong_module.c \
+                $ngx_addon_dir/src/ngx_http_lua_kong_log_handler.c \
+                $ngx_addon_dir/src/ngx_http_lua_kong_vars.c \
                 "
 
 ngx_module_incs="$ngx_addon_dir/src"

src/ngx_http_lua_kong_common.h

@@ -33,9 +33,15 @@ typedef struct {
     unsigned            upstream_ssl_verify:1;
     unsigned            upstream_ssl_verify_set:1;
     unsigned            upstream_ssl_verify_depth_set:1;
+    ngx_http_log_handler_pt  orig_log_handler;
 } ngx_http_lua_kong_ctx_t;
 
 
+typedef struct {
+    ngx_int_t                request_id_var_index;
+} ngx_http_lua_kong_loc_conf_t;
+
+
 #ifdef NGX_LUA_USE_ASSERT
 #include <assert.h>
 #   define ngx_http_lua_kong_assert(a)  assert(a)
@@ -48,4 +54,10 @@ 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);
+
+ngx_int_t
+ngx_http_lua_kong_add_vars(ngx_conf_t *cf);
+
 #endif /* _NGX_HTTP_LUA_KONG_COMMON_H_INCLUDED_ */

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_ */

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;
+}
+
+

src/ngx_http_lua_kong_module.c

@@ -20,10 +20,12 @@
 
 
 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 = {
-    NULL,                                    /* preconfiguration */
+    ngx_http_lua_kong_add_vars,              /* preconfiguration */
     ngx_http_lua_kong_init,                  /* postconfiguration */
 
     NULL,                                    /* create main configuration */
@@ -32,8 +34,8 @@ static ngx_http_module_t ngx_http_lua_kong_module_ctx = {
     NULL,                                    /* create server configuration */
     NULL,                                    /* merge server configuration */
 
-    NULL,                                    /* create location configuration */
-    NULL                                     /* merge location configuration */
+    ngx_http_lua_kong_create_loc_conf,       /* create location configuration */
+    ngx_http_lua_kong_merge_loc_conf         /* merge location configuration */
 };
 
 static ngx_command_t ngx_http_lua_kong_commands[] = {
@@ -45,6 +47,13 @@ static ngx_command_t ngx_http_lua_kong_commands[] = {
       0,
       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
 };
 
@@ -68,6 +77,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_http_lua_kong_ssl_init(cf);
 }
 
@@ -112,3 +125,32 @@ ngx_http_lua_kong_get_module_ctx(ngx_http_request_t *r)
 }
 
 
+static void *
+ngx_http_lua_kong_create_loc_conf(ngx_conf_t* cf)
+{
+    ngx_http_lua_kong_loc_conf_t *conf;
+
+    conf = ngx_pcalloc(cf->pool, sizeof(ngx_http_lua_kong_loc_conf_t));
+    if (conf == NULL) {
+        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;
+}
+
+

src/ngx_http_lua_kong_var.c renamed to src/ngx_http_lua_kong_var_index.c

@@ -72,7 +72,7 @@ static ngx_str_t default_vars[] = {
     ngx_string("server_addr"),
     ngx_string("server_port"),
 
-/* --with-http_ssl_module */
+    /* --with-http_ssl_module */
 #if (NGX_SSL)
     ngx_string("ssl_cipher"),
     ngx_string("ssl_client_raw_cert"),
@@ -86,6 +86,9 @@ static ngx_str_t default_vars[] = {
     ngx_string("upstream_http_upgrade"),
     ngx_string("upstream_status"),
 
+    /* lua-kong-module vars */
+    ngx_string("kong_request_id"),
+
     ngx_null_string
 };