missing request headers in acces..log when 499

[doc temp]

Hello, 

We have the following openresty config

openresty: openresty/1.19.3.1

OS: Red Hat Enterprise Linux release 8.5 (Ootpa).

Whenever we hit 499, the request payload and request headers are not logged. is this the default behavior ? or am i missing something. 

[Jiahao Wang]

The request payload and request headers are logged even when a 499 response is encountered.

Can you provide the log format and the related logs?

And it would be great if you could provide a minimal use case.

[doc temp]

Here is 

1. logformat. 

log_format main escape=none '$remote_addr - $remote_user
[$time_local]
"$request" '
'$status
$body_bytes_sent
"$http_referer" '
"$http_user_agent"
"$http_x_forwarded_for"
req_body="$request_body"
elapsedTime="$request_time"
resp_body="$resp_body"
req_header="$req_header"
resp_header="$resp_header" '
'uct="$upstream_connect_time"
uht="$upstream_header_time"
urt ="$upstream_response_time "
uri="$uri "
uadd="$upstream_addr"
cr="$connection_requests" ';

2.Sample logs: 

Right now I cannot share the sample, as it has some sensitive information. 

3.Use-Case:

We are using access.log in our ELK stack for monitoring purposes. And when we encounter 499 [when the requestor times-out while nginx is still wiating for response from the upstream], we are not seeing this in our access.log and hence also not seen in our monitoring dashboards. 

[Junlong li]

Would you please provide a minimal nginx.conf and the test steps that can reproduce this issue?

[doc temp]

testSteps:

       1. have keepalive_timeout:   very big

       2. have location /something:  and try to induce a very large delay or sleep from target backend [upstream]

       3. trigger /something:  in very quick succession before the upstream even responds and close the session from the consuming application, thus causing a 499. 

 

here is the nginx.conf: [this is only a sample ]

http {
    include       mime.types;
    default_type  application/octet-stream;
   keepalive_timeout  180;

    log_format main escape=none '$remote_addr - $remote_user [$time_local] "$request" '
                          '$status $body_bytes_sent "$http_referer" '
                      '"$http_user_agent" "$http_x_forwarded_for" req_body="$request_body" elapsedTime="$request_time" resp_body="$resp_body" req_header="$req_header" resp_header="$resp_header" '
              'uct="$upstream_connect_time" uht="$upstream_header_time" urt ="$upstream_response_time " uri="$uri " uadd="$upstream_addr" cr="$connection_requests" ';

#----------------------------START of server -----------------------------------
    server {
        listen       <<portNumber>> ssl;
        server_name  <<serverName>>;
       

error_log <<location>> ;
access_log  <<location>>  


    # START ResponsePayload logging with LUA

      
            set $resp_body "";
            body_filter_by_lua_block{
                    local resp_body = string.sub(ngx.arg[1], 1, 10000)
                    ngx.ctx.buffered = (ngx.ctx.buffered or "") .. resp_body
                    if ngx.arg[2] then
                    ngx.var.resp_body = ngx.ctx.buffered
                    end}
                   
    # END ResponsePayload logging with LUA

    # START Header logging with LUA with Masking

        set $req_header "";
        set $resp_header "";
        header_filter_by_lua_block {
             local h = ngx.req.get_headers()
              for k1, v1 in pairs(h) do
                if k1:lower() == ("sensitive")  then
                v1="REDACTED"
                end
                if type(v1) =="table" then
                v1=table.concat(v1,";")
                end
                  ngx.var.req_header = ngx.var.req_header .. k1.."="..v1.." "
              end
              local rh = ngx.resp.get_headers()
              for k2, v2 in pairs(rh) do
                if type(v2) =="table" then
                v2= table.concat(v2,";")
                end
            ngx.var.resp_header = ngx.var.resp_header .. k2.."="..v2.." "
            end}
    # END Header logging with LUA with Masking


     location /something {
            root   /location/conf/html/;

            # try inducing a sleep in whatever way possible, so that the response take a longer time. 
            index  index.html index.htm;
           
        }

    location @handle_redirect {
        set $saved_redirect_location '$upstream_http_location';
        proxy_pass $saved_redirect_location;
        }


        # redirect server error pages to the static page /40x.html
        #
        error_page  404              /404.html;
        location = /40x.html {
            root   /location/nginx/html;
        }

        # redirect server error pages to the static page /50x.html
        #
        error_page   500 502 503 504  /50x.html;
        location = /50x.html {
            root   /location/nginx/html;
        }


}
#----------------------------END of server -----------------------------------  

   
}