My issue: Inconsistent logging with Nginx slice module
How I encountered the problem:
We are evaluating nginx slice for a file caching use case and while testing the same came across this inconsistency in logging of nginx.
Sample config:
Nginx config
nginx Nginx config - Pastebin.com
cache Cache config - Pastebin.com
upstream: Upstream.py - Pastebin.com
So when I tried to download via range request over nginx with slice configured, observed the following behavior while logging cache_key:
-
Nginx logs $slice_proxy_range, map variable from $slice_range, in cache_key as the value of the first slice range request. This is understood since nginx uses the primary request for the first slice range and rest are fetch over sub requests.
-
Logs
127.0.0.1 - - [12/Sep/2025:11:20:31 +0000] “GET /download/test.mp4 HTTP/1.1” 206 364 “localhost:6100” “-” “curl/7.81.0” “-” “bytes 0-99/223890855:bytes=0-99” “-” “application/octet-stream” “0.003” “127.0.0.1:5000” “0.003” “MISS” “cache_key=/download/test.mp4:bytes=0-1048575”
127.0.0.1 - - [12/Sep/2025:11:20:42 +0000] “GET /download/test.mp4 HTTP/1.1” 206 2000274 “localhost:6100” “-” “curl/7.81.0” “-” “bytes 0-2000000/223890855:bytes=0-2000000” “-” “application/octet-stream” “0.003” “-” “-” “HIT” “cache_key=/download/test.mp4:bytes=0-1048575”
-
-
Enabling sub request logging keeps the value of cache_key same across all sub requests.
Again this is expected because these sub requests do not go through normal request phases, but skip to the content phase. This means that if and set are ignored and the value remains the same from the primary/original request.-
Logs
127.0.0.1 - - [12/Sep/2025:11:22:47 +0000] “GET /download/test.mp4 HTTP/1.1” 206 2000274 “localhost:6100” “-” “curl/7.81.0” “-” “-:bytes=0-2000000” “-” “application/octet-stream” “0.005” “127.0.0.1:5000” “0.005” “MISS” “cache_key=/download/test.mp4:bytes=0-1048575”
127.0.0.1 - - [12/Sep/2025:11:22:47 +0000] “GET /download/test.mp4 HTTP/1.1” 206 2000274 “localhost:6100” “-” “curl/7.81.0” “-” “-:bytes=0-2000000” “-” “application/octet-stream” “0.010” “127.0.0.1:5000” “0.005” “MISS” “cache_key=/download/test.mp4:bytes=0-1048575”
-
-
However when I update the cache_key value in log to
cache_key=$uri:$slice_proxy_range, it logs the cache_key correctly for all sub requests but returns empty for the primary request.-
Logs
127.0.0.1 - - [12/Sep/2025:11:45:52 +0000] “GET /download/test.mp4 HTTP/1.1” 206 2000274 “localhost:6100” “-” “curl/7.81.0” “-” “-:bytes=0-2000000” “-” “application/octet-stream” “0.006” “127.0.0.1:5000” “0.006” “MISS” “cache_key=/download/test.mp4:bytes=1048576-2097151”
127.0.0.1 - - [12/Sep/2025:11:45:52 +0000] “GET /download/test.mp4 HTTP/1.1” 206 2000274 “localhost:6100” “-” “curl/7.81.0” “-” “-:bytes=0-2000000” “-” “application/octet-stream” “0.010” “127.0.0.1:5000” “0.004” “MISS” “cache_key=/download/test.mp4:”
-
Nginx logs the value for slice range in the primary request(see #1 above) but returns empty for primary request when sub request logging is on(see #3 above).
Some additional observations:
- Value of
$bytes_sentin subrequest logs seems to be cumulative of total bytes downloaded by all sub requests until the current sub request. - Value of
$sent_http_content_range:$http_rangealso do not show up correctly for any requests when sub request logging in turned on. - For requests spanning multiple slice ranges, if one slice range is cached then, with subrequests disabled, the logs shows the cache status as HIT while the rest of the cached slices are still fetched from upstream.
Right logging is helpful to debug during issues. Also right value for cache key or bytes_sent helps us identify any anomalies or slowness.
Can someone please help to identify what is wrong in the config or is this some bug?
Version of NGINX or NGINX adjacent software (e.g. NGINX Gateway Fabric):
nginx version: openresty/1.25.3.2
nginx -V
nginx version: openresty/1.25.3.2
built by gcc 13.2.1 20240309 (Alpine 13.2.1_git20240309)
built with OpenSSL 1.1.1w 11 Sep 2023
TLS SNI support enabled
configure arguments: --prefix=/usr/local/openresty/nginx --with-cc-opt=‘-O2 -DNGX_LUA_ABORT_AT_PANIC -I/usr/local/openresty/pcre/include -I/usr/local/openresty/openssl/include’ --add-module=../ngx_devel_kit-0.3.3 --add-module=../echo-nginx-module-0.63 --add-module=../xss-nginx-module-0.06 --add-module=../ngx_coolkit-0.2 --add-module=../set-misc-nginx-module-0.33 --add-module=../form-input-nginx-module-0.12 --add-module=../encrypted-session-nginx-module-0.09 --add-module=../srcache-nginx-module-0.33 --add-module=../ngx_lua-0.10.26 --add-module=../ngx_lua_upstream-0.07 --add-module=../headers-more-nginx-module-0.37 --add-module=../array-var-nginx-module-0.06 --add-module=../memc-nginx-module-0.20 --add-module=../redis2-nginx-module-0.15 --add-module=../redis-nginx-module-0.3.9 --add-module=../rds-json-nginx-module-0.16 --add-module=../rds-csv-nginx-module-0.09 --add-module=../ngx_stream_lua-0.0.14 --with-ld-opt=‘-Wl,-rpath,/usr/local/openresty/luajit/lib -L/usr/local/openresty/pcre/lib -L/usr/local/openresty/openssl/lib -Wl,-rpath,/usr/local/openresty/pcre/lib:/usr/local/openresty/openssl/lib’ --with-pcre --with-compat --with-file-aio --with-http_addition_module --with-http_auth_request_module --with-http_dav_module --with-http_flv_module --with-http_geoip_module=dynamic --with-http_gunzip_module --with-http_gzip_static_module --with-http_image_filter_module=dynamic --with-http_mp4_module --with-http_random_index_module --with-http_realip_module --with-http_secure_link_module --with-http_slice_module --with-http_ssl_module --with-http_stub_status_module --with-http_sub_module --with-http_v2_module --with-http_v3_module --with-http_xslt_module=dynamic --with-ipv6 --with-mail --with-mail_ssl_module --with-md5-asm --with-sha1-asm --with-stream --with-stream_ssl_module --with-threads --with-pcre-jit --with-stream --without-pcre2 --with-stream_ssl_preread_module
Deployment environment: Local test evaluation with docker image
Minimal NGINX config to reproduce your issue (preferably running on https://tech-playground.com/playgrounds/nginx for ease of debugging, and if not as a code block): (Tip → Run nginx -T to print your entire NGINX config to your terminal.)
ngnix -T config
nginx: the configuration file /usr/local/openresty/nginx/conf/nginx.conf syntax is ok
nginx: configuration file /usr/local/openresty/nginx/conf/nginx.conf test is successful
configuration file /usr/local/openresty/nginx/conf/nginx.conf:
user daemon;
worker_processes auto;
worker_rlimit_nofile 65536;
pid /run/openresty/summary_cache.pid;
events {
worker_connections 5000;
}
error_log /dev/stdout;
http {
include mime.types;
default_type application/octet-stream;
log_format main '$remote_addr - $remote_user [$time_local] "$request" '
'$status $body_bytes_sent "$http_referer" '
'"$http_user_agent" "$http_x_forwarded_for"';
# access_log /dev/stdout main;
sendfile on;
#tcp_nopush on;
#keepalive_timeout 0;
keepalive_timeout 65;
lua_shared_dict status_dict 5M;
# Hide Nginx Server Signature
server_tokens off;
include /usr/local/openresty/nginx/conf.d/cache.conf;
}
configuration file /usr/local/openresty/nginx/conf/mime.types:
types {
text/html html htm shtml;
text/css css;
text/xml xml;
image/gif gif;
image/jpeg jpeg jpg;
application/javascript js;
application/atom+xml atom;
application/rss+xml rss;
text/mathml mml;
text/plain txt;
text/vnd.sun.j2me.app-descriptor jad;
text/vnd.wap.wml wml;
text/x-component htc;
image/avif avif;
image/png png;
image/svg+xml svg svgz;
image/tiff tif tiff;
image/vnd.wap.wbmp wbmp;
image/webp webp;
image/x-icon ico;
image/x-jng jng;
image/x-ms-bmp bmp;
font/woff woff;
font/woff2 woff2;
application/java-archive jar war ear;
application/json json;
application/mac-binhex40 hqx;
application/msword doc;
application/pdf pdf;
application/postscript ps eps ai;
application/rtf rtf;
application/vnd.apple.mpegurl m3u8;
application/vnd.google-earth.kml+xml kml;
application/vnd.google-earth.kmz kmz;
application/vnd.ms-excel xls;
application/vnd.ms-fontobject eot;
application/vnd.ms-powerpoint ppt;
application/vnd.oasis.opendocument.graphics odg;
application/vnd.oasis.opendocument.presentation odp;
application/vnd.oasis.opendocument.spreadsheet ods;
application/vnd.oasis.opendocument.text odt;
application/vnd.openxmlformats-officedocument.presentationml.presentation
pptx;
application/vnd.openxmlformats-officedocument.spreadsheetml.sheet
xlsx;
application/vnd.openxmlformats-officedocument.wordprocessingml.document
docx;
application/vnd.wap.wmlc wmlc;
application/wasm wasm;
application/x-7z-compressed 7z;
application/x-cocoa cco;
application/x-java-archive-diff jardiff;
application/x-java-jnlp-file jnlp;
application/x-makeself run;
application/x-perl pl pm;
application/x-pilot prc pdb;
application/x-rar-compressed rar;
application/x-redhat-package-manager rpm;
application/x-sea sea;
application/x-shockwave-flash swf;
application/x-stuffit sit;
application/x-tcl tcl tk;
application/x-x509-ca-cert der pem crt;
application/x-xpinstall xpi;
application/xhtml+xml xhtml;
application/xspf+xml xspf;
application/zip zip;
application/octet-stream bin exe dll;
application/octet-stream deb;
application/octet-stream dmg;
application/octet-stream iso img;
application/octet-stream msi msp msm;
audio/midi mid midi kar;
audio/mpeg mp3;
audio/ogg ogg;
audio/x-m4a m4a;
audio/x-realaudio ra;
video/3gpp 3gpp 3gp;
video/mp2t ts;
video/mp4 mp4;
video/mpeg mpeg mpg;
video/quicktime mov;
video/webm webm;
video/x-flv flv;
video/x-m4v m4v;
video/x-mng mng;
video/x-ms-asf asx asf;
video/x-ms-wmv wmv;
video/x-msvideo avi;
}
configuration file /usr/local/openresty/nginx/conf.d/cache.conf:
ignore_invalid_headers off;
uninitialized_variable_warn off;
log_format gzip '$remote_addr - $remote_user [$time_local] '
'"$request" $status $bytes_sent '
'"$http_host" "$http_referer" "$http_user_agent" "$http_Accept_Encoding" '
'"$sent_http_content_range:$http_range" '
'"$gzip_ratio" "$sent_http_content_type" '
'"$request_time" "$upstream_addr" "$upstream_response_time" "$upstream_cache_status" "cache_key=$uri:$slice_proxy_range"';
access_log /dev/stdout gzip;
error_log /dev/stdout notice;
proxy_cache_path /mnt/volume1/cache/cache levels=1:2 keys_zone=cache:256m inactive=1d max_size=8000M;
proxy_temp_path /mnt/volume1/cache/proxy_temp;
resolver local=on ipv6=off;
send_timeout 300s;
client_body_timeout 300s;
proxy_read_timeout 300s;
client_max_body_size 0;
proxy_cache_methods GET;
proxy_max_temp_file_size 0;
proxy_cache_lock on;
proxy_cache_lock_timeout 60s;
proxy_cache_lock_age 120s;
proxy_cache_valid 200 1d;
proxy_cache_bypass true;
proxy_no_cache true;
proxy_request_buffering off;
proxy_http_version 1.1;
proxy_buffer_size 32k;
proxy_buffers 8 64k;
proxy_headers_hash_bucket_size 128;
proxy_ignore_headers Cache-Control;
proxy_ignore_headers Expires;
proxy_ignore_headers Set-Cookie;
tcp_nopush on;
tcp_nodelay on;
map $http_range $slice_proxy_range {
volatile;
~, $http_range;
default $slice_range;
}
server {
listen 6100;
proxy_set_header Host $host;
proxy_buffer_size 32k;
proxy_buffers 8 64k;
proxy_headers_hash_bucket_size 128;
server_name cache;
location /test {
return 200 "Cache Server is up and running\n";
}
location /download {
proxy_cache cache;
slice 1m;
log_subrequest on;
set $cache_key $uri:$slice_proxy_range;
proxy_cache_valid 200 206 1d;
proxy_cache_key $uri:$slice_proxy_range;
proxy_set_header Range $slice_proxy_range;
set $no_cache "";
if ($http_x_no_cache = "true") {
set $no_cache "no-cache";
}
if ($cache_key = "") {
set $no_cache "no-cache";
}
proxy_cache_bypass $no_cache;
proxy_no_cache $no_cache;
proxy_pass "http://127.0.0.1:5000";
}
}