Unable to log response body using NJS

[Asiya-Yunusa]

I am trying to get the response body logged in my NGINX plus Ingress Controller.

I am only able to get 2 new parameters populated "Requets Header and Response Header", I am not able to get the "Request Body and Response Body" logged.

This is my code below:
NGINX CONFIGMAP

apiVersion: v1
kind: ConfigMap
metadata:
  name: nginx-config-internal
  namespace: nginx-ingress-internal
data:
  log-format: |
    {
      "time": "$time_iso8601",
      "remote_addr": "$remote_addr",
      "request": "$request",
      "status": "$status",
      "request_body_file": "$request_body_file",
      "request_body": "$request_body",
      "request_headers": $request_headers_njs,
      "response_headers": $response_headers_njs,
      "response_body": "$response_body_njs",
    }
  ssl-session-cache: "True"
  ssl-session-cache-size: 10m
  ssl-session-timeout: 10m
  ssl-ciphers: HIGH:!aNULL:!MD5
  ssl-protocols: TLSv1.2 TLSv1.3
  main-snippets: |
    load_module /etc/nginx/modules/ngx_http_js_module.so;
  http-snippets: |
    js_import /etc/nginx/njs/logging.js;

    js_set $request_headers_njs logging.request_headers;
    js_set $response_headers_njs logging.response_headers;
    js_set $request_body_njs logging.request_body;
    js_set $response_body_njs logging.response_body;
    
    server {
            listen 80;
            access_log /dev/stdout;
            client_body_in_file_only clean;
            location / {
                js_body_filter logging.response_filter buffer_type=buffer;
                proxy_pass http://127.0.0.1:8080;
            }
    }

JAVASCRIPT FUNCTION

apiVersion: v1
kind: ConfigMap
metadata:
  name: nginx-njs-script
  namespace: nginx-ingress-internal
data:
  logging.js: |
    function request_headers(r) {
        return JSON.stringify(r.headersIn);
    }

    function response_headers(r) {
        return JSON.stringify(r.headersOut);
    }

    function request_body(r) {
        try {
            return JSON.stringify(require('fs').readFileSync(r.variables.request_body_file, 'utf8'));
        } catch(e) {
            return JSON.stringify("");  // In case reading the body fails
        }
    }



    
    var response_body_arr = [];
    function response_body(r) {
        return JSON.stringify(response_body_arr.join(''));
    }

    function response_filter(r, data, flags) {
        response_body_arr.push(data.toString());  // Capture the response body
        r.sendBuffer(data, flags);  // Send the response data to the client
    }

    export default { request_headers, response_headers, request_body, response_body, response_filter };

LOG RETURNED

