Odd logs maybe potential bugs in 3.7.0 trying to wrap my head didn't see on 2.8.x

[jeremyjpj0916]

Is there an existing issue for this?

• I have searched the existing issues

Kong version ($ kong version)

3.7.0

Current Behavior

Logs like this are popping up in 1 of my 2 dev environments:

2024-06-12T20:34:00.799734253-05:00 2024/06/13 01:34:00 [warn] 133442#0: *169848 using uninitialized "upstream_uri" variable while logging request, client: xxx.xxx.x.xxx, server: kong_mtls, request: "GET /F5/status HTTP/1.1", host: "gateway-dev-dc.company.com"

2024-06-12T20:34:00.799776653-05:00 2024/06/13 01:34:00 [notice] 133442#0: *169848 [kong] globalpatches.lua:147 [kong-kafka-log] request headers truncated while logging request, client: xxx.xxx.x.xxx, server: kong_mtls, request: "GET /F5/status HTTP/1.1", host: "gateway-dev-dc.company.com"

Expected Behavior

No logs like this ideally.

I see upstream_uri present all around in the template and in my kong_mtls block that is basically a dup of the typical kong server block other than the fact is also requires mtls client comms ingress. My first thought was maybe when yall implemented this bit

# Load variable indexes
lua_kong_load_var_index default;

It only works for the kong server block and not for custom templates that maybe duplicate it twice essentially? But its in the http block so I imagined it would apply anything kong specific to both server blocks... and my kong_mtls block is identical to my kong server block with respect to where upstream_uri shows as present so I am not sure why it throws that.

The other line seems to invoke on the global patches lua file of kong here and I never recall that line comming up on Kong 2.8.x with respect to running this plugin:
https://github.com/Kong/kong/blob/3.7.0/kong/globalpatches.lua#L147

Is it like when a plugin sees a header too big or too many headers it throws that log statement? Is there some new limiter to header sizes being applied perhaps snagging me here? Relevant plugin https://github.com/Optum/kong-kafka-log

Worth noting the /F5/status calls are just GET requests with no bodies essentially very plain health check calls. That endpoint runs the request termination plugin on the route resource.

Steps To Reproduce

Hard to say, including my nginx custom template here for speculation:

pid pids/nginx.pid;

> if wasm and wasm_dynamic_module then
load_module $(wasm_dynamic_module);
> end

error_log ${{PROXY_ERROR_LOG}} ${{LOG_LEVEL}};

> if database == "off" then
lmdb_environment_path ${{LMDB_ENVIRONMENT_PATH}};
lmdb_map_size         ${{LMDB_MAP_SIZE}};

> if lmdb_validation_tag then
lmdb_validation_tag   $(lmdb_validation_tag);
> end

> end

# injected nginx_main_* directives
> for _, el in ipairs(nginx_main_directives) do
$(el.name) $(el.value);
> end

events {
    # injected nginx_events_* directives
> for _, el in ipairs(nginx_events_directives) do
    $(el.name) $(el.value);
> end
}

> if wasm then
wasm {
> for _, el in ipairs(nginx_wasm_main_shm_kv_directives) do
  shm_kv $(el.name) $(el.value);
> end

> for _, module in ipairs(wasm_modules_parsed) do
  module $(module.name) $(module.path);
> end

> for _, el in ipairs(nginx_wasm_main_directives) do
> if el.name == "shm_kv" then
  shm_kv * $(el.value);
> else
  $(el.name) $(el.value);
> end
> end

> if #nginx_wasm_wasmtime_directives > 0 then
  wasmtime {
> for _, el in ipairs(nginx_wasm_wasmtime_directives) do
    flag $(el.name) $(el.value);
> end
  }
> end -- wasmtime

> if #nginx_wasm_v8_directives > 0 then
  v8 {
> for _, el in ipairs(nginx_wasm_v8_directives) do
    flag $(el.name) $(el.value);
> end
  }
> end -- v8

> if #nginx_wasm_wasmer_directives > 0 then
  wasmer {
> for _, el in ipairs(nginx_wasm_wasmer_directives) do
    flag $(el.name) $(el.value);
> end
  }
> end -- wasmer

}
> end


