#1126 closed defect (fixed)
No error logged when hitting upstream connect timeout over HTTPS
| Reported by: | Owned by: | ||
|---|---|---|---|
| Priority: | minor | Milestone: | |
| Component: | nginx-core | Version: | 1.10.x |
| Keywords: | Cc: | ||
| uname -a: | Linux haxbox.local 2.6.32-642.3.1.el6.x86_64 #1 SMP Sun Jun 26 18:16:44 EDT 2016 x86_64 x86_64 x86_64 GNU/Linux | ||
| nginx -V: |
ginx version: nginx/1.10.1
built by gcc 4.4.7 20120313 (Red Hat 4.4.7-16) (GCC) built with OpenSSL 1.0.1e-fips 11 Feb 2013 TLS SNI support enabled configure arguments: --prefix=/etc/nginx --sbin-path=/usr/sbin/nginx --modules-path=/usr/lib64/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-http_ssl_module --with-http_realip_module --with-http_addition_module --with-http_sub_module --with-http_dav_module --with-http_flv_module --with-http_mp4_module --with-http_gunzip_module --with-http_gzip_static_module --with-http_random_index_module --with-http_secure_link_module --with-http_stub_status_module --with-http_auth_request_module --with-http_xslt_module=dynamic --with-http_image_filter_module=dynamic --with-http_geoip_module=dynamic --with-http_perl_module=dynamic --add-dynamic-module=njs-1c50334fbea6/nginx --with-threads --with-stream --with-stream_ssl_module --with-http_slice_module --with-mail --with-mail_ssl_module --with-file-aio --with-ipv6 --with-http_v2_module --with-cc-opt='-O2 -g -pipe -Wall -Wp,-D_FORTIFY_SOURCE=2 -fexceptions -fstack-protector --param=ssp-buffer-size=4 -m64 -mtune=generic' |
||
Description
It seems like no errors are logged, not even using "error_log /var/log/nginx/error.log debug;", when upstream_connect_timeout is reached while attempting a TLS handshake with an upstream peer.
This makes it difficult to determine the source of the 502 errors that are returned back to the clients (no error might imply that the error is just proxy-passed, which is not the case).
I used the following minimal server config to reproduce the issue:
upstream test {
server 127.0.0.1:7443;
}
server {
listen 80;
server_name localhost;
location / {
proxy_connect_timeout 1;
proxy_read_timeout 5;
proxy_pass https://test;
}
}
with this python script acting as upstream server:
import socket
import time
sock = socket.socket(socket.AF_INET, socket.SOCK_STREAM)
server_address = ('127.0.0.1', 7443)
sock.bind(server_address)
sock.listen(1)
while True:
connection, client_address = sock.accept()
time.sleep(10)
connection.close()
When using http proxy_pass, i.e "proxy_pass http://test;", and requesting http://localhost using cURL, I get a 502 error back, and the following shows up in the error log:
2016/11/09 13:31:30 [error] 6282#6282: *1 upstream timed out (110: Connection timed out) while reading response header from upstream, client: 127.0.0.1, server: localhost, request: "GET / HTTP/1.1", upstream: "http://127.0.0.1:7443/", host: "localhost" 2016/11/09 13:31:30 [info] 6282#6282: *1 client 127.0.0.1 closed keepalive connection
However, if I switch to "proxy_pass https://test;", I get a 502 but only the "closed keepalive connection" message in the error log:
2016/11/09 13:33:05 [info] 6766#6766: *1 client 127.0.0.1 closed keepalive connection
Thanks for tracing this. Additionally, the error should be 504, not 502, and this is also confusing. Please try the following patch:
# HG changeset patch # User Maxim Dounin <mdounin@mdounin.ru> # Date 1478706403 -10800 # Wed Nov 09 18:46:43 2016 +0300 # Node ID 5a4bcd2979bc73fe0c73833fc8c648fdeec72e29 # Parent 1a917932db963e7ecf4d786cc02bd54bd4548b88 Upstream: handling of upstream SSL handshake timeouts. Previously SSL handshake timeouts were not properly logged, and resulted in 502 errors instead of 504 (ticket #1126). diff --git a/src/http/ngx_http_upstream.c b/src/http/ngx_http_upstream.c --- a/src/http/ngx_http_upstream.c +++ b/src/http/ngx_http_upstream.c @@ -1666,6 +1666,13 @@ ngx_http_upstream_ssl_handshake(ngx_conn return; } + if (c->write->timedout) { + c = r->connection; + ngx_http_upstream_next(r, u, NGX_HTTP_UPSTREAM_FT_TIMEOUT); + ngx_http_run_posted_requests(c); + return; + } + failed: c = r->connection;