feat(request-id): request trace id

Kong · Jul 28, 2023 · d466f6b · d466f6b
1 parent 85b3809
commit d466f6b
Show file tree

Hide file tree

Showing 12 changed files with 126 additions and 6 deletions.
diff --git a/kong/error_handlers.lua b/kong/error_handlers.lua
@@ -64,7 +64,8 @@ return function(ctx)
 
   else
     local mime_type = utils.get_response_type(accept_header)
-    message = fmt(utils.get_error_template(mime_type), message)
+    local trace_id = ngx and ngx.var and ngx.var.request_trace_id or ""
+    message = fmt(utils.get_error_template(mime_type), message, trace_id)
     headers = { [CONTENT_TYPE] = mime_type }
 
   end

diff --git a/kong/globalpatches.lua b/kong/globalpatches.lua
@@ -81,6 +81,41 @@ return function(options)
   end
 
 
+  do -- patch `ngx.log` to include `ngx.var.request_trace_id`
+
+    local get_phase = ngx.get_phase
+    local ngx_log = ngx.log
+
+    local ngx_var_phases = {
+      set = true,
+      rewrite = true,
+      access = true,
+      content = true,
+      header_filter = true,
+      body_filter = true,
+      log = true,
+      balancer = true,
+    }
+
+    ngx.log = function(...)
+      local trace_id
+      if ngx_var_phases[get_phase()] then
+        trace_id = ngx and ngx.var and ngx.var.request_trace_id
+      end
+
+      if trace_id and trace_id ~= "" then
+        local args = {...}
+        args[#args + 1] = ", trace_id: " .. trace_id
+        return ngx_log(table.unpack(args))
+      end
+      return ngx_log(...)
+    end
+
+    _G.native_ngx_log = ngx_log
+
+  end
+
+
   do
     _G.native_timer_at = ngx.timer.at
     _G.native_timer_every = ngx.timer.every

diff --git a/kong/plugins/opentelemetry/handler.lua b/kong/plugins/opentelemetry/handler.lua
@@ -14,6 +14,7 @@ local ngx_DEBUG = ngx.DEBUG
 local ngx_now = ngx.now
 local ngx_update_time = ngx.update_time
 local ngx_req = ngx.req
+local ngx_var = ngx.var
 local ngx_get_headers = ngx_req.get_headers
 local propagation_parse = propagation.parse
 local propagation_set = propagation.set
@@ -113,6 +114,7 @@ function OpenTelemetryHandler:access(conf)
   if trace_id then
     root_span.trace_id = trace_id
     kong.ctx.plugin.trace_id = trace_id
+    ngx_var.request_trace_id = to_hex(trace_id)
   end
 
   -- overwrite root span's parent_id

diff --git a/kong/plugins/zipkin/handler.lua b/kong/plugins/zipkin/handler.lua
@@ -123,6 +123,8 @@ if subsystem == "http" then
       span_name = method .. ' ' .. path
     end
 
+    ngx_var.request_trace_id = to_hex(trace_id)
+
     local request_span = new_span(
       "SERVER",
       span_name,

diff --git a/kong/runloop/handler.lua b/kong/runloop/handler.lua
@@ -48,6 +48,7 @@ local clear_header      = ngx.req.clear_header
 local http_version      = ngx.req.http_version
 local escape            = require("kong.tools.uri").escape
 local encode            = require("string.buffer").encode
+local to_hex            = require("resty.string").to_hex
 
 
 local is_http_module   = subsystem == "http"
@@ -921,6 +922,15 @@ local function set_init_versions_in_cache()
 end
 
 
+local function set_trace_id_var()
+  local root_span = ngx.ctx.KONG_SPANS and ngx.ctx.KONG_SPANS[1]
+  local id_bin = root_span and root_span.trace_id or utils.get_rand_bytes(16)
+
+  var.request_trace_id = to_hex(id_bin)
+  ngx.log(ngx.ERR, "test log with trace id")
+end
+
+
 -- in the table below the `before` and `after` is to indicate when they run:
 -- before or after the plugins
 return {
@@ -1154,6 +1164,7 @@ return {
       local server_port = var.server_port
       ctx.host_port = HOST_PORTS[server_port] or server_port
       instrumentation.request(ctx)
+      set_trace_id_var()
     end,
   },
   access = {

diff --git a/kong/templates/nginx_kong.lua b/kong/templates/nginx_kong.lua
@@ -23,6 +23,25 @@ lua_shared_dict kong_db_cache               ${{MEM_CACHE_SIZE}};
 lua_shared_dict kong_db_cache_miss          12m;
 lua_shared_dict kong_secrets                5m;
 
+map $request_trace_id $log_tr_id {
+    default            0;
+    "~*^[a-fA-F0-9]+$" 1;
+}
+
+map $request_trace_id $log_def {
+    default            1;
+    "~*^[a-fA-F0-9]+$" 0;
+}
+
+log_format def '$remote_addr - $remote_user [$time_local] '
+               '"$request" $status $body_bytes_sent '
+               '"$http_referer" "$http_user_agent"';
+
+log_format tr_id '[$request_trace_id] '
+                 '$remote_addr - $remote_user [$time_local] '
+                 '"$request" $status $body_bytes_sent '
+                 '"$http_referer" "$http_user_agent"';
+
 underscores_in_headers on;
 > if ssl_ciphers then
 ssl_ciphers ${{SSL_CIPHERS}};
@@ -72,7 +91,8 @@ server {
     error_page 400 404 405 408 411 412 413 414 417 494 /kong_error_handler;
     error_page 500 502 503 504                     /kong_error_handler;
 
-    access_log ${{PROXY_ACCESS_LOG}};
+    access_log ${{PROXY_ACCESS_LOG}} tr_id if=$log_tr_id;
+    access_log ${{PROXY_ACCESS_LOG}} def if=$log_def;
     error_log  ${{PROXY_ERROR_LOG}} ${{LOG_LEVEL}};
 
 > if proxy_ssl_enabled then
@@ -130,6 +150,7 @@ server {
         set $upstream_x_forwarded_port   '';
         set $upstream_x_forwarded_path   '';
         set $upstream_x_forwarded_prefix '';
+        set $request_trace_id      '';
         set $kong_proxy_mode             'http';
 
         proxy_http_version      1.1;

diff --git a/spec/fixtures/custom_nginx.template b/spec/fixtures/custom_nginx.template
@@ -95,6 +95,26 @@ http {
     lua_shared_dict kong_db_cache               ${{MEM_CACHE_SIZE}};
     lua_shared_dict kong_db_cache_miss          12m;
     lua_shared_dict kong_secrets                5m;
+
+    map $request_trace_id $log_tr_id {
+        default            0;
+        "~*^[a-fA-F0-9]+$" 1;
+    }
+
+    map $request_trace_id $log_def {
+        default            1;
+        "~*^[a-fA-F0-9]+$" 0;
+    }
+
+    log_format def '$remote_addr - $remote_user [$time_local] '
+                   '"$request" $status $body_bytes_sent '
+                   '"$http_referer" "$http_user_agent"';
+
+    log_format tr_id '[$request_trace_id] '
+                     '$remote_addr - $remote_user [$time_local] '
+                     '"$request" $status $body_bytes_sent '
+                     '"$http_referer" "$http_user_agent"';
+
 > if role == "control_plane" then
     lua_shared_dict kong_clustering             5m;
 > end
@@ -149,7 +169,8 @@ http {
         error_page 400 404 405 408 411 412 413 414 417 494 /kong_error_handler;
         error_page 500 502 503 504                     /kong_error_handler;
 
-        access_log ${{PROXY_ACCESS_LOG}};
+        access_log ${{PROXY_ACCESS_LOG}} tr_id if=$log_tr_id;
+        access_log ${{PROXY_ACCESS_LOG}} def if=$log_def;
         error_log  ${{PROXY_ERROR_LOG}} ${{LOG_LEVEL}};
 
 > if proxy_ssl_enabled then
@@ -207,6 +228,7 @@ http {
             set $upstream_x_forwarded_port   '';
             set $upstream_x_forwarded_path   '';
             set $upstream_x_forwarded_prefix '';
+            set $request_trace_id      '';
             set $kong_proxy_mode             'http';
 
             proxy_http_version      1.1;

diff --git a/spec/fixtures/default_nginx.template b/spec/fixtures/default_nginx.template
@@ -47,6 +47,26 @@ http {
     lua_shared_dict kong_db_cache               ${{MEM_CACHE_SIZE}};
     lua_shared_dict kong_db_cache_miss          12m;
     lua_shared_dict kong_secrets                5m;
+
+    map $request_trace_id $log_tr_id {
+        default            0;
+        "~*^[a-fA-F0-9]+$" 1;
+    }
+
+    map $request_trace_id $log_def {
+        default            1;
+        "~*^[a-fA-F0-9]+$" 0;
+    }
+
+    log_format def '$remote_addr - $remote_user [$time_local] '
+                   '"$request" $status $body_bytes_sent '
+                   '"$http_referer" "$http_user_agent"';
+
+    log_format tr_id '[$request_trace_id] '
+                     '$remote_addr - $remote_user [$time_local] '
+                     '"$request" $status $body_bytes_sent '
+                     '"$http_referer" "$http_user_agent"';
+
 > if database == "cassandra" then
     lua_shared_dict kong_cassandra              5m;
 > end
@@ -105,7 +125,8 @@ http {
         error_page 400 404 405 408 411 412 413 414 417 494 /kong_error_handler;
         error_page 500 502 503 504                     /kong_error_handler;
 
-        access_log ${{PROXY_ACCESS_LOG}};
+        access_log ${{PROXY_ACCESS_LOG}} tr_id if=$log_tr_id;
+        access_log ${{PROXY_ACCESS_LOG}} def if=$log_def;
         error_log  ${{PROXY_ERROR_LOG}} ${{LOG_LEVEL}};
 
 > if proxy_ssl_enabled then
@@ -163,6 +184,7 @@ http {
             set $upstream_x_forwarded_port   '';
             set $upstream_x_forwarded_path   '';
             set $upstream_x_forwarded_prefix '';
+            set $request_trace_id      '';
             set $kong_proxy_mode             'http';
 
             proxy_http_version      1.1;

diff --git a/spec/fixtures/error_templates/error_template.html b/spec/fixtures/error_templates/error_template.html
@@ -7,5 +7,6 @@
   <body>
     <h1>Not the default</h1>
     <p>%s.</p>
+    <p>trace_id: %s</p>
   </body>
 </html>
diff --git a/spec/fixtures/error_templates/error_template.json b/spec/fixtures/error_templates/error_template.json
@@ -1,3 +1,4 @@
 {
-  "custom_template_message":"%s"
+  "custom_template_message":"%s",
+  "trace_id":"%s"
 }
diff --git a/spec/fixtures/error_templates/error_template.plain b/spec/fixtures/error_templates/error_template.plain
@@ -1 +1,2 @@
-custom plain template: %s\n
+custom plain template: %s\n
+trace_id: %s\n
diff --git a/spec/fixtures/error_templates/error_template.xml b/spec/fixtures/error_templates/error_template.xml
@@ -2,4 +2,5 @@
 <error>
   <message>custom template</message>
   <message>%s</message>
+  <message>%s</message>
 </error>