http {
  server_tokens off;

  error_log ${{PROXY_ERROR_LOG}} ${{LOG_LEVEL}};


# enable capturing error logs
lua_capture_error_log 100k;

# exclusive oauth proxy shm caches for consumers and their cached token
lua_shared_dict kong_oauth_cache2       5m;
lua_shared_dict kong_oauth_cache_miss2  2m;
lua_shared_dict kong_oauth_cache_locks2 1m;

# exclusive oauth proxy token shm caches
lua_shared_dict kong_oauth_token_cache2       5m;
lua_shared_dict kong_oauth_token_cache_miss2  2m;
lua_shared_dict kong_oauth_token_cache_locks2 1m;

# exclusive oidc shm caches
lua_shared_dict kong_oidc_cache      10m;
lua_shared_dict kong_oidc_cache_miss  6m;
lua_shared_dict kong_oidc_cache_locks 3m;

lua_package_path       '${{LUA_PACKAGE_PATH}};;';
lua_package_cpath      '${{LUA_PACKAGE_CPATH}};;';
lua_socket_pool_size   ${{LUA_SOCKET_POOL_SIZE}};
lua_socket_log_errors  off;
lua_max_running_timers 4096;
lua_max_pending_timers 16384;

lua_ssl_verify_depth   ${{LUA_SSL_VERIFY_DEPTH}};
> if lua_ssl_trusted_certificate_combined then
lua_ssl_trusted_certificate '${{LUA_SSL_TRUSTED_CERTIFICATE_COMBINED}}';
> end
lua_ssl_protocols ${{NGINX_HTTP_LUA_SSL_PROTOCOLS}};


lua_shared_dict kong                        5m;
lua_shared_dict kong_locks                  8m;
lua_shared_dict kong_healthchecks           5m;
lua_shared_dict kong_cluster_events         5m;
lua_shared_dict kong_rate_limiting_counters 12m;
lua_shared_dict kong_core_db_cache          ${{MEM_CACHE_SIZE}};
lua_shared_dict kong_core_db_cache_miss     12m;
lua_shared_dict kong_db_cache               ${{MEM_CACHE_SIZE}};
lua_shared_dict kong_db_cache_miss          12m;
lua_shared_dict kong_secrets                5m;
underscores_in_headers on;

> if ssl_cipher_suite == 'old' then
lua_ssl_conf_command CipherString DEFAULT:@SECLEVEL=0;
proxy_ssl_conf_command CipherString DEFAULT:@SECLEVEL=0;
ssl_conf_command CipherString DEFAULT:@SECLEVEL=0;
grpc_ssl_conf_command CipherString DEFAULT:@SECLEVEL=0;
> end

> if ssl_ciphers then
ssl_ciphers ${{SSL_CIPHERS}};
> end

# injected nginx_http_* directives
> for _, el in ipairs(nginx_http_directives) do
$(el.name) $(el.value);
> end

init_by_lua_block {
> if test and coverage then
    require 'luacov'
    jit.off()
> end -- test and coverage
    Kong = require 'kong'
    Kong.init()
}

init_worker_by_lua_block {
    Kong.init_worker()
}

exit_worker_by_lua_block {
    Kong.exit_worker()
}

> if (role == "traditional" or role == "data_plane") and #proxy_listeners > 0 then
log_format kong_log_format '$remote_addr - $remote_user [$time_local] '
                           '"$request" $status $body_bytes_sent '
                           '"$http_referer" "$http_user_agent" '
                           'kong_request_id: "$kong_request_id"';

# Load variable indexes
lua_kong_load_var_index default;

upstream kong_upstream {
    server 0.0.0.1;

    # injected nginx_upstream_* directives
> for _, el in ipairs(nginx_upstream_directives) do
    $(el.name) $(el.value);
> end

    balancer_by_lua_block {
        Kong.balancer()
    }
}

server {
    server_name kong;
> for _, entry in ipairs(proxy_listeners) do
    listen $(entry.listener);
> end

> for _, entry in ipairs(proxy_listeners) do
> if entry.http2 then
    http2 on;
> break
> end
> end

    error_page 400 404 405 408 411 412 413 414 417 /kong_error_handler;
    error_page 494 =494                            /kong_error_handler;
    error_page 500 502 503 504                     /kong_error_handler;

    # Append the kong request id to the error log
    # https://github.com/Kong/lua-kong-nginx-module#lua_kong_error_log_request_id
    lua_kong_error_log_request_id $kong_request_id;

> if proxy_access_log_enabled then
>   if custom_proxy_access_log then
    access_log ${{PROXY_ACCESS_LOG}};
>   else
    access_log ${{PROXY_ACCESS_LOG}} kong_log_format;
>   end
> else
    access_log off;
> end
    
    error_log  ${{PROXY_ERROR_LOG}} ${{LOG_LEVEL}};

> if proxy_ssl_enabled then
> for i = 1, #ssl_cert do
    ssl_certificate     $(ssl_cert[i]);
    ssl_certificate_key $(ssl_cert_key[i]);
> end
    ssl_session_cache   shared:SSL:${{SSL_SESSION_CACHE_SIZE}};
    ssl_certificate_by_lua_block {
        Kong.ssl_certificate()
    }
> end

    # injected nginx_proxy_* directives
> for _, el in ipairs(nginx_proxy_directives) do
    $(el.name) $(el.value);
> end
> for _, ip in ipairs(trusted_ips) do
    set_real_ip_from $(ip);
> end

    rewrite_by_lua_block {
        Kong.rewrite()
    }

    access_by_lua_block {
        Kong.access()
    }

    header_filter_by_lua_block {
        Kong.header_filter()
        ngx.header["Server"] = nil
        ngx.header["Via"] = nil
    }

    body_filter_by_lua_block {
        Kong.body_filter()
    }

    log_by_lua_block {
        Kong.log()
    }

    location / {
        default_type                     '';

        set $ctx_ref                     '';
        set $upstream_te                 '';
        set $upstream_host               '';
        set $upstream_upgrade            '';
        set $upstream_connection         '';
        set $upstream_scheme             '';
        set $upstream_uri                '';
        set $upstream_x_forwarded_for    '';
        set $upstream_x_forwarded_proto  '';
        set $upstream_x_forwarded_host   '';
        set $upstream_x_forwarded_port   '';
        set $upstream_x_forwarded_path   '';
        set $upstream_x_forwarded_prefix '';
        set $kong_proxy_mode             'http';

        proxy_http_version      1.1;
        proxy_buffering          on;
        proxy_request_buffering  on;

        # injected nginx_location_* directives
> for _, el in ipairs(nginx_location_directives) do
        $(el.name) $(el.value);
> end

        proxy_set_header      TE                 $upstream_te;
        proxy_set_header      Host               $upstream_host;
        proxy_set_header      Upgrade            $upstream_upgrade;
        proxy_set_header      Connection         $upstream_connection;
        proxy_set_header      X-Forwarded-For    $upstream_x_forwarded_for;
        proxy_set_header      X-Forwarded-Proto  $upstream_x_forwarded_proto;
        proxy_set_header      X-Forwarded-Host   $upstream_x_forwarded_host;
        proxy_set_header      X-Forwarded-Port   $upstream_x_forwarded_port;
        proxy_set_header      X-Forwarded-Path   $upstream_x_forwarded_path;
        proxy_set_header      X-Forwarded-Prefix $upstream_x_forwarded_prefix;
        proxy_set_header      X-Real-IP          $remote_addr;
> if enabled_headers_upstream["X-Kong-Request-Id"] then
        proxy_set_header      X-Kong-Request-Id  $kong_request_id;
> end
        proxy_pass_header     Server;
        proxy_pass_header     Date;
        proxy_ssl_name        $upstream_host;
        proxy_ssl_server_name on;
> if client_ssl then
        proxy_ssl_certificate ${{CLIENT_SSL_CERT}};
        proxy_ssl_certificate_key ${{CLIENT_SSL_CERT_KEY}};
> end
        proxy_pass            $upstream_scheme://kong_upstream$upstream_uri;
    }

    location @unbuffered {
        internal;
        default_type         '';
        set $kong_proxy_mode 'unbuffered';

        proxy_http_version      1.1;
        proxy_buffering         off;
        proxy_request_buffering off;

        proxy_set_header      TE                 $upstream_te;
        proxy_set_header      Host               $upstream_host;
        proxy_set_header      Upgrade            $upstream_upgrade;
        proxy_set_header      Connection         $upstream_connection;
        proxy_set_header      X-Forwarded-For    $upstream_x_forwarded_for;
        proxy_set_header      X-Forwarded-Proto  $upstream_x_forwarded_proto;
        proxy_set_header      X-Forwarded-Host   $upstream_x_forwarded_host;
        proxy_set_header      X-Forwarded-Port   $upstream_x_forwarded_port;
        proxy_set_header      X-Forwarded-Path   $upstream_x_forwarded_path;
        proxy_set_header      X-Forwarded-Prefix $upstream_x_forwarded_prefix;
        proxy_set_header      X-Real-IP          $remote_addr;
> if enabled_headers_upstream["X-Kong-Request-Id"] then
        proxy_set_header      X-Kong-Request-Id  $kong_request_id;
> end
        proxy_pass_header     Server;
        proxy_pass_header     Date;
        proxy_ssl_name        $upstream_host;
        proxy_ssl_server_name on;
> if client_ssl then
        proxy_ssl_certificate ${{CLIENT_SSL_CERT}};
        proxy_ssl_certificate_key ${{CLIENT_SSL_CERT_KEY}};
> end
        proxy_pass            $upstream_scheme://kong_upstream$upstream_uri;
    }

    location @unbuffered_request {
        internal;
        default_type         '';
        set $kong_proxy_mode 'unbuffered';

        proxy_http_version      1.1;
        proxy_buffering          on;
        proxy_request_buffering off;

        proxy_set_header      TE                 $upstream_te;
        proxy_set_header      Host               $upstream_host;
        proxy_set_header      Upgrade            $upstream_upgrade;
        proxy_set_header      Connection         $upstream_connection;
        proxy_set_header      X-Forwarded-For    $upstream_x_forwarded_for;
        proxy_set_header      X-Forwarded-Proto  $upstream_x_forwarded_proto;
        proxy_set_header      X-Forwarded-Host   $upstream_x_forwarded_host;
        proxy_set_header      X-Forwarded-Port   $upstream_x_forwarded_port;
        proxy_set_header      X-Forwarded-Path   $upstream_x_forwarded_path;
        proxy_set_header      X-Forwarded-Prefix $upstream_x_forwarded_prefix;
        proxy_set_header      X-Real-IP          $remote_addr;
> if enabled_headers_upstream["X-Kong-Request-Id"] then
        proxy_set_header      X-Kong-Request-Id  $kong_request_id;
> end
        proxy_pass_header     Server;
        proxy_pass_header     Date;
        proxy_ssl_name        $upstream_host;
        proxy_ssl_server_name on;
> if client_ssl then
        proxy_ssl_certificate ${{CLIENT_SSL_CERT}};
        proxy_ssl_certificate_key ${{CLIENT_SSL_CERT_KEY}};
> end
        proxy_pass            $upstream_scheme://kong_upstream$upstream_uri;
    }

    location @unbuffered_response {
        internal;
        default_type         '';
        set $kong_proxy_mode 'unbuffered';

        proxy_http_version      1.1;
        proxy_buffering         off;
        proxy_request_buffering  on;

        proxy_set_header      TE                 $upstream_te;
        proxy_set_header      Host               $upstream_host;
        proxy_set_header      Upgrade            $upstream_upgrade;
        proxy_set_header      Connection         $upstream_connection;
        proxy_set_header      X-Forwarded-For    $upstream_x_forwarded_for;
        proxy_set_header      X-Forwarded-Proto  $upstream_x_forwarded_proto;
        proxy_set_header      X-Forwarded-Host   $upstream_x_forwarded_host;
        proxy_set_header      X-Forwarded-Port   $upstream_x_forwarded_port;
        proxy_set_header      X-Forwarded-Path   $upstream_x_forwarded_path;
        proxy_set_header      X-Forwarded-Prefix $upstream_x_forwarded_prefix;
        proxy_set_header      X-Real-IP          $remote_addr;
> if enabled_headers_upstream["X-Kong-Request-Id"] then
        proxy_set_header      X-Kong-Request-Id  $kong_request_id;
> end
        proxy_pass_header     Server;
        proxy_pass_header     Date;
        proxy_ssl_name        $upstream_host;
        proxy_ssl_server_name on;
> if client_ssl then
        proxy_ssl_certificate ${{CLIENT_SSL_CERT}};
        proxy_ssl_certificate_key ${{CLIENT_SSL_CERT_KEY}};
> end
        proxy_pass            $upstream_scheme://kong_upstream$upstream_uri;
    }

    location @grpc {
        internal;
        default_type         '';
        set $kong_proxy_mode 'grpc';

        grpc_set_header      TE                 $upstream_te;
        grpc_set_header      X-Forwarded-For    $upstream_x_forwarded_for;
        grpc_set_header      X-Forwarded-Proto  $upstream_x_forwarded_proto;
        grpc_set_header      X-Forwarded-Host   $upstream_x_forwarded_host;
        grpc_set_header      X-Forwarded-Port   $upstream_x_forwarded_port;
        grpc_set_header      X-Forwarded-Path   $upstream_x_forwarded_path;
        grpc_set_header      X-Forwarded-Prefix $upstream_x_forwarded_prefix;
        grpc_set_header      X-Real-IP          $remote_addr;
> if enabled_headers_upstream["X-Kong-Request-Id"] then
        grpc_set_header      X-Kong-Request-Id  $kong_request_id;
> end
        grpc_pass_header     Server;
        grpc_pass_header     Date;
        grpc_ssl_name        $upstream_host;
        grpc_ssl_server_name on;
> if client_ssl then
        grpc_ssl_certificate ${{CLIENT_SSL_CERT}};
        grpc_ssl_certificate_key ${{CLIENT_SSL_CERT_KEY}};
> end
        grpc_pass            $upstream_scheme://kong_upstream;
    }

    location = /kong_buffered_http {
        internal;
        default_type         '';
        set $kong_proxy_mode 'http';

        rewrite_by_lua_block       {
          -- ngx.localtion.capture will create a new nginx request,
          -- so the upstream ssl-related info attached to the `r` gets lost.
          -- we need to re-set them here to the new nginx request.
          local ctx = ngx.ctx
          local upstream_ssl = require("kong.runloop.upstream_ssl")

          upstream_ssl.set_service_ssl(ctx)
          upstream_ssl.fallback_upstream_client_cert(ctx)
        }
        access_by_lua_block        {;}
        header_filter_by_lua_block {;}
        body_filter_by_lua_block   {;}
        log_by_lua_block           {;}

        proxy_http_version 1.1;
        proxy_set_header      TE                 $upstream_te;
        proxy_set_header      Host               $upstream_host;
        proxy_set_header      Upgrade            $upstream_upgrade;
        proxy_set_header      Connection         $upstream_connection;
        proxy_set_header      X-Forwarded-For    $upstream_x_forwarded_for;
        proxy_set_header      X-Forwarded-Proto  $upstream_x_forwarded_proto;
        proxy_set_header      X-Forwarded-Host   $upstream_x_forwarded_host;
        proxy_set_header      X-Forwarded-Port   $upstream_x_forwarded_port;
        proxy_set_header      X-Forwarded-Path   $upstream_x_forwarded_path;
        proxy_set_header      X-Forwarded-Prefix $upstream_x_forwarded_prefix;
        proxy_set_header      X-Real-IP          $remote_addr;
> if enabled_headers_upstream["X-Kong-Request-Id"] then
        proxy_set_header      X-Kong-Request-Id  $kong_request_id;
> end
        proxy_pass_header     Server;
        proxy_pass_header     Date;
        proxy_ssl_name        $upstream_host;
        proxy_ssl_server_name on;
> if client_ssl then
        proxy_ssl_certificate ${{CLIENT_SSL_CERT}};
        proxy_ssl_certificate_key ${{CLIENT_SSL_CERT_KEY}};
> end
        proxy_pass            $upstream_scheme://kong_upstream$upstream_uri;
    }

    location = /kong_error_handler {
        internal;
        default_type                 '';

        uninitialized_variable_warn  off;

        rewrite_by_lua_block {;}
        access_by_lua_block  {;}

        content_by_lua_block {
            Kong.handle_error()
        }
    }
}

server {
    server_name kong_mtls;
    listen 0.0.0.0:9443 ssl deferred reuseport backlog=16384;
    http2 on;

    modsecurity ${{WAF}};
    modsecurity_rules_file /usr/local/modsec_includes.conf;

    #WAF_DEBUG_LEVEL level 0 = off 9 = on
    modsecurity_rules '
      SecRuleEngine ${{WAF_MODE}}
      SecRequestBodyLimit ${{WAF_REQUEST_FILE_SIZE_LIMIT}}
      SecRequestBodyNoFilesLimit ${{WAF_REQUEST_NO_FILE_SIZE_LIMIT}}
      SecPcreMatchLimit ${{WAF_PCRE_MATCH_LIMIT}}
      SecPcreMatchLimitRecursion ${{WAF_PCRE_MATCH_LIMIT_RECURSION}}
      SecDebugLogLevel ${{WAF_DEBUG_LEVEL}}
      SecAuditEngine ${{WAF_AUDIT}}
      SecAction "id:900000,phase:1,nolog,pass,t:none,setvar:tx.paranoia_level=${{WAF_PARANOIA_LEVEL}}"
    ';


    # Mutual TLS logic, check if server port is 9443
    ssl_verify_client on;
    ssl_client_certificate /usr/local/kong/stargate-mutual-trust.ca;
    ssl_crl /usr/local/kong/stargate-mutual-trust.crl.pem;
    ssl_verify_depth 3;

    error_page 400 404 405 408 411 412 413 414 417 /kong_error_handler;
    error_page 494 =494                            /kong_error_handler;
    error_page 500 502 503 504                     /kong_error_handler;

    # Append the kong request id to the error log
    # https://github.com/Kong/lua-kong-nginx-module#lua_kong_error_log_request_id
    lua_kong_error_log_request_id $kong_request_id;

> if proxy_access_log_enabled then
>   if custom_proxy_access_log then
    access_log ${{PROXY_ACCESS_LOG}};
>   else
    access_log ${{PROXY_ACCESS_LOG}} kong_log_format;
>   end
> else
    access_log off;
> end

    error_log  ${{PROXY_ERROR_LOG}} ${{LOG_LEVEL}};

    client_body_buffer_size ${{CLIENT_BODY_BUFFER_SIZE}};
    client_header_buffer_size 8k;
    large_client_header_buffers 2 20k;

> if proxy_ssl_enabled then
    # Hardcode the certificate for MTLS we want Stargate to present to clients
    ssl_certificate /usr/local/kong/ssl/kongmtlscert.crt;
    ssl_certificate_key /usr/local/kong/ssl/kongmtlsprivatekey.key;
    
    ssl_session_cache   shared:SSL:10m;
    ssl_certificate_by_lua_block {
        Kong.ssl_certificate()
    }
> end

  # injected nginx_proxy_* directives
> for _, el in ipairs(nginx_proxy_directives) do
  $(el.name) $(el.value);
> end
> for i = 1, #trusted_ips do
  set_real_ip_from  $(trusted_ips[i]);
> end

  rewrite_by_lua_block {
      Kong.rewrite()
  }

  access_by_lua_block {
      Kong.access()
  }

  header_filter_by_lua_block {
      Kong.header_filter()
      ngx.header["Server"] = nil
      ngx.header["Via"] = nil
  }

  body_filter_by_lua_block {
      Kong.body_filter()
  }

  log_by_lua_block {
      Kong.log()
  }

     location / {
        default_type                     '';

        set $ctx_ref                     '';
        set $upstream_te                 '';
        set $upstream_host               '';
        set $upstream_upgrade            '';
        set $upstream_connection         '';
        set $upstream_scheme             '';
        set $upstream_uri                '';
        set $upstream_x_forwarded_for    '';
        set $upstream_x_forwarded_proto  '';
        set $upstream_x_forwarded_host   '';
        set $upstream_x_forwarded_port   '';
        set $upstream_x_forwarded_path   '';
        set $upstream_x_forwarded_prefix '';
        set $kong_proxy_mode             'http';

        proxy_http_version      1.1;
        proxy_buffering          on;
        proxy_request_buffering  on;

        # injected nginx_location_* directives
> for _, el in ipairs(nginx_location_directives) do
        $(el.name) $(el.value);
> end

        proxy_set_header      TE                 $upstream_te;
        proxy_set_header      Host               $upstream_host;
        proxy_set_header      Upgrade            $upstream_upgrade;
        proxy_set_header      Connection         $upstream_connection;
        proxy_set_header      X-Forwarded-For    $upstream_x_forwarded_for;
        proxy_set_header      X-Forwarded-Proto  $upstream_x_forwarded_proto;
        proxy_set_header      X-Forwarded-Host   $upstream_x_forwarded_host;
        proxy_set_header      X-Forwarded-Port   $upstream_x_forwarded_port;
        proxy_set_header      X-Forwarded-Path   $upstream_x_forwarded_path;
        proxy_set_header      X-Forwarded-Prefix $upstream_x_forwarded_prefix;
        proxy_set_header      X-Real-IP          $remote_addr;
> if enabled_headers_upstream["X-Kong-Request-Id"] then
        proxy_set_header      X-Kong-Request-Id  $kong_request_id;
> end
        proxy_pass_header     Server;
        proxy_pass_header     Date;
        proxy_ssl_name        $upstream_host;
        proxy_ssl_server_name on;
> if client_ssl then
        proxy_ssl_certificate ${{CLIENT_SSL_CERT}};
        proxy_ssl_certificate_key ${{CLIENT_SSL_CERT_KEY}};
> end
        proxy_pass            $upstream_scheme://kong_upstream$upstream_uri;
    }

    location @unbuffered {
        internal;
        default_type         '';
        set $kong_proxy_mode 'unbuffered';

        proxy_http_version      1.1;
        proxy_buffering         off;
        proxy_request_buffering off;

        proxy_set_header      TE                 $upstream_te;
        proxy_set_header      Host               $upstream_host;
        proxy_set_header      Upgrade            $upstream_upgrade;
        proxy_set_header      Connection         $upstream_connection;
        proxy_set_header      X-Forwarded-For    $upstream_x_forwarded_for;
        proxy_set_header      X-Forwarded-Proto  $upstream_x_forwarded_proto;
        proxy_set_header      X-Forwarded-Host   $upstream_x_forwarded_host;
        proxy_set_header      X-Forwarded-Port   $upstream_x_forwarded_port;
        proxy_set_header      X-Forwarded-Path   $upstream_x_forwarded_path;
        proxy_set_header      X-Forwarded-Prefix $upstream_x_forwarded_prefix;
        proxy_set_header      X-Real-IP          $remote_addr;
> if enabled_headers_upstream["X-Kong-Request-Id"] then
        proxy_set_header      X-Kong-Request-Id  $kong_request_id;
> end
        proxy_pass_header     Server;
        proxy_pass_header     Date;
        proxy_ssl_name        $upstream_host;
        proxy_ssl_server_name on;
> if client_ssl then
        proxy_ssl_certificate ${{CLIENT_SSL_CERT}};
        proxy_ssl_certificate_key ${{CLIENT_SSL_CERT_KEY}};
> end
        proxy_pass            $upstream_scheme://kong_upstream$upstream_uri;
    }

    location @unbuffered_request {
        internal;
        default_type         '';
        set $kong_proxy_mode 'unbuffered';

        proxy_http_version      1.1;
        proxy_buffering          on;
        proxy_request_buffering off;

        proxy_set_header      TE                 $upstream_te;
        proxy_set_header      Host               $upstream_host;
        proxy_set_header      Upgrade            $upstream_upgrade;
        proxy_set_header      Connection         $upstream_connection;
        proxy_set_header      X-Forwarded-For    $upstream_x_forwarded_for;
        proxy_set_header      X-Forwarded-Proto  $upstream_x_forwarded_proto;
        proxy_set_header      X-Forwarded-Host   $upstream_x_forwarded_host;
        proxy_set_header      X-Forwarded-Port   $upstream_x_forwarded_port;
        proxy_set_header      X-Forwarded-Path   $upstream_x_forwarded_path;
        proxy_set_header      X-Forwarded-Prefix $upstream_x_forwarded_prefix;
        proxy_set_header      X-Real-IP          $remote_addr;
> if enabled_headers_upstream["X-Kong-Request-Id"] then
        proxy_set_header      X-Kong-Request-Id  $kong_request_id;
> end
        proxy_pass_header     Server;
        proxy_pass_header     Date;
        proxy_ssl_name        $upstream_host;
        proxy_ssl_server_name on;
> if client_ssl then
        proxy_ssl_certificate ${{CLIENT_SSL_CERT}};
        proxy_ssl_certificate_key ${{CLIENT_SSL_CERT_KEY}};
> end
        proxy_pass            $upstream_scheme://kong_upstream$upstream_uri;
    }

    location @unbuffered_response {
        internal;
        default_type         '';
        set $kong_proxy_mode 'unbuffered';

        proxy_http_version      1.1;
        proxy_buffering         off;
        proxy_request_buffering  on;

        proxy_set_header      TE                 $upstream_te;
        proxy_set_header      Host               $upstream_host;
        proxy_set_header      Upgrade            $upstream_upgrade;
        proxy_set_header      Connection         $upstream_connection;
        proxy_set_header      X-Forwarded-For    $upstream_x_forwarded_for;
        proxy_set_header      X-Forwarded-Proto  $upstream_x_forwarded_proto;
        proxy_set_header      X-Forwarded-Host   $upstream_x_forwarded_host;
        proxy_set_header      X-Forwarded-Port   $upstream_x_forwarded_port;
        proxy_set_header      X-Forwarded-Path   $upstream_x_forwarded_path;
        proxy_set_header      X-Forwarded-Prefix $upstream_x_forwarded_prefix;
        proxy_set_header      X-Real-IP          $remote_addr;
> if enabled_headers_upstream["X-Kong-Request-Id"] then
        proxy_set_header      X-Kong-Request-Id  $kong_request_id;
> end
        proxy_pass_header     Server;
        proxy_pass_header     Date;
        proxy_ssl_name        $upstream_host;
        proxy_ssl_server_name on;
> if client_ssl then
        proxy_ssl_certificate ${{CLIENT_SSL_CERT}};
        proxy_ssl_certificate_key ${{CLIENT_SSL_CERT_KEY}};
> end
        proxy_pass            $upstream_scheme://kong_upstream$upstream_uri;
    }

    location @grpc {
        internal;
        default_type         '';
        set $kong_proxy_mode 'grpc';

        grpc_set_header      TE                 $upstream_te;
        grpc_set_header      X-Forwarded-For    $upstream_x_forwarded_for;
        grpc_set_header      X-Forwarded-Proto  $upstream_x_forwarded_proto;
        grpc_set_header      X-Forwarded-Host   $upstream_x_forwarded_host;
        grpc_set_header      X-Forwarded-Port   $upstream_x_forwarded_port;
        grpc_set_header      X-Forwarded-Path   $upstream_x_forwarded_path;
        grpc_set_header      X-Forwarded-Prefix $upstream_x_forwarded_prefix;
        grpc_set_header      X-Real-IP          $remote_addr;
> if enabled_headers_upstream["X-Kong-Request-Id"] then
        grpc_set_header      X-Kong-Request-Id  $kong_request_id;
> end
        grpc_pass_header     Server;
        grpc_pass_header     Date;
        grpc_ssl_name        $upstream_host;
        grpc_ssl_server_name on;
> if client_ssl then
        grpc_ssl_certificate ${{CLIENT_SSL_CERT}};
        grpc_ssl_certificate_key ${{CLIENT_SSL_CERT_KEY}};
> end
        grpc_pass            $upstream_scheme://kong_upstream;
    }

    location = /kong_buffered_http {
        internal;
        default_type         '';
        set $kong_proxy_mode 'http';

        rewrite_by_lua_block       {
          -- ngx.localtion.capture will create a new nginx request,
          -- so the upstream ssl-related info attached to the `r` gets lost.
          -- we need to re-set them here to the new nginx request.
          local ctx = ngx.ctx
          local upstream_ssl = require("kong.runloop.upstream_ssl")

          upstream_ssl.set_service_ssl(ctx)
          upstream_ssl.fallback_upstream_client_cert(ctx)
        }
        access_by_lua_block        {;}
        header_filter_by_lua_block {;}
        body_filter_by_lua_block   {;}
        log_by_lua_block           {;}

        proxy_http_version 1.1;
        proxy_set_header      TE                 $upstream_te;
        proxy_set_header      Host               $upstream_host;
        proxy_set_header      Upgrade            $upstream_upgrade;
        proxy_set_header      Connection         $upstream_connection;
        proxy_set_header      X-Forwarded-For    $upstream_x_forwarded_for;
        proxy_set_header      X-Forwarded-Proto  $upstream_x_forwarded_proto;
        proxy_set_header      X-Forwarded-Host   $upstream_x_forwarded_host;
        proxy_set_header      X-Forwarded-Port   $upstream_x_forwarded_port;
        proxy_set_header      X-Forwarded-Path   $upstream_x_forwarded_path;
        proxy_set_header      X-Forwarded-Prefix $upstream_x_forwarded_prefix;
        proxy_set_header      X-Real-IP          $remote_addr;
> if enabled_headers_upstream["X-Kong-Request-Id"] then
        proxy_set_header      X-Kong-Request-Id  $kong_request_id;
> end
        proxy_pass_header     Server;
        proxy_pass_header     Date;
        proxy_ssl_name        $upstream_host;
        proxy_ssl_server_name on;
> if client_ssl then
        proxy_ssl_certificate ${{CLIENT_SSL_CERT}};
        proxy_ssl_certificate_key ${{CLIENT_SSL_CERT_KEY}};
> end
        proxy_pass            $upstream_scheme://kong_upstream$upstream_uri;
    }

    location = /kong_error_handler {
        internal;
        default_type                 '';

        uninitialized_variable_warn  off;

        rewrite_by_lua_block {;}
        access_by_lua_block  {;}

        content_by_lua_block {
            Kong.handle_error()
        }
    }  

}
> end -- (role == "traditional" or role == "data_plane") and #proxy_listeners > 0
> if (role == "control_plane" or role == "traditional") and #admin_listeners > 0 then
server {
    server_name kong_admin;
> for _, entry in ipairs(admin_listeners) do
    listen $(entry.listener);
> end

> for _, entry in ipairs(admin_listeners) do
> if entry.http2 then
    http2 on;
> break
> end
> end

    access_log ${{ADMIN_ACCESS_LOG}};
    error_log  ${{ADMIN_ERROR_LOG}} ${{LOG_LEVEL}};

> if admin_ssl_enabled then
> for i = 1, #admin_ssl_cert do
    ssl_certificate     $(admin_ssl_cert[i]);
    ssl_certificate_key $(admin_ssl_cert_key[i]);
> end
    ssl_session_cache   shared:AdminSSL:10m;
> end
    # injected nginx_admin_* directives
> for _, el in ipairs(nginx_admin_directives) do
    $(el.name) $(el.value);
> end
    location / {
        default_type application/json;
        content_by_lua_block {
            Kong.admin_content()
        }
        header_filter_by_lua_block {
            Kong.admin_header_filter()
        }
      }

      location /robots.txt {
          return 200 'User-agent: *\nDisallow: /';
      }
 }
> end -- (role == "control_plane" or role == "traditional") and #admin_listeners > 0

server {
    charset UTF-8;
    server_name kong_worker_events;
    listen unix:${{PREFIX}}/worker_events.sock;
    access_log off;
    location / {
        content_by_lua_block {
          require("resty.events.compat").run()
        }
    }
}

}

