Opened 22 months ago
Closed 22 months ago
#2461 closed defect (invalid)
Unable to identify upstream errors
| Reported by: | Owned by: | ||
|---|---|---|---|
| Priority: | minor | Milestone: | nginx-1.23 |
| Component: | nginx-module | Version: | 1.23.x |
| Keywords: | ngx_http_proxy_module | Cc: | |
| uname -a: | Linux 4b832a089ad0 5.15.64-0-virt #1-Alpine SMP Mon, 05 Sep 2022 08:02:49 +0000 x86_64 GNU/Linux | ||
| nginx -V: |
nginx version: nginx/1.23.3
built by gcc 10.2.1 20210110 (Debian 10.2.1-6) built with OpenSSL 1.1.1n 15 Mar 2022 TLS SNI support enabled configure arguments: --prefix=/etc/nginx --sbin-path=/usr/sbin/nginx --modules-path=/usr/lib/nginx/modules --conf-path=/etc/nginx/nginx.conf --error-log-path=/var/log/nginx/error.log --http-log-path=/var/log/nginx/access.log --pid-path=/var/run/nginx.pid --lock-path=/var/run/nginx.lock --http-client-body-temp-path=/var/cache/nginx/client_temp --http-proxy-temp-path=/var/cache/nginx/proxy_temp --http-fastcgi-temp-path=/var/cache/nginx/fastcgi_temp --http-uwsgi-temp-path=/var/cache/nginx/uwsgi_temp --http-scgi-temp-path=/var/cache/nginx/scgi_temp --user=nginx --group=nginx --with-compat --with-file-aio --with-threads --with-http_addition_module --with-http_auth_request_module --with-http_dav_module --with-http_flv_module --with-http_gunzip_module --with-http_gzip_static_module --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-mail --with-mail_ssl_module --with-stream --with-stream_realip_module --with-stream_ssl_module --with-stream_ssl_preread_module --with-cc-opt='-g -O2 -ffile-prefix-map=/data/builder/debuild/nginx-1.23.3/debian/debuild-base/nginx-1.23.3=. -fstack-protector-strong -Wformat -Werror=format-security -Wp,-D_FORTIFY_SOURCE=2 -fPIC' --with-ld-opt='-Wl,-z,relro -Wl,-z,now -Wl,--as-needed -pie' |
||
Description
Consider this config file.
events {}
http {
log_format main 'Returned ${status} in ${request_time}s, upstream returned ${upstream_status} in ${upstream_response_time}s. Request id: ${request_id}. Response id: ${sent_http_response_id}. Cache status: ${upstream_cache_status}.';
proxy_cache_path /var/cache keys_zone=zone1:10m inactive=60m;
access_log /dev/stdout main;
error_log /dev/stderr;
upstream api {
server api:3000;
}
server {
listen 8000;
location / {
proxy_pass http://api;
proxy_set_header X-Request-Id $request_id;
proxy_send_timeout 2s;
proxy_read_timeout 2s;
proxy_cache zone1;
proxy_cache_key "$uri";
proxy_cache_valid any 10s;
proxy_cache_use_stale updating error timeout invalid_header http_500 http_502 http_503 http_504;
proxy_cache_lock on;
proxy_cache_lock_timeout 30s;
proxy_cache_background_update on;
}
}
}
When using proxy_cache_background_update on, Nginx will respond to the client with a stale cache and asynchronously will revalidate the cache. The cache status, in this case, is STALE and the cached response status is used. Doesn't matter if the upstream respond with success or not (e.g. 200 or 500), I won't be able to see this problem on Nginx logs.
If I turn proxy_cache_background_update off, I'll be able to check the real status by using upstream_status, but this variable is always empty if proxy_cache_background_update on.
Here is a runnable example: https://github.com/pcandido/nginx-cache/tree/nginx-ticket (branch nginx-ticket). It will show that there is no difference in the log if the upstream request succeeds or fails.
Besides the log format used in the example, I inspected 97 variables, and none of them was able to show me the upstream fail. $ancient_browser, $arg_, $args, $binary_remote_addr, $body_bytes_sent, $bytes_received, $bytes_sent, $connection, $connection_requests, $connection_time, $connections_active, $connections_reading, $connections_waiting, $connections_writing, $content_length, $content_type, $cookie_, $date_gmt, $date_local, $document_root, $document_uri, $fastcgi_path_info, $fastcgi_script_name, $gzip_ratio, $host, $hostname, $http2, $http_, $https, $invalid_referer, $is_args, $jwt_claim_, $jwt_header_, $jwt_payload, $limit_conn_status, $limit_rate, $limit_req_status, $memcached_key, $modern_browser, $msec, $msie, $nginx_version, $pid, $pipe, $protocol, $proxy_add_x_forwarded_for, $proxy_host, $proxy_port, $query_string, $realip_remote_addr, $realip_remote_port, $realpath_root, $remote_addr, $remote_port, $remote_user, $request, $request_body, $request_body_file, $request_completion, $request_filename, $request_id, $request_length, $request_method, $request_time, $request_uri, $scheme, $sent_http_, $sent_trailer_, $slice_range, $spdy, $spdy_request_priority, $status, $tcpinfo_rcv_space, $tcpinfo_rtt, $tcpinfo_rttvar, $tcpinfo_snd_cwnd, $time_iso8601, $time_local, $uid_got, $uid_reset, $uid_set, $upstream_addr, $upstream_bytes_received, $upstream_bytes_sent, $upstream_cache_status, $upstream_connect_time, $upstream_cookie_, $upstream_first_byte_time, $upstream_header_time, $upstream_http_, $upstream_queue_time, $upstream_response_length, $upstream_response_time, $upstream_session_time, $upstream_status, $upstream_trailer_, $uri.
When using proxy_cache_background_update, nginx uses a background subrequest to update an expired cache item. Details for subrequest handling are not generally available in the main request variables (though you can set some variables explicitly).
Errors, if they happen during subrequest handling, are logged by nginx into the error log. If you want to get access logging for subrequests, consider using the log_subrequest directive.