5s hangs with http2 and variable-based proxy_pass

[Chris West]

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).
-------------- next part --------------
A non-text attachment was scrubbed...
Name: debug.log.gz
Type: application/x-gzip
Size: 15622 bytes
Desc: not available
URL: <http://mailman.nginx.org/pipermail/nginx/attachments/20161010/2508b4b3/attachment.bin>