Anything else?

No response

[chronolaw]

Thanks for your report, we also already noticed it and are investigating.

[oowl]

We can easily reproduce it by common case

1. Start Kong

2. Send HTTP traffic to the HTTPS port

╰─$ curl 127.0.0.1:8443                                                                       
<html>
<head><title>400 The plain HTTP request was sent to HTTPS port</title></head>
<body>
<center><h1>400 Bad Request</h1></center>
<center>The plain HTTP request was sent to HTTPS port</center>
</body>
</html>

3. Check the error log

2024/06/13 14:38:43 [warn] 1915011#0: *10309 using uninitialized "kong_proxy_mode" variable while logging request, client: 127.0.0.1, server: kong, request: "GET / HTTP/1.1", host: "127.0.0.1:8443"
2024/06/13 14:38:43 [warn] 1915011#0: *10309 [lua] reports.lua:106: log(): [reports] could not determine log suffix (scheme=http, proxy_mode=) while logging request, client: 127.0.0.1, server: kong, request: "GET / HTTP/1.1", host: "127.0.0.1:8443"

HTTP request was sent to the HTTPS port, and 400 was triggered in the TLS handshake process, it does not initialize any nginx variable, and we can not get the kong_proxy_mode variable. So this case did not affect any production correctly traffic, just some abnormal traffic.

