Opened 3 years ago

Closed 2 years ago

#428 closed defect (fixed)

SPDY and Proxy Cache prematurely closes connections

Reported by: philcollect@… Owned by: vbart
Priority: major Milestone:
Component: nginx-core Version:
Keywords: spdy proxy cache Cc:
Sensitive: no
uname -a: Linux myserver 3.8.0-31-generic #46~precise1-Ubuntu SMP Wed Sep 11 18:21:16 UTC 2013 x86_64 x86_64 x86_64 GNU/Linux
nginx -V: nginx version: nginx/1.5.6 TLS SNI support enabled configure arguments: --prefix=/etc/nginx --sbin-path=/usr/sbin/nginx --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-http_ssl_module --with-http_realip_module --with-http_addition_module --with-http_sub_module --with-http_dav_module --with-http_flv_module --with-http_mp4_module --with-http_gunzip_module --with-http_gzip_static_module --with-http_random_index_module --with-http_secure_link_module --with-http_stub_status_module --with-http_auth_request_module --with-mail --with-mail_ssl_module --with-file-aio --with-http_spdy_module --with-cc-opt='-g -O2 -fstack-protector --param=ssp-buffer-size=4 -Wformat -Wformat-security -Werror=format-security -Wp,-D_FORTIFY_SOURCE=2' --with-ld-opt='-Wl,-Bsymbolic-functions -Wl,-z,relro' --with-ipv6

Description

As originally reported via mailing list/forum (a while ago):
http://forum.nginx.org/read.php?2,233497,241193#msg-241193

When SPDY and proxy cache are both being used, nginx will prematurely close the connection to avoid sending the body to the client. However with SPDY, there could be other items still to send, so this causes empty responses. In my case, css/js/images come back empty to the browser occasionally.

Debug logs have been provided to Valentin V. Bartenev, who stated in April:

"Well, from what I've examined from your debug logs, it looks like a known feature of caching mechanism, that closes connection to prevent sending body to a client, while the whole response is receiving from upstream. It's not a big deal in http, but turns into serious issue with spdy."

"The problem appears when the whole page is requested from upstream for caching purposes, but the client should not get its body (i.e. 304 response, or HEAD request)."

Didn't originally file a ticket here because Valentin hoped that rewrites going on at the time for the upstream code might fix this, but looks like it did not.

Change History (11)

comment:1 Changed 3 years ago by vbart

  • Owner set to vbart
  • Status changed from new to assigned

comment:2 Changed 2 years ago by vbart

