zero size buf in output with proxy cache

[Ivan]

As I can see it happens on all versions of nginx from 1.8.0. I use only debian packages from official repository.

I got
2016/02/14 11:09:20 [alert] 30161#30161: *1388932 zero size buf in output t:0 r:0 f:0 0000000002387520 0000000002387520-0000000002389356 0000000000000000 0-0 while sending to client, client: HIDDENIPV4, server: e6.mysite.com, request: "GET /place1/stream/cam13_low-5743015560.ts HTTP/1.1", upstream: "​https://[HIDDENIPV6]:443/place1/video/cam13_low-5743015560.ts", host: "e6.mysite.com", referrer: "​https://mysite.com/"
2016/02/14 11:09:23 [alert] 30160#30160: *1389653 zero size buf in output t:0 r:0 f:0 00000000022BBC50 00000000022BBC50-00000000022BF185 0000000000000000 0-0 while sending to client, client: HIDDENIPV4, server: e6.mysite.com, request: "GET /place1/stream/cam13_hi-5297110020.ts HTTP/1.1", upstream: "​https://HIDDENIPV4:443/place1/video/cam13_hi-5297110020.ts", host: "e6.mysite.com", referrer: "​https://mysite.com/"
in my logs.

I think it's because of
proxy_cache_use_stale updating;
proxy_cache_lock on;

More information, configs and debug log are here: ​https://forum.nginx.org/read.php?21,264561

I also try to attach debug.log here.

[Ivan]

Can't attach debug log. So it's here:

[Ivan]

​https://kinetiksoft.com/thecloud/index.php/s/5ldvsZFiC2NjpXJ

[Maxim Dounin]

Please try the following patch:

# HG changeset patch
# User Maxim Dounin <mdounin@mdounin.ru>
# Date 1457105784 -10800
#      Fri Mar 04 18:36:24 2016 +0300
# Node ID 36a4f55e09d6910f79507635b6e5a773e487fa08
# Parent  c5f81dcf97a79576138917501c9a6cc6f53ee930
Upstream: fixed "zero size buf" alerts with cache (ticket #918).

If caching was used, "zero size buf in output" alerts might appear
in logs if a client prematurely closed connection.  Alerts appeared
in the following situation:

- writing to client returned an error, so event pipe
  drained all busy buffers leaving body output filters
  in an invalid state;

- when upstream response was fully received,
  ngx_http_upstream_finalize_request() tried to flush
  all pending data.

Fix is to avoid flushing body if c->error is set.

diff --git a/src/http/ngx_http_upstream.c b/src/http/ngx_http_upstream.c
--- a/src/http/ngx_http_upstream.c
+++ b/src/http/ngx_http_upstream.c
@@ -4068,7 +4068,8 @@ ngx_http_upstream_finalize_request(ngx_h
 
     if (!u->header_sent
         || rc == NGX_HTTP_REQUEST_TIME_OUT
-        || rc == NGX_HTTP_CLIENT_CLOSED_REQUEST)
+        || rc == NGX_HTTP_CLIENT_CLOSED_REQUEST
+        || r->connection->error)
     {
         ngx_http_finalize_request(r, rc);
         return;

[Maxim Dounin]

Slightly improved patch:

# HG changeset patch
# User Maxim Dounin <mdounin@mdounin.ru>
# Date 1457120458 -10800
#      Fri Mar 04 22:40:58 2016 +0300
# Node ID bace49b26a447d9b8de0347a7b75d470d5287ba8
# Parent  c5f81dcf97a79576138917501c9a6cc6f53ee930
Upstream: fixed "zero size buf" alerts with cache (ticket #918).

If caching was used, "zero size buf in output" alerts might appear
in logs if a client prematurely closed connection.  Alerts appeared
in the following situation:

- writing to client returned an error, so event pipe
  drained all busy buffers leaving body output filters
  in an invalid state;

- when upstream response was fully received,
  ngx_http_upstream_finalize_request() tried to flush
  all pending data.

Fix is to avoid flushing body if p->downstream_error is set.

diff --git a/src/http/ngx_http_upstream.c b/src/http/ngx_http_upstream.c
--- a/src/http/ngx_http_upstream.c
+++ b/src/http/ngx_http_upstream.c
@@ -4068,7 +4068,8 @@ ngx_http_upstream_finalize_request(ngx_h
 
     if (!u->header_sent
         || rc == NGX_HTTP_REQUEST_TIME_OUT
-        || rc == NGX_HTTP_CLIENT_CLOSED_REQUEST)
+        || rc == NGX_HTTP_CLIENT_CLOSED_REQUEST
+        || (u->pipe && u->pipe->downstream_error))
     {
         ngx_http_finalize_request(r, rc);
         return;

[Ivan]

Maxim, thank you! I've just applied the last patch on one of our productions server. Will wait for few days to check if the issue will be repeated.

[creativeprogramming@…]

i'm experiencing the same with fastcgi_cache

I'm trying to apply the patch now hoping it will address also fastcgi_cache.

[creativeprogramming@…]

No luck, that doesn't fix it when using fastcgi_cache

[Maxim Dounin]

As long as you are seeing the same problem, there is no difference if proxy_cache or fastcgi_cache is used. If the patch doesn't work for you - you are probably seeing a different problem (or you've failed to apply the patch properly).

[Ivan]

Seems to fix the bug for me. No zero buf errors for two days on the server with nginx 1.9.12 with the patch. While on the server with nginx 1.8.1 without the patch I get near 10 errors a day.

Maxim, will the patch be backported to 1.8.* branch?

[Maxim Dounin]

Thanks for testing, appreciated.

Backporting to 1.8.x is unlikely because the problem isn't critical (the alert is the only bad thing that happens) and 1.10.x stable branch is expected to appear soon.

[creativeprogramming@…]

Yes I'm probably experiencing a different issue (I'm sure i recompiled nginx with right patch, anyway i applied it to 1.9.4 not master)

I'm sure I applied the same condiction to the if block

     if (!u->header_sent
         || rc == NGX_HTTP_REQUEST_TIME_OUT
        || rc == NGX_HTTP_CLIENT_CLOSED_REQUEST)
        || rc == NGX_HTTP_CLIENT_CLOSED_REQUEST
        || (u->pipe && u->pipe->downstream_error))

And that i recompiled and installed well...

Anyway this is the issue I got:

2016/03/10 13:05:44 [alert] 4855#4855: *3220 zero size buf in output t:0 r:0 f:1 0000000000000000 0000000000000000-0000000000000000 00000000038C1650 0-0 while sending request to upstream, client: 87.7.159.190, server: myhost.it, request: "GET /my/path/1002 HTTP/1.1", upstream: "fastcgi://127.0.0.1:9000", host: "myhost.it", referrer: "http://m.facebook.com/"
2016/03/10 13:05:44 [error] 4855#4855: *3220 recv() failed (104: Connection reset by peer) while reading response header from upstream, client: 87.7.159.190, server: myhost.it, request: "GET /my/path/1002 HTTP/1.1", upstream: "fastcgi://127.0.0.1:9000", host: "myhost.it", referrer: "http://m.facebook.com/"
2016/03/10 13:05:44 [alert] 4855#4855: *3220 zero size buf in output t:0 r:0 f:1 0000000000000000 0000000000000000-0000000000000000 00000000038C1650 0-0 while sending request to upstream, client: 87.7.159.190, server: myhost.it, request: "GET /my/path/1002 HTTP/1.1", upstream: "fastcgi://unix:/var/run/fallback-php-fpm-unix.sock:", host: "myhost.it", referrer: "http://m.facebook.com/"

Note: I'm using HHVM php at localhost:9000 with fallback (error_page 502 @fallback... location) to php5-fpm to the unix socket.

The url is working when i try to open with my browser but it seems i get this error with some clients

nginx -V
nginx version: nginx/1.9.4
built by gcc 4.9.2 (Ubuntu 4.9.2-10ubuntu13)
built with OpenSSL 1.0.2e 3 Dec 2015
TLS SNI support enabled
configure arguments: --with-http_realip_module --with-file-aio --with-threads --with-google_perftools_module --with-pcre --with-pcre-jit --with-ld-opt='-Wl,-z,relro -Wl,-E' --with-cc-opt='-D FD_SETSIZE=40048 -O2 -g -pipe -Wall -Wp,-D_FORTIFY_SOURCE=2 -fexceptions -fstack-protector-strong --param=ssp-buffer-size=4 -grecord-gcc-switches -m64 -mtune=generic -DTCP_FASTOPEN=23' --with-http_stub_status_module --with-http_spdy_module --with-http_ssl_module --prefix=/usr/local/nginx-pagespeed --sbin-path=/usr/local/nginx-pagespeed/nginx --conf-path=/etc/nginx/nginx.conf --pid-path=/var/run/nginx.pid --add-module=/root/nginx-source/ngx_pagespeed-release-1.10.33.5-beta/ --add-module=/root/nginx-source/ngx_cache_purge/ngx_cache_purge/ --add-module= --add-module= --with-http_gzip_static_module --error-log-path=/var/log/nginx/error.log --http-log-path=/var/log/nginx/access.log --with-http_sub_module


uname -a
Linux xxxxx 3.19.0-51-generic #58-Ubuntu SMP Fri Feb 26 21:22:26 UTC 2016 x86_64 x86_64 x86_64 GNU/Linux

[Maxim Dounin]

Replying to creativeprogramming@…:

Anyway this is the issue I got:

2016/03/10 13:05:44 [alert] 4855#4855: *3220 zero size buf in output t:0 r:0 f:1 0000000000000000 0000000000000000-0000000000000000 00000000038C1650 0-0 while sending request to upstream, client: 87.7.159.190, server: myhost.it, request: "GET /my/path/1002 HTTP/1.1", upstream: "fastcgi://127.0.0.1:9000", host: "myhost.it", referrer: "http://m.facebook.com/"
2016/03/10 13:05:44 [error] 4855#4855: *3220 recv() failed (104: Connection reset by peer) while reading response header from upstream, client: 87.7.159.190, server: myhost.it, request: "GET /my/path/1002 HTTP/1.1", upstream: "fastcgi://127.0.0.1:9000", host: "myhost.it", referrer: "http://m.facebook.com/"
2016/03/10 13:05:44 [alert] 4855#4855: *3220 zero size buf in output t:0 r:0 f:1 0000000000000000 0000000000000000-0000000000000000 00000000038C1650 0-0 while sending request to upstream, client: 87.7.159.190, server: myhost.it, request: "GET /my/path/1002 HTTP/1.1", upstream: "fastcgi://unix:/var/run/fallback-php-fpm-unix.sock:", host: "myhost.it", referrer: "http://m.facebook.com/"

This certainly is a different issue, as it's "... while sending request to upstream". Similar messages are known to appear when using HTTP/2 (and likely SPDY in old versions), see ticket #907.

[creativeprogramming@…]

yes i'm using SPDY (and i get the same also if i upgrade to 1.9.9 for HTTP/2. Thank you for referencing the other ticket i'll not write anymore in this one.

Regards

[Maxim Dounin <mdounin@…>]

In 6427:ad3f342f14ba/nginx:

Upstream: fixed "zero size buf" alerts with cache (ticket #918).

If caching was used, "zero size buf in output" alerts might appear
in logs if a client prematurely closed connection. Alerts appeared
in the following situation:

• writing to client returned an error, so event pipe drained all busy buffers leaving body output filters in an invalid state;

• when upstream response was fully received, ngx_http_upstream_finalize_request() tried to flush all pending data.

Fix is to avoid flushing body if p->downstream_error is set.

[Maxim Dounin]

Fix committed.