[jeremyjpj0916]

@oowl I think my case is similar to the http call to an https endpoint but mine was essentially a loadbalancer calling its health check endpoint to a port expecting client mtls that could not serve a client certificate so nginx rejects the call early for no client cert passed. similar early nginx termination of the tx for not meeting tls needs similar to your http protocol mismatch.

< HTTP/2 400
< date: Thu, 13 Jun 2024 15:30:56 GMT
< content-type: text/html; charset=UTF-8
< content-length: 202
< x-response-latency: 0
<
<html>
<head><title>400 No required SSL certificate was sent</title></head>
<body>
<center><h1>400 Bad Request</h1></center>
<center>No required SSL certificate was sent</center>
</body>
</html>

Will this be backported to 3.7.0 or end up in a 3.7.1? For now I will drop in some patch files with your suggested fixes and try it out. In looking at the fix I notice you opted to just move the uninitialized_variable_warn off; up to the main block so all server blocks can get that benefit. I guess the only concern with that approach may be what if there were totally valid situations where a problematic uninitialized variable was occurring in Kong/Nginx and now that setting will make it so folks don't realize it vs in this situation where its more of a false positive because the tx .

@chronolaw I also saw a different error too w respect to my original post, the

2024-06-12T20:34:00.799776653-05:00 2024/06/13 01:34:00 [notice] 133442#0: *169848 [kong] globalpatches.lua:147 [kong-kafka-log] request headers truncated while logging request, client: xxx.xxx.x.xxx, server: kong_mtls, request: "GET /F5/status HTTP/1.1", host: "gateway-dev-dc.company.com"

