Welcome! Log In Create A New Profile

Advanced

5s hangs with http2 and variable-based proxy_pass

All files from this thread

File Name File Size   Posted by Date  
debug.log.gz 15.3 KB open | download Chris West 10/10/2016 Read message
Chris West
October 10, 2016 07:36AM
If you enable http2, our proxy setup develops 5s hangs, under load.
This happens from at least Chrome/linux, Firefox/linux and Edge/win10.

Any suggestions on how to further diagnose this problem, or work out
where this "5 second" number is coming from? Full reproduction config
and debug logs are attached, but I don't understand the debug logs.


This isn't always reproducible, but happens frequently. Changing
browser, restarting nginx, ... doesn't cause it to be immediately
reproducible.

The proxying is based on a variable:

resolver 8.8.4.4;
location ~/proxy/([a-z-]+\.example\.com)$ {
proxy_pass https://$1/foo;
...

This is easiest to see when a number of these urls are hit from a
single page, e.g.
<iframe src="/proxy/a.example.com"></iframe>
<iframe src="/proxy/b.example.com"></iframe>
.... etc.

The observed effect is that exactly eight requests will be serviced,
then there will be a 5s wait, then another eight will be serviced,
then hang, etc. until all requests have been serviced.


Reproduced on Ubuntu 16.04's nginx packages (1.10 based), with default
config, and this sites-enabled/default full config:

server {
listen 443 default_server ssl http2;
ssl on;

ssl_certificate /etc/letsencrypt/live/.../fullchain.pem;
ssl_certificate_key /etc/letsencrypt/live/.../privkey.pem;

root /var/www/html;
index index.html index.htm;
server_name _;
location / {
try_files $uri $uri/ =404;
}

resolver 8.8.4.4;
location ~/proxy/([a-z-]+\....)$ {
proxy_pass https://$1/index.txt;
proxy_http_version 1.1;
proxy_connect_timeout 13s;
proxy_read_timeout 28s;
}
}


The 5s pause is evident in the debug log. However, the debug log
*also* shows that the upstream requests have been generated, which
means that all the requests have been received.

Pause:

2016/10/10 11:17:31 [debug] 4058#4058: *238 process http2 frame type:3
f:0 l:4 sid:17
2016/10/10 11:17:31 [debug] 4058#4058: *238 http2 RST_STREAM frame,
sid:17 status:8
2016/10/10 11:17:31 [debug] 4058#4058: *238 unknown http2 stream
2016/10/10 11:17:31 [debug] 4058#4058: *238 http2 frame complete
pos:00007F536315501D end:00007F536315501D
2016/10/10 11:17:31 [debug] 4058#4058: *238 http2 read handler
2016/10/10 11:17:31 [debug] 4058#4058: *238 SSL_read: 13
2016/10/10 11:17:31 [debug] 4058#4058: *238 SSL_read: -1
2016/10/10 11:17:31 [debug] 4058#4058: *238 SSL_get_error: 2
2016/10/10 11:17:31 [debug] 4058#4058: *238 process http2 frame type:3
f:0 l:4 sid:13
2016/10/10 11:17:31 [debug] 4058#4058: *238 http2 RST_STREAM frame,
sid:13 status:8
2016/10/10 11:17:31 [debug] 4058#4058: *238 unknown http2 stream
2016/10/10 11:17:31 [debug] 4058#4058: *238 http2 frame complete
pos:00007F536315501D end:00007F536315501D
2016/10/10 11:17:31 [debug] 4058#4058: *238 http2 read handler
2016/10/10 11:17:31 [debug] 4058#4058: *238 SSL_read: 13
2016/10/10 11:17:31 [debug] 4058#4058: *238 SSL_read: -1
2016/10/10 11:17:31 [debug] 4058#4058: *238 SSL_get_error: 2
2016/10/10 11:17:31 [debug] 4058#4058: *238 process http2 frame type:3
f:0 l:4 sid:5
2016/10/10 11:17:31 [debug] 4058#4058: *238 http2 RST_STREAM frame,
sid:5 status:8
2016/10/10 11:17:31 [debug] 4058#4058: *238 unknown http2 stream
2016/10/10 11:17:31 [debug] 4058#4058: *238 http2 frame complete
pos:00007F536315501D end:00007F536315501D
2016/10/10 11:17:36 [debug] 4058#4058: *238 http upstream resolve:
"/proxy/nettesto....?"
2016/10/10 11:17:36 [debug] 4058#4058: *238 name was resolved to 94.23.43.98
2016/10/10 11:17:36 [debug] 4058#4058: *238 name was resolved to
2001:41d0:2:2c62::
2016/10/10 11:17:36 [debug] 4058#4058: *238 posix_memalign:
000055B45897FDB0:4096 @16
2016/10/10 11:17:36 [debug] 4058#4058: *238 get rr peer, try: 2
2016/10/10 11:17:36 [debug] 4058#4058: *238 get rr peer, current:
000055B45897FE18 -1
2016/10/10 11:17:36 [debug] 4058#4058: *238 stream socket 12


Upstream requsets:

2016/10/10 11:17:31 [debug] 4058#4058: *238 http proxy header:
"GET /index.txt HTTP/1.1^M
Host: nettestz.fau...^M


But they're not served by the backend until much later, at
[10/Oct/2016:11:17:46 +0000] in this case (according to the backend's
nginx access logs).

The host names mentioned in the debug log are public and are valid
until I pull them down, but I don't know if this is reproducible with
multiple people accessing it (and you can probably guess why I
stripped them from the email body).
_______________________________________________
nginx mailing list
nginx@nginx.org
http://mailman.nginx.org/mailman/listinfo/nginx
Attachments:
open | download - debug.log.gz (15.3 KB)
Subject Author Posted

5s hangs with http2 and variable-based proxy_pass Attachments

Chris West October 10, 2016 07:36AM

Re: 5s hangs with http2 and variable-based proxy_pass

Valentin V. Bartenev October 10, 2016 08:00AM

Re: 5s hangs with http2 and variable-based proxy_pass

Chris West October 10, 2016 08:32AM



Sorry, only registered users may post in this forum.

Click here to login

Online Users

Guests: 178
Record Number of Users: 6 on February 13, 2018
Record Number of Guests: 421 on December 02, 2018
Powered by nginx      Powered by FreeBSD      PHP Powered      Powered by MariaDB      ipv6 ready