{
    "time": "2024-11-27T16:19:39+00:00",
    "remote_addr": "***",
    "request": "GET / HTTP/1.1",
    "status": "404",
    "request_body_file": "-",
    "request_body": "-",
    "request_headers": {\x22Host\x22:\x22***x22
    },
    "response_headers": {\x22Content-Type\x22:\x22text/html\x22,\x22Content-Length\x22:\x22153\x22
    },
    "response_body": "\x22\x22",
}
{
    "time": "2024-11-27T16:19:47+00:00",
    "remote_addr": "***",
    "request": "GET / HTTP/1.1",
    "status": "404",
    "request_body_file": "-",
    "request_body": "-",
    "request_headers": {\x22Host\x22:\x22***x22
    },
    "response_headers": {\x22Content-Type\x22:\x22text/html\x22,\x22Content-Length\x22:\x22153\x22
    },
    "response_body": "\x22\x22",
}
{
    "time": "2024-11-27T16:19:48+00:00",
    "remote_addr": "***",
    "request": "GET / HTTP/1.1",
    "status": "404",
    "request_body_file": "-",
    "request_body": "-",
    "request_headers": {\x22Host\x22:\x22***x22
    },
    "response_headers": {\x22Content-Type\x22:\x22text/html\x22,\x22Content-Length\x22:\x22153\x22
    },
    "response_body": "\x22\x22",
}
I1127 16: 19: 50.934412       1 leaderelection.go: 258
] successfully acquired lease nginx-ingress-internal/nginx-ingress-leader-election
{
"time": "2024-11-27T16:20:07+00:00",
"remote_addr": "***",
"request": "GET /api/v1/stream/applications?name=nginx-ingress-controller-internal HTTP/1.1",
"status": "200",
"request_body_file": "-",
"request_body": "-",
"request_headers": {\x22X-FORWARDED-PROTO\x22:\x22https\x22,\x22X-FORWARDED-PORT\x22:\x22443\x22,\x22X-Forwarded-For\x22:\x2210.21.134.5: 50183\x22,\x22X-Original-URL\x22:\x22/api/v1/stream/applications?name=nginx-ingress-controller-internal\x22,\x22Connection\x22:\x22keep-alive\x22,\x22X-AppGW-Trace-Id\x22:\x2248ab159c938e467b061e423335b42f72\x22,\x22Host\x22:\x22***\x22,\x22X-ORIGINAL-HOST\x22:\x22***\x22,\x22sec-ch-ua-platform\x22:\x22\x5C\x22macOS\x5C\x22\x22,\x22cache-control\x22:\x22no-cache\x22,\x22user-agent\x22:\x22Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/131.0.0.0 Safari/537.36\x22,\x22accept\x22:\x22text/event-stream\x22,\x22sec-ch-ua\x22:\x22\x5C\x22Google Chrome\x5C\x22;v=\x5C\x22131\x5C\x22, \x5C\x22Chromium\x5C\x22;v=\x5C\x22131\x5C\x22, \x5C\x22Not_A Brand\x5C\x22;v=\x5C\x2224\x5C\x22\x22,\x22sec-ch-ua-mobile\x22:\x22?0\x22,\x22sec-fetch-site\x22:\x22same-origin\x22,\x22sec-fetch-mode\x22:\x22cors\x22,\x22sec-fetch-dest\x22:\x22empty\x22,\x22referer\x22:\x22https: //***/applications/nginx-ingress-controller-internal?resource=\x22,\x22accept-encoding\x22:\x22gzip, deflate, br, zstd\x22,\x22accept-language\x22:\x22en-US,en-NG;q=0.9,en;q=0.8\x22,\x22priority\x22:\x22u=1, i\x22,\x22cookie\x22:\x22***\x22},   "response_headers": {\x22Content-Type\x22:\x22text/event-stream\x22,\x22Grpc-Metadata-Content-Type\x22:\x22application/grpc\x22,\x22X-Content-Type-Options\x22:\x22nosniff\x22},   "response_body": "\x22\x22", }

[xeioex]

Hi @Asiya-Yunusa,

in regards to request_body, you are using $request_body variable. Which returns the body value only when the body is in memory. When client_body_in_file_only is set to on or clean this variable will be empty. Probably you wanted to use $request_body_njs which works if the request body contains JSON.

I also suggest to add escape=json to your log_format directive. So it will be parseable as JSON.

[Asiya-Yunusa]

Thank you @xeioex, I added request body directly because I saw it in the variables that are available by default on NGINX. My main issue is the response body variable. It does not populate at all. It just returns an empty string, even when I catch the response gotten by NGINX to process it is empty.

I updated the request body variable to request_body_njs but its an empty parameter still. The json format updated, thank you.

[xeioex]

Hi @Asiya-Yunusa,

I am using the following nginx.conf and js script.

 curl http://127.0.0.1:8080/ --data-raw "WAKAWAKA" -v
*   Trying 127.0.0.1:8080...
* Connected to 127.0.0.1 (127.0.0.1) port 8080 (#0)
> POST / HTTP/1.1
> Host: 127.0.0.1:8080
> User-Agent: curl/7.81.0
> Accept: */*
> Content-Length: 8
> Content-Type: application/x-www-form-urlencoded
> 
* Mark bundle as not supporting multiuse
< HTTP/1.1 200 OK
< Server: nginx/1.25.5
< Date: Thu, 12 Dec 2024 01:35:46 GMT
< Content-Type: text/plain
< Content-Length: 7
< Connection: keep-alive
< 
* Connection #0 to host 127.0.0.1 left intact
BACKEND

have the following lines in the logs

2024/12/11 17:35:46 [notice] 579318#579318: *4 a client request body is buffered to a temporary file /usr/local/nginx/client_body_temp/0000987650, client: 127.0.0.1, server: , request: "POST / HTTP/1.1", host: "127.0.0.1:8080"
{ "time": "2024-12-11T17:35:46-08:00","remote_addr": "127.0.0.1","request": "POST / HTTP/1.1","status": "200","request_body_file": "/usr/local/nginx/client_body_temp/0000987650","request_body": "WAKAWAKA","request_headers": {\"Host\":\"127.0.0.1:8080\",\"User-Agent\":\"curl/7.81.0\",\"Accept\":\"*/*\",\"Content-Length\":\"8\",\"Content-Type\":\"application/x-www-form-urlencoded\"},"response_headers": {\"Content-Type\":\"text/plain\",\"Content-Length\":\"7\"},"response_body": "\"BACKEND\""}

What kinds of request and you using and what do you get in the logs?