It likely may be related similarly due to short circuited txs though but it prints w the globalpatches lua file line.

[jeremyjpj0916]

So @chronolaw @oowl I dropped in the nginx template change to move the no warning on the uninit vars + patched the reports.lua file and that did fix one of the log issues I saw.

Still getting this log though on both my server blocks:

2024-06-13T12:50:49.035418672-05:00 2024/06/13 17:50:49 [notice] 50#0: *2958 [kong] globalpatches.lua:147 [kong-kafka-log] request headers truncated while logging request, client: xxx.xxx.x.xxx, server: kong, request: "GET /F5/status HTTP/1.1", host: "gateway-dev-dc.company.com", request_id: "d3ecff4fcd1cdf42a7f7aa2fd2b39847"
2024-06-13T12:50:49.041943127-05:00 2024/06/13 17:50:49 [notice] 48#0: *2956 [kong] globalpatches.lua:147 [kong-kafka-log] request headers truncated while logging request, client: xxx.xxx.x.xxx, server: kong_mtls, request: "GET /F5/status HTTP/1.1", host: "gateway-dev-dc.company.com"

Studying this code here from global patches:

      local DEFAULT_MAX_REQ_HEADERS = 100
      local DEFAULT_MAX_RESP_HEADERS = 100
      local DEFAULT_MAX_URI_ARGS = 100
      local DEFAULT_MAX_POST_ARGS = 100
      local DEFAULT_MAX_DECODE_ARGS = 100

      local MAX_REQ_HEADERS
      local MAX_RESP_HEADERS
      local MAX_URI_ARGS
      local MAX_POST_ARGS
      local MAX_DECODE_ARGS

      -- REQUEST HEADERS [
      local function get_req_headers_real(max_req_headers, ...)
        local request_headers, err = get_req_headers(max_req_headers or MAX_REQ_HEADERS or DEFAULT_MAX_REQ_HEADERS, ...)
        if err == "truncated" then
          kong.log.notice("request headers truncated")
        end
        return request_headers, err
      end

      _G.ngx.req.get_headers = function(max_req_headers, ...)
        if not get_request() then
          error("no request found")
        end
        MAX_REQ_HEADERS = kong and kong.configuration and kong.configuration.lua_max_req_headers or DEFAULT_MAX_REQ_HEADERS
        _G.ngx.req.get_headers = get_req_headers_real
        return get_req_headers_real(max_req_headers or MAX_REQ_HEADERS, ...)
      end
      -- ]

