Hello!
I spent some time digging further into this problem. Did a fresh VM build, upgraded debian to 7.9, removed all the custom nginx modules and worked through our config line by line. I found that this happens when we use http2 and "lua_check_client_abort on". If I change nothing else at all, just switch off lua_check_client_abort, the problem goes away.
To make sure, I did a clean build from the 1.9.7.4 release on github - https://github.com/openresty/openresty/archive/v1.9.7.4.tar.gz - tested it through, and found the same results. Here are all the steps I took.
Initial download and build:
$ curl -OL https://github.com/openresty/openresty/archive/v1.9.7.4.tar.gz
% Total % Received % Xferd Average Speed Time Time Time Current
Dload Upload Total Spent Left Speed
100 129 0 129 0 0 248 0 --:--:-- --:--:-- --:--:-- 353
0 0 0 670k 0 0 307k 0 --:--:-- 0:00:02 --:--:-- 446k
$ tar zxf v1.9.7.4.tar.gz
$ cd openresty-1.9.7.4/
$ make
$ cd openresty-1.9.7.4/
$ ls -d ../../../pcre-8.38
../../../pcre-8.38
$ ./configure --with-pcre=../../../pcre-8.38 --with-http_v2_module
$ make -j 3
$ make install
$ /usr/local/openresty/nginx/sbin/nginx -V
nginx version: openresty/1.9.7.4
built by gcc 4.7.2 (Debian 4.7.2-5)
built with OpenSSL 1.0.1e 11 Feb 2013
TLS SNI support enabled
configure arguments: --prefix=/usr/local/openresty/nginx --with-cc-opt=-O2 --add-module=../ngx_devel_kit-0.2.19 --add-module=../echo-nginx-module-0.58 --add-module=../xss-nginx-module-0.05 --add-module=../ngx_coolkit-0.2rc3 --add-module=../set-misc-nginx-module-0.30 --add-module=../form-input-nginx-module-0.11 --add-module=../encrypted-session-nginx-module-0.04 --add-module=../srcache-nginx-module-0.30 --add-module=../ngx_lua-0.10.2 --add-module=../ngx_lua_upstream-0.05 --add-module=../headers-more-nginx-module-0.29 --add-module=../array-var-nginx-module-0.05 --add-module=../memc-nginx-module-0.16 --add-module=../redis2-nginx-module-0.12 --add-module=../redis-nginx-module-0.3.7 --add-module=../rds-json-nginx-module-0.14 --add-module=../rds-csv-nginx-module-0.07 --with-ld-opt=-Wl,-rpath,/usr/local/openresty/luajit/lib --with-pcre=/home/vagrant/openresty/openresty-1.9.7.4/openresty-1.9.7.4/../../../pcre-8.38 --with-http_v2_module --with-http_ssl_module
Create some self-signed SSL certs:
openssl genrsa -out /etc/ssl/192.168.56.110.key 2048
openssl req -new -x509 -key /etc/ssl/192.168.56.110.key -out /etc/ssl/192.168.56.110.cert -days 3650 -subj /CN=192.168.56.110
Add the following server{} block to /etc/nginx/nginx.conf:
server {
listen 443 http2 ssl;
ssl_certificate /etc/ssl/192.168.56.110.cert;
ssl_certificate_key /etc/ssl/192.168.56.110.key;
ssl_protocols TLSv1 TLSv1.1 TLSv1.2;
location /test-lua {
lua_check_client_abort on;
content_by_lua_block {
ngx.header['content-type'] = 'text/plain'
ngx.say("hi world")
}
}
}
Try to access /test-lua, request fails as before:
$ /usr/local/bin/curl -k -v --http2 https://192.168.56.110/test-lua
* Trying 192.168.56.110...
* Connected to 192.168.56.110 (192.168.56.110) port 443 (#0)
* ALPN, offering h2
* ALPN, offering http/1.1
* Cipher selection: ALL:!EXPORT:!EXPORT40:!EXPORT56:!aNULL:!LOW:!RC4:@STRENGTH
* successfully set certificate verify locations:
* CAfile: /usr/local/etc/openssl/cert.pem
CApath: none
* TLSv1.2 (OUT), TLS header, Certificate Status (22):
* TLSv1.2 (OUT), TLS handshake, Client hello (1):
* TLSv1.2 (IN), TLS handshake, Server hello (2):
* NPN, negotiated HTTP2 (h2)
* TLSv1.2 (IN), TLS handshake, Certificate (11):
* TLSv1.2 (IN), TLS handshake, Server key exchange (12):
* TLSv1.2 (IN), TLS handshake, Server finished (14):
* TLSv1.2 (OUT), TLS handshake, Client key exchange (16):
* TLSv1.2 (OUT), TLS change cipher, Client hello (1):
* TLSv1.2 (OUT), TLS handshake, Unknown (67):
* TLSv1.2 (OUT), TLS handshake, Finished (20):
* TLSv1.2 (IN), TLS change cipher, Client hello (1):
* TLSv1.2 (IN), TLS handshake, Finished (20):
* SSL connection using TLSv1.2 / ECDHE-RSA-AES256-GCM-SHA384
* ALPN, server did not agree to a protocol
* Server certificate:
* subject: CN=192.168.56.110
* start date: Mar 25 14:24:23 2016 GMT
* expire date: Mar 23 14:24:23 2026 GMT
* issuer: CN=192.168.56.110
* SSL certificate verify result: self signed certificate (18), continuing anyway.
* Using HTTP2, server supports multi-use
* Connection state changed (HTTP/2 confirmed)
* TCP_NODELAY set
* Copying HTTP/2 data in stream buffer to connection buffer after upgrade: len=0
* Using Stream ID: 1 (easy handle 0x7fdcb300c400)
> GET /test-lua HTTP/1.1
> Host: 192.168.56.110
> User-Agent: curl/7.47.1
> Accept: */*
>
* Connection state changed (MAX_CONCURRENT_STREAMS updated)!
* HTTP/2 stream 1 was not closed cleanly: error_code = 2
* Closing connection 0
* TLSv1.2 (OUT), TLS alert, Client hello (1):
curl: (16) HTTP/2 stream 1 was not closed cleanly: error_code = 2
Check the log:
2016/03/25 15:13:48 [notice] 11103#0: using the "epoll" event method
2016/03/25 15:13:48 [notice] 11103#0: openresty/1.9.7.4
2016/03/25 15:13:48 [notice] 11103#0: built by gcc 4.7.2 (Debian 4.7.2-5)
2016/03/25 15:13:48 [notice] 11103#0: OS: Linux 3.2.0-4-amd64
2016/03/25 15:13:48 [notice] 11103#0: getrlimit(RLIMIT_NOFILE): 1024:4096
2016/03/25 15:13:48 [notice] 11104#0: start worker processes
2016/03/25 15:13:48 [notice] 11104#0: start worker process 11105
2016/03/25 15:14:06 [alert] 11105#0: *1 epoll_ctl(1, 3) failed (17: File exists), client: 192.168.56.1, server: , request: "GET /test-lua HTTP/2.0", host: "192.168.56.110"
Switch off lua_check_client_abort in /etc/nginx/nginx.conf:
server {
listen 443 http2 ssl;
ssl_certificate /etc/ssl/192.168.56.110.cert;
ssl_certificate_key /etc/ssl/192.168.56.110.key;
ssl_protocols TLSv1 TLSv1.1 TLSv1.2;
location /test-lua {
lua_check_client_abort off;
content_by_lua_block {
ngx.header['content-type'] = 'text/plain'
ngx.say("hi world")
}
}
}
Restart nginx, try to access /test-lua, request succeeds:
$ /usr/local/bin/curl -k -v --http2 https://192.168.56.110/test-lua
* Trying 192.168.56.110...
* Connected to 192.168.56.110 (192.168.56.110) port 443 (#0)
* ALPN, offering h2
* ALPN, offering http/1.1
* Cipher selection: ALL:!EXPORT:!EXPORT40:!EXPORT56:!aNULL:!LOW:!RC4:@STRENGTH
* successfully set certificate verify locations:
* CAfile: /usr/local/etc/openssl/cert.pem
CApath: none
* TLSv1.2 (OUT), TLS header, Certificate Status (22):
* TLSv1.2 (OUT), TLS handshake, Client hello (1):
* TLSv1.2 (IN), TLS handshake, Server hello (2):
* NPN, negotiated HTTP2 (h2)
* TLSv1.2 (IN), TLS handshake, Certificate (11):
* TLSv1.2 (IN), TLS handshake, Server key exchange (12):
* TLSv1.2 (IN), TLS handshake, Server finished (14):
* TLSv1.2 (OUT), TLS handshake, Client key exchange (16):
* TLSv1.2 (OUT), TLS change cipher, Client hello (1):
* TLSv1.2 (OUT), TLS handshake, Unknown (67):
* TLSv1.2 (OUT), TLS handshake, Finished (20):
* TLSv1.2 (IN), TLS change cipher, Client hello (1):
* TLSv1.2 (IN), TLS handshake, Finished (20):
* SSL connection using TLSv1.2 / ECDHE-RSA-AES256-GCM-SHA384
* ALPN, server did not agree to a protocol
* Server certificate:
* subject: CN=192.168.56.110
* start date: Mar 25 14:24:23 2016 GMT
* expire date: Mar 23 14:24:23 2026 GMT
* issuer: CN=192.168.56.110
* SSL certificate verify result: self signed certificate (18), continuing anyway.
* Using HTTP2, server supports multi-use
* Connection state changed (HTTP/2 confirmed)
* TCP_NODELAY set
* Copying HTTP/2 data in stream buffer to connection buffer after upgrade: len=0
* Using Stream ID: 1 (easy handle 0x7f99ec00c400)
> GET /test-lua HTTP/1.1
> Host: 192.168.56.110
> User-Agent: curl/7.47.1
> Accept: */*
>
* Connection state changed (MAX_CONCURRENT_STREAMS updated)!
< HTTP/2.0 200
< server:openresty/1.9.7.4
< date:Fri, 25 Mar 2016 15:09:09 GMT
< content-type:text/plain
<
hi world
* Connection #0 to host 192.168.56.110 left intact
Check the log:
2016/03/25 15:15:29 [notice] 11125#0: using the "epoll" event method
2016/03/25 15:15:29 [notice] 11125#0: openresty/1.9.7.4
2016/03/25 15:15:29 [notice] 11125#0: built by gcc 4.7.2 (Debian 4.7.2-5)
2016/03/25 15:15:29 [notice] 11125#0: OS: Linux 3.2.0-4-amd64
2016/03/25 15:15:29 [notice] 11125#0: getrlimit(RLIMIT_NOFILE): 1024:4096
2016/03/25 15:15:29 [notice] 11126#0: start worker processes
2016/03/25 15:15:29 [notice] 11126#0: start worker process 11127
This is repeatable on my machine, from a fresh build of openresty - with lua_check_client_abort on, an HTTP/2 request fails with the above error; with lua_check_client_abort off (or not present), an HTTP/2 request succeeds with no errors.
At this point I'm out of ideas - I can see there are a ton of tests in the openresty codebase for lua_check_client_abort, and I can see references to the "check_client_abort" member in the ngx_lua implementation, but that's getting deep into ngx_lua C code, where I'm out of my depth :-(
Fortunately for us we can get by without lua_check_client_abort, but it might bite someone else, so I hope this is useful.
Cheers,
Igor
On Monday, March 21, 2016 at 1:06:36 AM UTC, Igor Clark wrote:
Hi again - more digging around shows that "working in Safari" was a red herring. I'm on OSX 10.9 and 10.10 on the laptop, and it seems neither of those have HTTP/2 support in Safari. Doh.
I haven't done an OS upgrade to test whether it makes this stop working on Safari too(!), but I've checked the logs again while running the test config from Safari, and the working requests are definitely coming in as HTTP/1.1.
So that's one piece of puzzle down.
Cheers
Igor
On Sunday, March 20, 2016 at 4:43:35 PM UTC, Igor Clark wrote:
Hi there, hope all well!
On building and testing a new package for OpenResty 1.9.7.4, I found
that with this version, Lua scripts which output content directly no
longer return successfully to clients using HTTP/2. In Chrome (
Version 49.0.2623.87 (64-bit)), they all fail with
"net::ERR_SPDY_PROTOCOL_ERROR"
.
The site at large works as before, not only the standard nginx and
PHP sections, but all the rewrite_by_lua_* and access_by_lua_*
components work fine too, even when called via HTTP/2 requests to
the front end.
However making XmlHttpRequest calls from Chrome to any of the Lua
API endpoints fails with the SPDY error. nginx error_log shows this:
[alert] 5962#0: *2 epoll_ctl(1, 19) failed (17: File
exists)
The only reference I found online was this issue thread
https://github.com/openresty/lua-nginx-module/issues/252 - but that
was closed because SPDY support was finished. (I think I read
somewhere that nginx's HTTP/2 implementation uses some of the SPDY
code, but I could be imagining that.)
To try to track it down, I made as simple a test config as I could:
location /test-lua {
content_by_lua_block {
ngx.header['content-type'] = 'text/plain'
ngx.say("hi world")
}
}
And that failed with the same error:
This site can’t be reached
The webpage at https://my_host/test-lua might be temporarily down
or it may have moved permanently to a new web address.
ERR_SPDY_PROTOCOL_ERROR
At first I thought it might somehow be a Chrome HTTP/2
implementation issue, but it happens in Firefox too. (And Chromium,
but I guess that'd be expected.) Strangely, it doesn't happen in
Safari - but it does happen with curl.
Here's a bunch of detailed output, some private info removed. Hope
it helps point somehow to where the problem might lie.
nginx -V output for the new build:
# /usr/share/openresty/nginx/sbin/nginx -V
nginx version: openresty/1.9.7.4
built by gcc 4.7.2 (Debian 4.7.2-5)
built with OpenSSL 1.0.1e 11 Feb 2013
TLS SNI support enabled
configure arguments: --prefix=/usr/share/openresty/nginx
--with-debug --with-cc-opt='-DNGX_LUA_USE_ASSERT
-DNGX_LUA_ABORT_AT_PANIC -O2 -g -O2 -fstack-protector
--param=ssp-buffer-size=4 -Wformat -Werror=format-security
-D_FORTIFY_SOURCE=2 -I/usr/share/maxmind/include'
--add-module=../ngx_devel_kit-0.2.19
--add-module=../echo-nginx-module-0.58
--add-module=../xss-nginx-module-0.05
--add-module=../ngx_coolkit-0.2rc3
--add-module=../set-misc-nginx-module-0.30
--add-module=../form-input-nginx-module-0.11
--add-module=../encrypted-session-nginx-module-0.04
--add-module=../srcache-nginx-module-0.30
--add-module=../ngx_lua-0.10.2
--add-module=../ngx_lua_upstream-0.05
--add-module=../headers-more-nginx-module-0.29
--add-module=../array-var-nginx-module-0.05
--add-module=../memc-nginx-module-0.16
--add-module=../redis2-nginx-module-0.12
--add-module=../redis-nginx-module-0.3.7
--add-module=../rds-json-nginx-module-0.14
--add-module=../rds-csv-nginx-module-0.07
--add-module=../nginx-push-stream-module-0.5.1
--add-module=../ngx_cache_purge-2.3
--add-module=../ngx_http_geoip2_module-1.0
--with-ld-opt='-Wl,-rpath,/usr/share/openresty/luajit/lib
-Wl,-z,relro -L/usr/share/maxmind/lib -lmaxminddb'
--with-pcre=/home/vagrant/openresty-openresty-3041624/openresty-1.9.7.4/../../pcre-8.38
--with-pcre-jit --with-pcre-conf-opt=--enable-unicode-properties
--with-http_dav_module --conf-path=/etc/nginx/nginx.conf
--http-log-path=/var/log/nginx/access.log
--error-log-path=/var/log/nginx/error.log
--lock-path=/var/lock/nginx.lock --pid-path=/run/nginx.pid
--http-client-body-temp-path=/var/lib/nginx/body
--http-fastcgi-temp-path=/var/lib/nginx/fastcgi
--http-proxy-temp-path=/var/lib/nginx/proxy
--http-scgi-temp-path=/var/lib/nginx/scgi
--http-uwsgi-temp-path=/var/lib/nginx/uwsgi --with-ipv6
--with-http_v2_module --with-http_ssl_module
--with-http_stub_status_module --with-http_realip_module
--with-http_auth_request_module --with-http_addition_module
--with-http_gzip_static_module --with-http_sub_module
Linux version is debian/7.6, wheezy-backports:
Linux frontend 3.2.0-4-amd64 #1 SMP Debian
3.2.60-1+deb7u3 x86_64 GNU/Linux
nginx log entries when running the test configuration above:
[access_log]
192.168.56.1 my_host open [20/Mar/2016:15:29:22 +0000] "GET
/test-lua HTTP/2.0" 000 0 "-" "curl/7.47.1" "-"
[error_log]
2016/03/20 15:29:22 [alert] 5692#0: *4 epoll_ctl(1, 23) failed
(17: File exists), client: 192.168.56.1, server: my_host, request:
"GET /test-lua HTTP/2.0", host: "my_host"
nginx log entries, running test configuration at 'debug' log level:
[access_log]
192.168.56.1 my_host user [20/Mar/2016:15:54:09 +0000] "GET
/test-lua HTTP/2.0" 000 0 "-" "curl/7.47.1" "-"
[error_log]
2016/03/20 15:54:09 [debug] 5727#0: *2 SSL NPN advertised
2016/03/20 15:54:09 [debug] 5727#0: *2 SSL_do_handshake: -1
2016/03/20 15:54:09 [debug] 5727#0: *2 SSL_get_error: 2
2016/03/20 15:54:09 [debug] 5727#0: *2 reusable connection: 0
2016/03/20 15:54:09 [debug] 5727#0: *2 post event 0000000002029950
2016/03/20 15:54:09 [debug] 5727#0: *2 delete posted event
0000000002029950
2016/03/20 15:54:09 [debug] 5727#0: *2 SSL handshake handler: 0
2016/03/20 15:54:09 [debug] 5727#0: *2 ssl new session:
68E5144B:32:165
2016/03/20 15:54:09 [debug] 5727#0: *2 SSL_do_handshake: 1
2016/03/20 15:54:09 [debug] 5727#0: *2 SSL: TLSv1.2, cipher:
"ECDHE-RSA-AES128-GCM-SHA256 TLSv1.2 Kx=ECDH Au=RSA
Enc=AESGCM(128) Mac=AEAD"
2016/03/20 15:54:09 [debug] 5727#0: *2 init http2 connection
2016/03/20 15:54:09 [debug] 5727#0: *2 malloc:
0000000001CC4770:400
2016/03/20 15:54:09 [debug] 5727#0: *2 posix_memalign:
0000000001CC3690:4096 @16
2016/03/20 15:54:09 [debug] 5727#0: *2 add cleanup:
0000000001B80910
2016/03/20 15:54:09 [debug] 5727#0: *2 malloc:
0000000001B819E0:256
2016/03/20 15:54:09 [debug] 5727#0: *2 posix_memalign:
0000000001CC54F0:256 @16
2016/03/20 15:54:09 [debug] 5727#0: *2 http2 send SETTINGS frame
2016/03/20 15:54:09 [debug] 5727#0: *2 http2 read handler
2016/03/20 15:54:09 [debug] 5727#0: *2 SSL_read: 24
2016/03/20 15:54:09 [debug] 5727#0: *2 SSL_read: 9
2016/03/20 15:54:09 [debug] 5727#0: *2 SSL_read: 80
2016/03/20 15:54:09 [debug] 5727#0: *2 SSL_read: -1
2016/03/20 15:54:09 [debug] 5727#0: *2 SSL_get_error: 2
2016/03/20 15:54:09 [debug] 5727#0: *2 http2 preface verified
2016/03/20 15:54:09 [debug] 5727#0: *2 process http2 frame type:4
f:0 l:0 sid:0
2016/03/20 15:54:09 [debug] 5727#0: *2 http2 send SETTINGS frame
2016/03/20 15:54:09 [debug] 5727#0: *2 http2 frame complete
pos:0000000002072F51 end:0000000002072FA1
2016/03/20 15:54:09 [debug] 5727#0: *2 process http2 frame type:1
f:5 l:71 sid:1
2016/03/20 15:54:09 [debug] 5727#0: *2 http2 HEADERS frame sid:1
on 0 excl:0 weight:16
2016/03/20 15:54:09 [debug] 5727#0: *2 posix_memalign:
0000000001E74140:4096 @16
2016/03/20 15:54:09 [debug] 5727#0: *2 posix_memalign:
0000000001E75150:4096 @16
2016/03/20 15:54:09 [debug] 5727#0: *2 http2 get indexed header
name: 2
2016/03/20 15:54:09 [debug] 5727#0: *2 http2 get indexed header: 4
2016/03/20 15:54:09 [debug] 5727#0: *2 http2 hpack encoded string
length: 7
2016/03/20 15:54:09 [debug] 5727#0: *2 http uri: "/test-lua"
2016/03/20 15:54:09 [debug] 5727#0: *2 http args: ""
2016/03/20 15:54:09 [debug] 5727#0: *2 http exten: ""
2016/03/20 15:54:09 [debug] 5727#0: *2 http2 get indexed header
name: 7
2016/03/20 15:54:09 [debug] 5727#0: *2 http2 get indexed header: 1
2016/03/20 15:54:09 [debug] 5727#0: *2 http2 hpack encoded string
length: 19
2016/03/20 15:54:09 [debug] 5727#0: *2 http2 add header to hpack
table: ":authority: my_host"
2016/03/20 15:54:09 [debug] 5727#0: *2 malloc:
0000000001CC5760:512
2016/03/20 15:54:09 [debug] 5727#0: *2 malloc:
0000000001E76160:4096
2016/03/20 15:54:09 [debug] 5727#0: *2 http2 hpack table account:
67 free:4096
2016/03/20 15:54:09 [debug] 5727#0: *2 http regex set $deploy_env
to "vagrant"
2016/03/20 15:54:09 [debug] 5727#0: *2 http2 get indexed header:
23
2016/03/20 15:54:09 [debug] 5727#0: *2 http2 hpack encoded string
length: 21
2016/03/20 15:54:09 [debug] 5727#0: *2 http2 http header:
"authorization: Basic my_auth="
2016/03/20 15:54:09 [debug] 5727#0: *2 http2 get indexed header:
58
2016/03/20 15:54:09 [debug] 5727#0: *2 http2 hpack encoded string
length: 8
2016/03/20 15:54:09 [debug] 5727#0: *2 http2 add header to hpack
table: "user-agent: curl/7.47.1"
2016/03/20 15:54:09 [debug] 5727#0: *2 http2 hpack table account:
53 free:4029
2016/03/20 15:54:09 [debug] 5727#0: *2 http2 http header:
"user-agent: curl/7.47.1"
2016/03/20 15:54:09 [debug] 5727#0: *2 http2 get indexed header:
19
2016/03/20 15:54:09 [debug] 5727#0: *2 http2 hpack raw string
length: 3
2016/03/20 15:54:09 [debug] 5727#0: *2 http2 add header to hpack
table: "accept: */*"
2016/03/20 15:54:09 [debug] 5727#0: *2 http2 hpack table account:
41 free:3976
2016/03/20 15:54:09 [debug] 5727#0: *2 posix_memalign:
0000000001CC5A30:256 @16
2016/03/20 15:54:09 [debug] 5727#0: *2 http2 http header: "accept:
*/*"
2016/03/20 15:54:09 [debug] 5727#0: *2 http2 http request line:
"GET /test-lua HTTP/2.0"
2016/03/20 15:54:09 [debug] 5727#0: *2 generic phase: 0
2016/03/20 15:54:09 [debug] 5727#0: *2 rewrite phase: 1
2016/03/20 15:54:09 [debug] 5727#0: *2 rewrite phase: 2
[ here it sets a bunch of variables, chooses configuration ]
2016/03/20 15:54:09 [debug] 5727#0: *2 using configuration
"/test-lua"
2016/03/20 15:54:09 [debug] 5727#0: *2 http cl:-1 max:10485760
2016/03/20 15:54:09 [debug] 5727#0: *2 rewrite phase: 4
2016/03/20 15:54:09 [debug] 5727#0: *2 lua rewrite handler,
uri:"/test-lua" c:1
2016/03/20 15:54:09 [debug] 5727#0: *2 rewrite phase: 4
2016/03/20 15:54:09 [debug] 5727#0: *2 rewrite phase: 5
2016/03/20 15:54:09 [debug] 5727#0: *2 rewrite phase: 6
2016/03/20 15:54:09 [debug] 5727#0: *2 lua rewrite handler,
uri:"/test-lua" c:1
2016/03/20 15:54:09 [debug] 5727#0: *2 post rewrite phase: 7
2016/03/20 15:54:09 [debug] 5727#0: *2 generic phase: 8
2016/03/20 15:54:09 [debug] 5727#0: *2 generic phase: 9
2016/03/20 15:54:09 [debug] 5727#0: *2 generic phase: 10
2016/03/20 15:54:09 [debug] 5727#0: *2 access phase: 11
2016/03/20 15:54:09 [debug] 5727#0: *2 lua access handler,
uri:"/test-lua" c:1
2016/03/20 15:54:09 [debug] 5727#0: *2 access phase: 11
2016/03/20 15:54:09 [debug] 5727#0: *2 access phase: 12
2016/03/20 15:54:09 [debug] 5727#0: *2 read: 20, 00007FFFF4D91310,
2048, 0
2016/03/20 15:54:09 [debug] 5727#0: *2 rc: 0 user: "open" salt:
"$apr1$LGKsk178$nrtG3JhbWiyJ1/5CZmLWA1"
2016/03/20 15:54:09 [debug] 5727#0: *2 access phase: 13
2016/03/20 15:54:09 [debug] 5727#0: *2 access phase: 14
2016/03/20 15:54:09 [debug] 5727#0: *2 lua access handler,
uri:"/test-lua" c:1
2016/03/20 15:54:09 [debug] 5727#0: *2 post access phase: 15
2016/03/20 15:54:09 [debug] 5727#0: *2 try files phase: 16
2016/03/20 15:54:09 [debug] 5727#0: *2 lua content handler,
uri:"/test-lua" c:1
2016/03/20 15:54:09 [debug] 5727#0: *2 add cleanup:
0000000001E76048
2016/03/20 15:54:09 [debug] 5727#0: *2 lua creating new vm state
2016/03/20 15:54:09 [debug] 5727#0: *2 lua initializing lua
registry
2016/03/20 15:54:09 [debug] 5727#0: *2 lua initializing lua
globals
2016/03/20 15:54:09 [debug] 5727#0: *2 lua initialize the global
Lua VM 0000000040821378
2016/03/20 15:54:09 [debug] 5727#0: *2 malloc: 0000000001FD1E80:16
2016/03/20 15:54:09 [debug] 5727#0: *2 lua reset ctx
2016/03/20 15:54:09 [debug] 5727#0: *2 lua creating new thread
2016/03/20 15:54:09 [debug] 5727#0: *2 http cleanup add:
0000000001E76060
2016/03/20 15:54:09 [debug] 5727#0: *2 epoll add event: fd:19 op:1
ev:00002001
2016/03/20 15:54:09 [alert] 5727#0: *2 epoll_ctl(1, 19) failed
(17: File exists), client: 192.168.56.1, server: my_host, request:
"GET /test-lua HTTP/2.0", host: "my_host"
2016/03/20 15:54:09 [debug] 5727#0: *2 http finalize request: -1,
"/test-lua?" a:1, c:1
2016/03/20 15:54:09 [debug] 5727#0: *2 http terminate request
count:1
2016/03/20 15:54:09 [debug] 5727#0: *2 lua request cleanup:
forcible=0
2016/03/20 15:54:09 [debug] 5727#0: *2 http terminate cleanup
count:1 blk:0
2016/03/20 15:54:09 [debug] 5727#0: *2 http posted request:
"/test-lua?"
2016/03/20 15:54:09 [debug] 5727#0: *2 http terminate handler
count:1
2016/03/20 15:54:09 [debug] 5727#0: *2 http request count:1 blk:0
2016/03/20 15:54:09 [debug] 5727#0: *2 http2 close stream 1,
queued 0, processing 1
2016/03/20 15:54:09 [debug] 5727#0: *2 http close request
2016/03/20 15:54:09 [debug] 5727#0: *2 http log handler
2016/03/20 15:54:09 [debug] 5727#0: *2 run cleanup:
0000000001E76048
2016/03/20 15:54:09 [debug] 5727#0: *2 free: 0000000001E74140,
unused: 0
2016/03/20 15:54:09 [debug] 5727#0: *2 free: 0000000001E75150,
unused: 38
2016/03/20 15:54:09 [debug] 5727#0: *2 http2 frame complete
pos:0000000002072FA1 end:0000000002072FA1
2016/03/20 15:54:09 [debug] 5727#0: *2 http2 frame out:
0000000001CC3AF0 sid:0 bl:0 len:4
2016/03/20 15:54:09 [debug] 5727#0: *2 http2 frame out:
0000000001CC3848 sid:0 bl:0 len:0
2016/03/20 15:54:09 [debug] 5727#0: *2 http2 frame out:
0000000001CC3798 sid:0 bl:0 len:4
2016/03/20 15:54:09 [debug] 5727#0: *2 http2 frame out:
0000000001CC36E0 sid:0 bl:0 len:18
2016/03/20 15:54:09 [debug] 5727#0: *2 malloc:
0000000001EF9950:16384
2016/03/20 15:54:09 [debug] 5727#0: *2 SSL buf copy: 27
2016/03/20 15:54:09 [debug] 5727#0: *2 SSL buf copy: 13
2016/03/20 15:54:09 [debug] 5727#0: *2 SSL buf copy: 9
2016/03/20 15:54:09 [debug] 5727#0: *2 SSL buf copy: 13
2016/03/20 15:54:09 [debug] 5727#0: *2 SSL to write: 62
2016/03/20 15:54:09 [debug] 5727#0: *2 SSL_write: 62
2016/03/20 15:54:09 [debug] 5727#0: *2 tcp_nodelay
2016/03/20 15:54:09 [debug] 5727#0: *2 http2 frame sent:
0000000001CC36E0 sid:0 bl:0 len:18
2016/03/20 15:54:09 [debug] 5727#0: *2 http2 frame sent:
0000000001CC3798 sid:0 bl:0 len:4
2016/03/20 15:54:09 [debug] 5727#0: *2 http2 frame sent:
0000000001CC3848 sid:0 bl:0 len:0
2016/03/20 15:54:09 [debug] 5727#0: *2 http2 frame sent:
0000000001CC3AF0 sid:0 bl:0 len:4
2016/03/20 15:54:09 [debug] 5727#0: *2 free: 0000000001CC3690,
unused: 2800
2016/03/20 15:54:09 [debug] 5727#0: *2 free: 0000000001EF9950
2016/03/20 15:54:09 [debug] 5727#0: *2 reusable connection: 1
2016/03/20 15:54:09 [debug] 5727#0: *2 event timer del: 19:
1458489309686
2016/03/20 15:54:09 [debug] 5727#0: *2 event timer add: 19:
180000:1458489429704
2016/03/20 15:54:09 [debug] 5727#0: *2 http2 idle handler
2016/03/20 15:54:09 [debug] 5727#0: *2 reusable connection: 0
2016/03/20 15:54:09 [debug] 5727#0: *2 posix_memalign:
0000000001CC3690:4096 @16
2016/03/20 15:54:09 [debug] 5727#0: *2 http2 read handler
2016/03/20 15:54:09 [debug] 5727#0: *2 SSL_read: 9
2016/03/20 15:54:09 [debug] 5727#0: *2 SSL_read: 0
2016/03/20 15:54:09 [debug] 5727#0: *2 SSL_get_error: 6
2016/03/20 15:54:09 [debug] 5727#0: *2 peer shutdown SSL cleanly
2016/03/20 15:54:09 [debug] 5727#0: *2 process http2 frame type:4
f:1 l:0 sid:0
2016/03/20 15:54:09 [debug] 5727#0: *2 http2 frame complete
pos:0000000002072F39 end:0000000002072F39
2016/03/20 15:54:09 [debug] 5727#0: *2 close http connection: 19
2016/03/20 15:54:09 [debug] 5727#0: *2 SSL_shutdown: 1
2016/03/20 15:54:09 [debug] 5727#0: *2 event timer del: 19:
1458489429704
2016/03/20 15:54:09 [debug] 5727#0: *2 reusable connection: 0
2016/03/20 15:54:09 [debug] 5727#0: *2 run cleanup:
0000000001B80910
2016/03/20 15:54:09 [debug] 5727#0: *2 free: 0000000001CC3690,
unused: 4016
2016/03/20 15:54:09 [debug] 5727#0: *2 free: 0000000000000000
2016/03/20 15:54:09 [debug] 5727#0: *2 free: 0000000001E76160
2016/03/20 15:54:09 [debug] 5727#0: *2 free: 0000000001CC5760
2016/03/20 15:54:09 [debug] 5727#0: *2 free: 0000000001B819E0
2016/03/20 15:54:09 [debug] 5727#0: *2 free: 0000000001CC4770
2016/03/20 15:54:09 [debug] 5727#0: *2 free: 0000000001B6F1C0,
unused: 15
2016/03/20 15:54:09 [debug] 5727#0: *2 free: 0000000001B80840,
unused: 0
2016/03/20 15:54:09 [debug] 5727#0: *2 free: 0000000001CC54F0,
unused: 8
2016/03/20 15:54:09 [debug] 5727#0: *2 free: 0000000001CC5A30,
unused: 96
And here's the output of making the request with curl using
http/1.1:
$ /usr/local/bin/curl -v --http1.1 -u user:pass
https://my_host/test-lua
* Trying 192.168.56.101...
* Connected to my_host (192.168.56.101) port 443 (#0)
* ALPN, offering http/1.1
* Cipher selection:
ALL:!EXPORT:!EXPORT40:!EXPORT56:!aNULL:!LOW:!RC4:@STRENGTH
* successfully set certificate verify locations:
* CAfile: /usr/local/etc/openssl/cert.pem
[… SSL cert stuff …]
* SSL certificate verify ok.
* Server auth using Basic with user 'user'
> GET /test-lua HTTP/1.1
> Host: my_host
> Authorization: Basic my-auth=
> User-Agent: curl/7.47.1
> Accept: */*
>
< HTTP/1.1 200 OK
< Server: openresty
< Date: Sun, 20 Mar 2016 15:29:36 GMT
< Content-Type: text/plain; charset=utf-8
< Transfer-Encoding: chunked
< Connection: keep-alive
< Vary: Accept-Encoding
<
hi world
* Connection #0 to host my_host left intact
And using http/2:
$ /usr/local/bin/curl -v --http2 -u user:pass
https://my_host/test-lua
* Trying 192.168.56.101...
* Connected to my_host (192.168.56.101) port 443 (#0)
* ALPN, offering h2
* ALPN, offering http/1.1
* Cipher selection:
ALL:!EXPORT:!EXPORT40:!EXPORT56:!aNULL:!LOW:!RC4:@STRENGTH
* successfully set certificate verify locations:
* CAfile: /usr/local/etc/openssl/cert.pem
[… SSL cert stuff …]
* SSL certificate verify ok.
* Using HTTP2, server supports multi-use
* Connection state changed (HTTP/2 confirmed)
* TCP_NODELAY set
* Copying HTTP/2 data in stream buffer to connection buffer after
upgrade: len=0
* Server auth using Basic with user 'user'
* Using Stream ID: 1 (easy handle 0x7fc5ba80c400)
> GET /test-lua HTTP/1.1
> Host: my_host
> Authorization: Basic my-auth=
> User-Agent: curl/7.47.1
> Accept: */*
>
* Connection state changed (MAX_CONCURRENT_STREAMS updated)!
* HTTP/2 stream 1 was not closed cleanly: error_code = 2
* Closing connection 0
* TLSv1.2 (OUT), TLS alert, Client hello (1):
curl: (16) HTTP/2 stream 1 was not closed cleanly: error_code = 2
(Not sure why it says "HTTP/2 confirmed" and then seems to issue an
HTTP/1.1 request? Would wonder if that's a curl issue, but with FF
& Chrome failing too ... ?)
I also tried switching off http2 in the particular server config:
listen 443 ssl;
That worked exactly as above: requests with --http1.1 work fine, but
using --http2 gives the same error.
Finally, I reverted to our previous OpenResty build, 1.9.7.2, on
which HTTP/2.0 works just fine, on all endpoints including Lua
scripts outputting directly, as before. The (automated) build
process for that 1.9.7.2 package was otherwise identical (except of
course that the OpenResty github project is now called 'openresty'
rather than 'ngx_openresty'):
# /usr/share/openresty/nginx/sbin/nginx -V
nginx version: openresty/1.9.7.2
built by gcc 4.7.2 (Debian 4.7.2-5)
built with OpenSSL 1.0.1e 11 Feb 2013
TLS SNI support enabled
configure arguments: --prefix=/usr/share/openresty/nginx
--with-debug --with-cc-opt='-DNGX_LUA_USE_ASSERT
-DNGX_LUA_ABORT_AT_PANIC -O2 -g -O2 -fstack-protector
--param=ssp-buffer-size=4 -Wformat -Werror=format-security
-D_FORTIFY_SOURCE=2 -I/usr/share/maxmind/include'
--add-module=../ngx_devel_kit-0.2.19
--add-module=../echo-nginx-module-0.58
--add-module=../xss-nginx-module-0.05
--add-module=../ngx_coolkit-0.2rc3
--add-module=../set-misc-nginx-module-0.29
--add-module=../form-input-nginx-module-0.11
--add-module=../encrypted-session-nginx-module-0.04
--add-module=../srcache-nginx-module-0.30
--add-module=../ngx_lua-0.10.0
--add-module=../ngx_lua_upstream-0.04
--add-module=../headers-more-nginx-module-0.29
--add-module=../array-var-nginx-module-0.04
--add-module=../memc-nginx-module-0.16
--add-module=../redis2-nginx-module-0.12
--add-module=../redis-nginx-module-0.3.7
--add-module=../rds-json-nginx-module-0.14
--add-module=../rds-csv-nginx-module-0.07
--add-module=../nginx-push-stream-module-0.5.1
--add-module=../ngx_cache_purge-2.3
--add-module=../ngx_http_geoip2_module-1.0
--with-ld-opt='-Wl,-rpath,/usr/share/openresty/luajit/lib
-Wl,-z,relro -L/usr/share/maxmind/lib -lmaxminddb'
--with-pcre=/home/vagrant/openresty-ngx_openresty-da90bd7/ngx_openresty-1.9.7.2/../../pcre-8.38
--with-pcre-jit --with-pcre-conf-opt=--enable-unicode-properties
--with-http_dav_module --conf-path=/etc/nginx/nginx.conf
--http-log-path=/var/log/nginx/access.log
--error-log-path=/var/log/nginx/error.log
--lock-path=/var/lock/nginx.lock --pid-path=/run/nginx.pid
--http-client-body-temp-path=/var/lib/nginx/body
--http-fastcgi-temp-path=/var/lib/nginx/fastcgi
--http-proxy-temp-path=/var/lib/nginx/proxy
--http-scgi-temp-path=/var/lib/nginx/scgi
--http-uwsgi-temp-path=/var/lib/nginx/uwsgi --with-ipv6
--with-http_v2_module --with-http_ssl_module
--with-http_stub_status_module --with-http_realip_module
--with-http_auth_request_module --with-http_addition_module
--with-http_gzip_static_module --with-http_sub_module
So - Safari works fine regardless of the build; Firefox, Chrome and
curl fail on 1.9.7.4. On first thoughts that makes it sound like
like either (a) 1.9.7.4 is doing something which is observing
HTTP/2.0 more strictly than 1.9.7.2 did, and exposing bugs in FF and
Chrome (which seems unlikely), or (b) Safari is being a bit more
relaxed about its HTTP/2 implementation and doesn't mind whatever it
is that 1.9.7.2 is doing.
Whatever the case, as I mentioned above, all the rest of our site
and app works fine - static content, PHP, everything works fine
using 1.9.7.4. Even the Lua code that doesn't output data directly
works fine - doing rewrites, access control, connecting to
databases, all fine. From what I can tell, it's just the Lua code
which actually sends output over the HTTP connection which hits this
problem.
Hope that makes sense, and hope there might be some way to work
round or fix it!
Cheers,
Igor
