Opened 4 years ago

Closed 4 years ago

Last modified 4 years ago

#1126 closed defect (fixed)

No error logged when hitting upstream connect timeout over HTTPS

Reported by: moshisushi@… 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

Change History (4)

comment:1 by Maxim Dounin, 4 years ago

Status: newaccepted

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;

comment:2 by Maxim Dounin <mdounin@…>, 4 years ago

In 6799:d8d037f20484/nginx:

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).

comment:3 by Maxim Dounin, 4 years ago

Resolution: fixed
Status: acceptedclosed

Fix committed.

comment:4 by Andrey Zelenkov <zelenkov@…>, 4 years ago

In 1080:cd4395a68fc6/nginx-tests:

Tests: proxy ssl test with handshake timeout (ticket #1126).

Note: See TracTickets for help on using tickets.