Seems basically Kong OOTB now limits req/resp headers to 100 elements each? Thats about on par with most load balancer defaults too from what I have seen from a safety standpoint. BUT the kicker here is I am fairly confident that there were less than 100 request headers to that ping endpoint healthcheck call.... so something about transactions cut short by nginx causing this behavior too in logging plugins? Does this global patches just execute with every plugin? Its odd to me that the http-log plugin isn't printing this also on those txs only my kong-kafka-log plugin.

https://github.com/Optum/kong-kafka-log

Another one of those behaviors I haven't observed on 2.8.x

[jeremyjpj0916]

More proof of it, even curling our health check endpoint on it that has the request termination plugin on it on a custom path from the initial route path defined adding /test showed the behavior on a dummy OOTB curl call:

Am starting to think its any route that has the request termination enabled on it. Testing to confirm that behavior further rn. Adding req termination to another unique route proxy on Kong.

I run all logging plugins globally, the request termination plugin to the healthcheck is local to the route and has this config:

{
  "config": {
    "echo": false,
    "status_code": 200,
    "message": "Success",
    "body": null,
    "content_type": null,
    "trigger": null
  },
  "protocols": [
    "grpc",
    "grpcs",
    "http",
    "https"
  ],
  "service": null,
  "id": "b0df0260-d82d-4d17-bd85-59f73b50e7a7",
  "enabled": true,
  "created_at": 1713993860,
  "instance_name": null,
  "consumer": null,
  "route": {
    "id": "12b9f530-b292-49d1-8651-ccb7f304c85d"
  },
  "updated_at": 1717537316,
  "name": "request-termination",
  "tags": null
}

