Having problems with HTTP/2 on 1.9.7.4

[Igor Clark]

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

[Igor Clark]

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

[Igor Clark]

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

[Yichun Zhang (agentzh)]

Hello!

On Fri, Mar 25, 2016 at 8:37 AM, Igor Clark wrote:
> 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.

Thanks for the investigation and report! Will you file a GitHub issue
in the lua-nginx-module repos? Thanks a lot!

Best regards,
-agentzh

[Igor Clark]

Hi agentzh! Sure, sorry - don't know why I didn't think to do that. Duh.

Here it is: https://github.com/openresty/lua-nginx-module/issues/724

Thanks!

cheers,
Igor