Writing connections not closed after 'Pull brotli v1.0.4'

[eustas]

Writing connections not closed after 'Pull brotli v1.0.4'

[kochtopf]

...fastcgi_buffering off; does still produce those errors. BUT disabling the fastcgi_cache works. No errors anymore.

[eustas]

Hi. How could I view this status page?

[kochtopf]

This page is generated by the https://nginx.org/en/docs/http/ngx_http_stub_status_module.html. Normally Reading+Writing+Waiting=Active connections after send_timeout of 60s. This is not the case anymore. Some Writing connections are never closed - hanging until 'service nginx restart'.
This happens after upgrading from commit 8cd9dd5 to f1fcc84.
Thank you for reading.
Environment:
nginx version: nginx/1.13.12
built by gcc 7.3.0 (Raspbian 7.3.0-12)
built with OpenSSL 1.1.1-pre4 (beta) 3 Apr 2018

[eustas]

Between those commits the module has been completely rewritten =) Thanks for the heads-up, going to fix ASAP.

[eustas]

Can't reproduce on osx. Perhaps more ingredients come in play. Currently I build without SSL.
Going to try to build & run in docker + setup SSL.

[eustas]

Even with SSL can not reproduce on osx. Eventually the following happens:

2018/04/16 13:19:59 [notice] 43948#0: signal 20 (SIGCHLD) received from 43949
2018/04/16 13:19:59 [alert] 43948#0: worker process 43949 exited on signal 11
2018/04/16 13:19:59 [notice] 43948#0: start worker process 44066
2018/04/16 13:19:59 [notice] 43948#0: signal 23 (SIGIO) received

And after that the count of active connections become bigger than reading + writing + waiting...

[eustas]

This happens when client closes connection before the whole file is transferred.

[eustas]

I have a guess - nginx still tries to access the buffer, after reporting the error... Going to check it soon.

[kochtopf]

That's it. You are THE MAN! Did check the syslog but forgot the error.log. Sorry my bad. I do also see those...
2018/04/16 14:54:25 [alert] 8245#8245: *9 open socket #14 left in connection 6
2018/04/16 14:54:25 [alert] 8245#8245: aborting

but only with commit f1fcc84. Commit 8cd9dd5 do not produce those.
Thank you very much for looking into this...

[eustas]

OMG, I think I've found it! It is the last piece that was copied from the previous implementation of the filter. Just removing it fixes the problem for me =) Going to publish it soon.

[kochtopf]

Great. Can't wait... Thank you.

[eustas]

Would appreciate very much, if you check that problem is fixed in https://github.com/eustas/ngx_brotli/tree/fix-clean

[kochtopf]

Just a quick update. I did recompile but did not see any changes - same as before incl the log [alerts]. But I just compiled the modules. I'll try again with a full compile (takes a couple of minutes on this slow iron I use). Keep u updated...

[kochtopf]

Nope. Did not work for me. Same as before. I compiled this one:
-rw-r--r-- 1 root root 21298 Apr 16 20:12 ngx_http_brotli_filter_module.c
sha1sum ngx_http_brotli_filter_module.c
20e47073ae44417c3ae468b36acab0aeba51cca0 ngx_http_brotli_filter_module.c
PS:
What I tried before opening this issue: I compiled your filter from Commit 8cd9dd5 against pulled brotli v1.0.4 and the other way around (brotli v1.0.2 and the filter from commit f1fcc84). Booth combinations did not work - and left me glueless.

[eustas]

Going to dig further tomorrow...

[eustas]