This patch should fix the problem:

  • src/http/ngx_http_upstream.c

    diff -r 01e2a5bcdd8f src/http/ngx_http_upstream.c
    a b static void 
    6666static void
    6767    ngx_http_upstream_process_non_buffered_request(ngx_http_request_t *r,
    6868    ngx_uint_t do_write);
     69static ngx_int_t ngx_http_upstream_output_filter(ngx_http_request_t *r,
     70    ngx_chain_t *in);
    6971static ngx_int_t ngx_http_upstream_non_buffered_filter_init(void *data);
    7072static ngx_int_t ngx_http_upstream_non_buffered_filter(void *data,
    7173    ssize_t bytes);
    ngx_http_upstream_send_response(ngx_http 
    22162218
    22172219    c = r->connection;
    22182220
    2219     if (r->header_only) {
    2220 
    2221         if (u->cacheable || u->store) {
    2222 
    2223             if (ngx_shutdown_socket(c->fd, NGX_WRITE_SHUTDOWN) == -1) {
    2224                 ngx_connection_error(c, ngx_socket_errno,
    2225                                      ngx_shutdown_socket_n " failed");
    2226             }
    2227 
    2228             r->read_event_handler = ngx_http_request_empty_handler;
    2229             r->write_event_handler = ngx_http_request_empty_handler;
    2230             c->error = 1;
    2231 
    2232         } else {
    2233             ngx_http_upstream_finalize_request(r, u, rc);
    2234             return;
    2235         }
     2221    if (r->header_only && !(u->cacheable || u->store)) {
     2222        ngx_http_upstream_finalize_request(r, u, rc);
     2223        return;
    22362224    }
    22372225
    22382226    if (r->request_body && r->request_body->temp_file) {
    ngx_http_upstream_send_response(ngx_http 
    23842372
    23852373    p = u->pipe;
    23862374
    2387     p->output_filter = (ngx_event_pipe_output_filter_pt) ngx_http_output_filter;
     2375    p->output_filter =
     2376        (ngx_event_pipe_output_filter_pt) ngx_http_upstream_output_filter;
     2377
    23882378    p->output_ctx = r;
    23892379    p->tag = u->output.tag;
    23902380    p->bufs = u->conf->bufs;
    ngx_http_upstream_process_non_buffered_r 
    28432833        if (do_write) {
    28442834
    28452835            if (u->out_bufs || u->busy_bufs) {
    2846                 rc = ngx_http_output_filter(r, u->out_bufs);
     2836                rc = ngx_http_upstream_output_filter(r, u->out_bufs);
    28472837
    28482838                if (rc == NGX_ERROR) {
    28492839                    ngx_http_upstream_finalize_request(r, u, NGX_ERROR);
    ngx_http_upstream_process_non_buffered_r 
    29432933
    29442934
    29452935static ngx_int_t
     2936ngx_http_upstream_output_filter(ngx_http_request_t *r, ngx_chain_t *in)
     2937{
     2938
     2939    if (!r->header_only) {
     2940        return ngx_http_output_filter(r, in);
     2941    }
     2942
     2943    while (in) {
     2944        in->buf->pos = in->buf->last;
     2945        in = in->next;
     2946    }
     2947
     2948    return NGX_OK;
     2949}
     2950
     2951
     2952static ngx_int_t
    29462953ngx_http_upstream_non_buffered_filter_init(void *data)
    29472954{
    29482955    return NGX_OK;

Feel free to use it.

comment:3 follow-up: Changed 2 years ago by philcollect@…

Thanks for that. I have tried it against 1.5.10 and it does appear to solve the issue!

Do you expect to apply this to mainline or does it require further work before that?

comment:4 in reply to: ↑ 3 Changed 2 years ago by vbart

Replying to Phil Sweeney <philcollect@gmail.com>:

Do you expect to apply this to mainline or does it require further work before that?

Yes, it needs more work. But not because it does something wrong, the patch is correct and shouldn't introduce any bugs. Just the way it solves the problem hasn't been liked by colleagues.

comment:5 Changed 2 years ago by iloginx@…

This bug makes me 3 days to investigate and search for solution to use SPDY with proxy cache.
The issue occurs if use

proxy_cache_bypass $no_cache;

or cached items deleted on server while use F5 in browsers. Only the first request is response (GET 304 status) and error with subsequent requests.
No problem if I remove SPDY.

I tested the patch of Valentin V. Bartenev on 1.5.10 and it work for me.
Thanks.

Update: Sorry, but today I got an error in Chrome 33 Dev tool when I post several wordpress comments:
net::ERR_SPDY_PROTOCOL_ERROR.

Last edited 2 years ago by iloginx@… (previous) (diff)

comment:6 follow-up: Changed 2 years ago by sedaj2@…

Hello,

it this problem fixed in 1.5.13?

comment:7 in reply to: ↑ 6 Changed 2 years ago by vbart

Replying to www.google.com/accounts/o8/id?id=AItOawlDriEnv-y6Xg9DA3Xg0k8r-h-p-wHri4w:

it this problem fixed in 1.5.13?

No. The patch above is still relevant.

comment:8 follow-up: Changed 2 years ago by lazy.dogtown@…

hi,

is the vuln and the patch valid for the stable 1.4.7 too?

brad

comment:9 in reply to: ↑ 8 Changed 2 years ago by vbart

The issue and the patch valid for 1.4.x branch too.

comment:10 Changed 2 years ago by stanojr@…

Patch work also for 1.6.
If it is not yet fixed information should be in documentation or somewhere.

I encountered also second problem with this issue. With limit_conn it looks like connections are not decreased when they are prematurely closed. So you can see in log that connections are limited on spdy but they are not over limit.

comment:11 Changed 2 years ago by mdounin

  • Resolution set to fixed
  • Status changed from assigned to closed

Fixed by 35990c69b3ac.

Note: See TracTickets for help on using tickets.