[jeremyjpj0916]

Darn nope, tried a new route defined without the request termination plugin and it still threw that log, so that plugin has nothing to do with it:

2024-06-13T20:04:19.524000997-05:00 2024/06/14 01:04:19 [notice] 107745#0: *113552 [kong] globalpatches.lua:147 [kong-kafka-log] request headers truncated while logging request, client: 10.xx.xxx.xx, server: kong, request: "GET /F5/status/no-termination HTTP/1.1"

Gonna just disable the kong-kafka-log plugin all together and see if that stops the global patches behavior when it runs too.

Edit - yep with that plugin disabled when I hit the /F5/status proxy healthcheck I don't see the global patches header truncate logging issue. Maybe I can patch global patches lua to give me a print statement of how many headers it thinks it sees and re-enable the kong-kafka-log plugin?

[oowl]

Will this be backported to 3.7.0 or end up in a 3.7.1?

In the current fix, I think we do not backport to the old version.

I guess the only concern with that approach may be what if there were totally valid situations where a problematic uninitialized variable was occurring in Kong/Nginx and now that setting will make it so folks don't realize it vs in this situation where its more of a false positive because the tx .

Yeah, it will let us not realize this error, but from my perspective, it's not a problem in Kong, even if we know this error log, we still do not see what we can do.