Perhaps there is something RPi specific. We have fixed one problem recently (though it manifested itself on every try to compress: google/brotli#656).

Could you share your steps to build and run nginx from scratch, please. I'll try to do that on my RPi, and would be able to debug the crashes...

[kochtopf]

I do nothing special - like:

./configure --with-cc-opt="-D_REENTRANT -D_GNU_SOURCE -DDEBIAN -fwrapv -fno-strict-aliasing -pipe -I/usr/local/include -D_LARGEFILE_SOURCE -D_FILE_OFFSET_BITS=64 -I/usr/lib/arm-linux-gnueabihf/perl/5.26/CORE -g -g -O2 -fdebug-prefix-map='/<>=.' -fstack-protector-strong -Wformat -Werror=format-security -fPIC -Wdate-time -D_FORTIFY_SOURCE=2" --with-ld-opt="-Wl,-z,relro -Wl,-z,now -fPIC -fstack-protector-strong" --prefix=/usr/local/nginx --pid-path=/run/nginx.pid --conf-path=/usr/local/nginx/etc/nginx.conf --modules-path=/usr/local/nginx/modules --http-log-path=/var/log/nginx/access.log --error-log-path=/var/log/nginx/error.log --lock-path=/var/lock/nginx.lock --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-pcre-jit --with-threads --with-http_stub_status_module --with-http_v2_module --with-http_dav_module --with-http_realip_module --with-http_gunzip_module --with-http_gzip_static_module --with-http_ssl_module --add-dynamic-module=./modules/nginx-dav-ext-module-master --add-dynamic-module=./modules/ngx-fancyindex-master --add-dynamic-module=./modules/ngx_cache_purge-master --add-dynamic-module=./modules/ngx_http_substitutions_filter_module-master --add-dynamic-module=./modules/ngx_brotli
...
make -j4 -f objs/Makefile modules
install -s ../objs/ngx_http_brotli_filter_module.so /usr/local/nginx/modules/
install -s ../objs/ngx_http_brotli_static_module.so /usr/local/nginx/modules/

[eustas]

One last question - what distro is installed on RPi?

[kochtopf]

...I digged through the error.log and found one web site that do NOT produce those errors. This site does not use 'fastcgi_cache'. Earlier you mentioned used buffers. I'll try to disable those and report back.

I'm on debian Linux pi 4.14.31-v7+ #1104 SMP Thu Mar 29 16:52:18 BST 2018 armv7l GNU/Linux

[eustas]

Thanks for the research. This might become a clue to start investigation with!

[notr1ch]

I can confirm this issue, after installing this module CLOSE_WAIT sockets are piling up and tying up nginx worker connections. Within 12 hours website was unreachable due to worker connection exhaustion.

Using HTTPS/H2, PHP-FPM/FastCGI backend with fastcgi_cache in use.

Server without the module:

# ss -n4tp  | grep CLOSE-WAIT | wc -l
4

With the module:

# ss -n4tp  | grep CLOSE-WAIT | wc -l
27236

If there's any information I can provide to help with a fix please let me know.

[eustas]

As before, I would appreciate "repro" - i.e. build script + config that cause the problem. In this case I would be able to run it with debugger and unravel the problem to its source...

Is it possible to use netstat instead of ss. Sorry of the stupid questions, but developing under osx have its bright and dark sides =(

[notr1ch]

I tried to reproduce this with a proxy_cache instead of fastcgi_cache to make the test case easier but I couldn't seem to get it to reproduce there. So you'll need a FastCGI backend of some sort, I used Debian php5-fpm at /var/run/php5-fpm.sock. ngx_brotli is HEAD of master branch and libbrotli is the version from the submodule.

# nginx -V
nginx version: nginx/1.15.0
built by gcc 6.3.0 20170516 (Debian 6.3.0-18+deb9u1)
built with OpenSSL 1.1.0f  25 May 2017
TLS SNI support enabled
configure arguments: --prefix=/etc/nginx --sbin-path=/usr/sbin/nginx --modules-path=/usr/lib/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-compat --with-file-aio --with-threads --with-http_addition_module --with-http_auth_request_module --with-http_dav_module --with-http_flv_module --with-http_gunzip_module --with-http_gzip_static_module --with-http_mp4_module --with-http_random_index_module --with-http_realip_module --with-http_secure_link_module --with-http_slice_module --with-http_ssl_module --with-http_stub_status_module --with-http_sub_module --with-http_v2_module --with-mail --with-mail_ssl_module --with-stream --with-stream_realip_module --with-stream_ssl_module --with-stream_ssl_preread_module --with-cc-opt='-g -O2 -fdebug-prefix-map=/root/nginx-1.15.0=. -specs=/usr/share/dpkg/no-pie-compile.specs -fstack-protector-strong -Wformat -Werror=format-security -Wp,-D_FORTIFY_SOURCE=2 -fPIC' --with-ld-opt='-specs=/usr/share/dpkg/no-pie-link.specs -Wl,-z,relro -Wl,-z,now -Wl,--as-needed -pie' --add-module=/root/ngx_brotli

nginx.conf:

user www-data;
worker_processes 4;
pid nginx.pid;

events {
        use epoll;
        worker_connections 768;
}

http {
        proxy_cache_path /tmp/cache levels=1:2 keys_zone=tmp:1m max_size=10m inactive=7d use_temp_path=off;
        fastcgi_cache_path /tmp/fcgi_cache levels=1:2 keys_zone=fcgi_cache:1m inactive=60m;

        brotli on;

        types {
                text/html html;
        }

        server {
                listen 127.0.0.1:8000;
                root /tmp/repro;

                location = /cached_file {
                        proxy_pass http://127.0.0.1:8001/index.html;
                        proxy_cache tmp;
                        proxy_cache_key "$scheme$request_method$host$request_uri";
                        proxy_cache_use_stale error timeout invalid_header http_500;
                        proxy_cache_valid 1m;
                }

                location = /index.php {
                        fastcgi_param  QUERY_STRING       $query_string;
                        fastcgi_param  REQUEST_METHOD     $request_method;
                        fastcgi_param  CONTENT_TYPE       $content_type;
                        fastcgi_param  CONTENT_LENGTH     $content_length;

                        fastcgi_param  SCRIPT_FILENAME    $request_filename;
                        fastcgi_param  SCRIPT_NAME        $fastcgi_script_name;
                        fastcgi_param  REQUEST_URI        $request_uri;
                        fastcgi_param  DOCUMENT_URI       $document_uri;
                        fastcgi_param  DOCUMENT_ROOT      $document_root;
                        fastcgi_param  SERVER_PROTOCOL    $server_protocol;
                        fastcgi_param  HTTPS              $https if_not_empty;

                        fastcgi_param  GATEWAY_INTERFACE  CGI/1.1;
                        fastcgi_param  SERVER_SOFTWARE    nginx/$nginx_version;

                        fastcgi_param  REMOTE_ADDR        $remote_addr;
                        fastcgi_param  REMOTE_PORT        $remote_port;
                        fastcgi_param  SERVER_ADDR        $server_addr;
                        fastcgi_param  SERVER_PORT        $server_port;
                        fastcgi_param  SERVER_NAME        $server_name;

                        fastcgi_read_timeout 300;
                        fastcgi_pass unix:/var/run/php5-fpm.sock;
                        fastcgi_index index.php;

                        fastcgi_cache fcgi_cache;
                        fastcgi_cache_key "$scheme$request_method$host$request_uri";
                        fastcgi_cache_use_stale error timeout invalid_header http_500;
                        fastcgi_cache_valid 1m;
                }
        }

        server {
                listen 127.0.0.1:8001;
                root /tmp/repro;
        }
}

index.php is a file full of any compressible lines to ensure it triggers brotli, doesn't need to be valid PHP or anything as long as it's accessed over FastCGI.

Test case (curl output omitted):

# netstat -an | grep CLOSE_WAIT
# curl -i -H 'Accept-Encoding: br' http://127.0.0.1:8000/index.php > /dev/null
# curl -i -H 'Accept-Encoding: br' http://127.0.0.1:8000/index.php > /dev/null
# curl -i -H 'Accept-Encoding: br' http://127.0.0.1:8000/index.php > /dev/null
# curl -i -H 'Accept-Encoding: br' http://127.0.0.1:8000/index.php > /dev/null
# curl -i -H 'Accept-Encoding: br' http://127.0.0.1:8000/index.php > /dev/null
# curl -i -H 'Accept-Encoding: br' http://127.0.0.1:8000/index.php > /dev/null
# curl -i -H 'Accept-Encoding: br' http://127.0.0.1:8000/index.php > /dev/null
# netstat -an | grep CLOSE_WAIT
tcp        1      0 127.0.0.1:8000          127.0.0.1:55518         CLOSE_WAIT
tcp        1      0 127.0.0.1:8000          127.0.0.1:55514         CLOSE_WAIT
tcp        1      0 127.0.0.1:8000          127.0.0.1:55512         CLOSE_WAIT
tcp        1      0 127.0.0.1:8000          127.0.0.1:55516         CLOSE_WAIT
tcp        1      0 127.0.0.1:8000          127.0.0.1:55510         CLOSE_WAIT
tcp        1      0 127.0.0.1:8000          127.0.0.1:55520         CLOSE_WAIT

Hope this helps!

[eustas]

With few alterations was able to repro in docker. Thanks.
Going to dive into debugging soon.

[eustas]

One thing I've found so far - input file size only implicitly affects the problem. Output (compressed) size have to be bigger than X to trigger the problem.

[eustas]

More intriguing details. When stream has upstream set (i.e. is not taken from the cache), like upstream: "fastcgi://unix:/var/run/php5-fpm.sock:", then connection is normally closed (client 127.0.0.1 closed keepalive connection).
This explains why not 100% fetches come into this state. Still, can't see what is the difference between fetching form upstream and cache.

[eustas]

The difference is that when served from cache few last blocks are coalesced (including empty last block). But this is all about input, so it can't affect output...

[eustas]

In cases when connection is closed, "ngx_http_set_keepalive" is invoked... On "unlucky" fetches it is not... So it does not close connection afterwards...

[eustas]

I suspect that this is nginx bug introduced ~8 months ago : nginx/nginx@661e408

It does not finalize subrequest if ngx_http_upstream_cache_send returns NGX_DONE.
Going to check further.

[eustas]

In comments to that change they do not take into account that ngx_http_cache_send can return NGX_DONE

[eustas]

Hey, @notr1ch, could you try if #16 fixes the problem and do not create new ones, please? Thanks.

[notr1ch]

Looks good on the test case, I can no longer reproduce the socket leak. I have put it into production and will continue to monitor.

[eustas]

(was unintentionally closed by PR comment)

[notr1ch]

I haven't seen any socket leaks since applying the patch nor have I received any reports about broken output, this is from a fairly active site (125k uniques/day) so I would consider this fixed. Thanks!