[jeremyjpj0916]

@chronolaw @oowl Would you like a separate git issue for the other log issue I mentioned seeing with Kong interacting badly in the core code with one of my OSS plugins when its enabled? I finally added some debug statements to the global patches lua file and confirmed there is some weird behavior up in the 3.7.0 kong verse here hah:

Code change to help debug was this:

      -- REQUEST HEADERS [
      local function get_req_headers_real(max_req_headers, ...)
        local request_headers, err = get_req_headers(max_req_headers or MAX_REQ_HEADERS or DEFAULT_MAX_REQ_HEADERS, ...)
        if err == "truncated" then

          -- How many headers did this request actually have?!?!?!
          local req_header_count = 0
          for _ in pairs(get_req_headers(0)) do req_header_count = req_header_count + 1 end

          kong.log.notice("Total count of request headers per nginx: " .. tostring(req_header_count))
          kong.log.notice("Size of max_req_headers: " .. tostring(max_req_headers))
          kong.log.notice("Size of MAX_REQ_HEADERS: " .. tostring(MAX_REQ_HEADERS))
          kong.log.notice("Size of DEFAULT_MAX_REQ_HEADERS: " .. tostring(DEFAULT_MAX_REQ_HEADERS))
          kong.log.notice("request headers truncated")
        end
        return request_headers, err
      end

Output of the above to help debug was this:

2024-06-18T03:22:44.560652686-05:00 2024/06/18 08:22:44 [notice] 48#0: *3181 [kong] globalpatches.lua:152 [kong-kafka-log] Total count of request headers per nginx: 4 while logging request, client: xxx.xxx.96.250, server: kong, request: "GET /F5/status HTTP/1.1", host: "my-gateway.company.com", request_id: "45b78b56afac4336d75f0d66a5374654"

2024-06-18T03:22:44.560681918-05:00 2024/06/18 08:22:44 [notice] 48#0: *3181 [kong] globalpatches.lua:153 [kong-kafka-log] Size of max_req_headers: 1 while logging request, client: xxx.xxx.96.250, server: kong, request: "GET /F5/status HTTP/1.1", host: "my-gateway.company.com", request_id: "45b78b56afac4336d75f0d66a5374654"

2024-06-18T03:22:44.560685734-05:00 2024/06/18 08:22:44 [notice] 48#0: *3181 [kong] globalpatches.lua:154 [kong-kafka-log] Size of MAX_REQ_HEADERS: 100 while logging request, client: xxx.xxx.96.250, server: kong, request: "GET /F5/status HTTP/1.1", host: "my-gateway.company.com", request_id: "45b78b56afac4336d75f0d66a5374654"

2024-06-18T03:22:44.560688618-05:00 2024/06/18 08:22:44 [notice] 48#0: *3181 [kong] globalpatches.lua:155 [kong-kafka-log] Size of DEFAULT_MAX_REQ_HEADERS: 100 while logging request, client: xxx.xxx.96.250, server: kong, request: "GET /F5/status HTTP/1.1", host: "my-gateway.company.com", request_id: "45b78b56afac4336d75f0d66a5374654"

2024-06-18T03:22:44.560698082-05:00 2024/06/18 08:22:44 [notice] 48#0: *3181 [kong] globalpatches.lua:156 [kong-kafka-log] request headers truncated while logging request, client: xxx.xxx.96.250, server: kong, request: "GET /F5/status HTTP/1.1", host: "my-gateway.company.com", request_id: "45b78b56afac4336d75f0d66a5374654"

So I think the real issue is why the heck was max_req_headers set to 1 during the context of this transaction? Only allowed 1 header element by Kong lol? All the other variables were at 100 which is reasonable but the value of 1 makes no sense in this situation. Why are there so many OR statements in there all setting the size vs 1 simple variable value that could also maybe be configured/overriden as an environment variable for max header count # ? I am not setting anything in my env variables around anything like that either. Seems way over complicated in that code block.

Edit - Ohhhh is it because of this? https://github.com/Optum/kong-kafka-log/blob/master/src/basic.lua#L146 ???? This logic used to work fine using ngx.req.get_headers(1)["optum-cid-ext"] before on 2.8.x ... Does the global patches now override that default nginx header grabbing behavior to cause that issue? Did Kong ever note this in its change log somewhere? I think thats the issue that Kong now overrides that ngx method globally which changed the methods behavior :/ ...

Edit Edit - Per docs it seems like to grab 1 header no arg is even needed inside at all now, maybe it even changed at openresty layer I guess because I don't want that to log "truncating headers" every time. I can update plugin:

Mystery solved.

[jeremyjpj0916]

^ will say I don't agree w notice log for the truncate headers kong does w global patches there either when I just wanna grab a singular header value for optimization. but I removed the (1) and that made the log go away even though I suppose the query is more intensive after doing so.