Writing connection leak while SPDY enabled

[Marcus Maciel]

I'm trying to use SPDY module, but when I enable this into my config

listen 443 ssl spdy;

The number of Writing connections start to leak.

[Marcus Maciel]

As you can see on attached file Writing connection still leaking until restart nginx without spdy option

[Valentin V. Bartenev]

Could you provide the full config? Is there anything in the error log?

[Marcus Maciel]

nginx.conf

root@php01:/etc/nginx# cat nginx.conf
user www-data;
worker_processes  auto;

error_log  /srv/log/nginx/error.log;
pid        /var/run/nginx.pid;

events {
	multi_accept on;
    	worker_connections 1024;
	use epoll;
}

http {
	include       /etc/nginx/mime.types;
	default_type  application/octet-stream;
	access_log	/srv/log/nginx/access.log;

        ssl_session_cache    shared:SSL:10m;
        ssl_session_timeout  10m;
        ssl_ciphers ALL:!kEDH!ADH:RC4+RSA:+HIGH:+MEDIUM:+LOW:+SSLv2:+EXP;


       # Custom logging
        log_format custom '$remote_addr - $remote_user [$time_local]  '
                    '"$request" $status $body_bytes_sent '
                    '"$http_referer" "$http_user_agent" CACHE:$upstream_cache_status RESPONSE:$upstream_response_time';

	
	fastcgi_cache_path /srv/cache/nginx levels=1:2 keys_zone=underlinux:512m inactive=30m max_size=1024m;
	fastcgi_buffer_size   8192k;
        fastcgi_buffers   4 8192k;
        fastcgi_busy_buffers_size   8192k;
	sendfile       on;
	tcp_nopush     on;
	tcp_nodelay off;
	client_body_buffer_size 8192k;
	client_max_body_size 500m;
	fastcgi_send_timeout 300;
	fastcgi_read_timeout 300;
	keepalive_timeout 15 15;
	keepalive_requests 100;
	ignore_invalid_headers on;

	gzip  on;
	gzip_comp_level 9;
	gzip_types		text/plain text/css text/javascript text/xml application/x-javascript application/xml application/xml+rss;
	gzip_buffers   64 8k;
	gzip_http_version 1.0;
	gzip_min_length  1100;
	gzip_proxied any;
	gzip_vary on;
	server_tokens off;

#	include /etc/nginx/conf.d/*.conf;
	include /etc/nginx/sites-enabled/*;
}

root@php01:/etc/nginx# 


root@php01:/etc/nginx/sites-enabled# cat under-linux.org.conf 
server {
	listen 80;
	access_log   off;
	server_name *.under-linux.org underlinux.com.br *.underlinux.com.br under-linux.net *.under-linux.net underlinux.net *.underlinux.net underlinux.org *.underlinux.org under-linux.org;

	rewrite /forums/(.*)/(\d+)-(.*).html https://under-linux.org/showthread.php?t=$2 permanent;
        rewrite /noticias/(.*)-(\d+) https://under-linux.org/content.php?r=$2 permanent;
        rewrite /forums/(.*)-(\d+) https://under-linux.org/showthread.php?t=$2 permanent;
        rewrite /blogs/(.*)/(.*)-(\d+) https://under-linux.org/entry.php?b=$3 permanent;
        rewrite /f(\d+)/(.*)-(\d+)/(.*) https://under-linux.org/showthread.php?t=$3 permanent;
        rewrite /f(\d+)/(.*)-(\d+) https://under-linux.org/showthread.php?t=$3 permanent;
        rewrite /f(\d+)-(.*)/(.*) https://under-linux.org/showthread.php?t=$1 permanent;
        rewrite /f(\d+)-(.*) https://under-linux.org/showthread.php?t=$1 permanent;
        rewrite /content/(.*)-(\d+) https://under-linux.org/content.php?r=$2 permanent;
        rewrite /b(\d+)-(.*) https://under-linux.org/entry.php?b=$1 permanent;
	rewrite /(.*)-(\d+)/(.*)-(\d+) https://under-linux.org/showthread.php?t=$4 permanent;
	rewrite /(.*)-(\d+) https://under-linux.org/content.php?r=$2 permanent;
	rewrite /forums/(\d+)-(.*) https://under-linux.org/showthread.php?t=$1 permanent;
	rewrite ^	https://under-linux.org$request_uri? permanent;
}
server {
	index index.php index.html;
	server_name under-linux.org;
	#ssl		on;
    	listen              443 ssl;
	ssl_certificate     under-linux.org.chained.crt;
	ssl_certificate_key underlinux.key;

	access_log /srv/log/nginx/underlinux-nginx-access.log custom;
	error_log /srv/log/nginx/underlinux-nginx-error.log notice;
	root /srv/www/01/under-linux.org/public_html;

	rewrite /noticias/(.*)-(\d+) /content.php?r=$2 permanent;
	rewrite /forums/(.*)-(\d+) /showthread.php?t=$2 permanent;
	rewrite	/blogs/(.*)/(.*)-(\d+) /entry.php?b=$3 permanent;
	rewrite /f(\d+)/(.*)-(\d+)/(.*) /showthread.php?t=$3 permanent;
	rewrite /f(\d+)/(.*)-(\d+) /showthread.php?t=$3 permanent;
	rewrite /f(\d+)-(.*)/(.*) /showthread.php?t=$1 permanent;	
	rewrite /f(\d+)-(.*) /showthread.php?t=$1 permanent;
	rewrite /content/(.*)-(\d+) /content.php?r=$2 permanent;
	rewrite /b(\d+)-(.*) /entry.php?b=$1 permanent;

        location = /robots.txt {
                expires       -24h;
        }


    location ~ /paineladmin/ {
       		auth_basic "Hello, Please login";
       		auth_basic_user_file /etc/nginx/underpass;
        location ~ \.php$ {
                fastcgi_pass  127.0.0.1:9000;
                fastcgi_index index.php;
                fastcgi_param SCRIPT_FILENAME $document_root$fastcgi_script_name;
                include fastcgi_params;
        }


    }



    location ~ /forumrunner/ {
        location ~ \.php$ {
                fastcgi_pass  127.0.0.1:9000;
                fastcgi_index index.php;
                fastcgi_param SCRIPT_FILENAME $document_root$fastcgi_script_name;
                include fastcgi_params;
        }
    }

rewrite ^/((urllist|sitemap).*\.(xml|txt)(\.gz)?)$ /vbseo_sitemap/vbseo_getsitemap.php?sitemap=$1 last;

#Inicio set nocache var
		set $nocache "";
		if ($http_cookie ~ (bb_userid|bb_imloggedin|vbseo_loggedin)) {
		  set $nocache "Y";
		}

             if ($request_uri ~ "(.*)(cron\.php|ajax\.php|search\.php|image\.php|login\.php|register\.php|usercp\.php|private\.php|sendmessage\.php|faleconosco|vbseo-xmlrpc|profile\.php|forumrunner\/|paineladmin\/)(.*)") {
		set $nocache "Y";                
		}

#
             if ($request_uri ~ "(.*)(attachment\.php|attachments\/)(.*)") {
                set $nocache "";
                }
#end of nocache

	# We don't want to allow the browsers to see .hidden linux/unix files
	location ~ /\. { deny  all; access_log off; log_not_found off; }

	location ~* \.(js|bmp|pdf|swf|css|jpg|jpeg|gif|png|ico)$ {
		access_log   off;
                add_header Pragma public;
                add_header Cache-Control "public, must-revalidate, proxy-revalidate";
		expires      max;
	}

        location = /activity.php {
                fastcgi_pass  127.0.0.1:9000;
                fastcgi_index index.php;
                fastcgi_param SCRIPT_FILENAME $document_root$fastcgi_script_name;
                include fastcgi_params;
        }

        location = /thanks.php {
                fastcgi_pass  127.0.0.1:9000;
                fastcgi_index index.php;
                fastcgi_param SCRIPT_FILENAME $document_root$fastcgi_script_name;
                include fastcgi_params;
        }

	location = /attachment.php {
		access_log   off;
                fastcgi_pass  127.0.0.1:9000;
                fastcgi_index index.php;
                fastcgi_param SCRIPT_FILENAME $document_root$fastcgi_script_name;
                include fastcgi_params;
                add_header Pragma public;
                add_header Cache-Control "public, must-revalidate, proxy-revalidate";
                expires      max;
                #novas configs de cache
                fastcgi_ignore_headers Cache-Control Expires Set-Cookie;
                fastcgi_hide_header Set-Cookie;
                fastcgi_cache_valid   200 302  5m;
                fastcgi_cache_valid   301      5m;
                fastcgi_cache_valid   any      1m;
                fastcgi_cache_min_uses  1;
                fastcgi_cache_use_stale error  timeout invalid_header http_500 http_503;
                fastcgi_cache underlinux;
                fastcgi_cache_key $request_method$request_uri$cookie_bb_userid$cookie_bb_imloggedin;
                #end of cache part

        }



location / {

	error_page     404 = @fixcms;

        location ~ \.php$ {
         	if ($nocache !~ "Y") {
                	return 404;
           	}
        	error_page     404 = @cache;
		fastcgi_pass  127.0.0.1:9000;
		fastcgi_index index.php;
                fastcgi_param SCRIPT_FILENAME $document_root$fastcgi_script_name;
                include fastcgi_params;
        }

}
	location @fixcms {
		rewrite /(.*)-(\d+) /content.php?r=$2 permanent;	
	}

        location @cache {
                #novas configs de cache
                fastcgi_ignore_headers Cache-Control Expires Set-Cookie;
		fastcgi_hide_header Set-Cookie;
                fastcgi_no_cache $nocache;
                fastcgi_cache_bypass $nocache;
                fastcgi_cache_valid   200 302  5m;
                fastcgi_cache_valid   301      5m;
                fastcgi_cache_valid   any      1m;
                fastcgi_cache_min_uses  1;
                fastcgi_cache_use_stale error  timeout invalid_header http_500 http_503;
                fastcgi_cache underlinux;
                fastcgi_cache_key $request_method$request_uri$cookie_bb_userid$cookie_bb_imloggedin;
                #end of cache part
                fastcgi_pass  127.0.0.1:9000;
                fastcgi_index index.php;
                fastcgi_param SCRIPT_FILENAME $document_root$fastcgi_script_name;
                include fastcgi_params;
        }

        location @fastcache {
                #novas configs de cache
                fastcgi_ignore_headers Cache-Control Expires Set-Cookie;
                fastcgi_hide_header Set-Cookie;
                fastcgi_no_cache $nocache;
                fastcgi_cache_bypass $nocache;
                fastcgi_cache_valid   200 302  5m;
                fastcgi_cache_valid   301      5m;
                fastcgi_cache_valid   any      1m;
                fastcgi_cache_min_uses  1;
                fastcgi_cache_use_stale error  timeout invalid_header http_500 http_503;
                fastcgi_cache underlinux;
                fastcgi_cache_key $request_method$request_uri$cookie_bb_userid$cookie_bb_imloggedin;
                #end of cache part
                fastcgi_pass  127.0.0.1:9000;
                fastcgi_index index.php;
                fastcgi_param SCRIPT_FILENAME $document_root$fastcgi_script_name;
                include fastcgi_params;
        }

}

[Marcus Maciel]

Hello Valentin,

Let me know if you need any other information to help me on this bug.

Thanks,

[Marcus Maciel]

any update ???

[Christopher O'Connell]

I can confirm this happening in 1.4.0 with a substantially similar configuration to that already posted. Please let me know if there's any help I can provide in testing with current code or proposed patches.

[Valentin V. Bartenev]

Investigation of the issue will take some time. It seems that the problem only appears on certain configurations under some conditions. There is also a known incompatibility with spdy and caching enabled, but it should not cause such leaks.

[Christopher O'Connell]

Replying to Valentin V. Bartenev:

Investigation of the issue will take some time. It seems that the problem only appears on certain configurations under some conditions. There is also a known incompatibility with spdy and caching enabled, but it should not cause such leaks.

Can you provide any guidance on what configuration commands or values produce the leaks?

[Danny Lockard]

I am also seeing a steady upward trend of open "writing" connections in my nginx status. We have a similar, less complex configuration.

server {
  listen IP:80;
  rewrite ^(.*) https://site$request_uri? permanent;
}

server {
  listen IP:443 ssl spdy;

    if ($host ~* www\.(.*)) {
      rewrite ^(.*) https://site$request_uri? permanent;
    }

  ssl_certificate /etc/nginx/ssl/site.crt ;
  ssl_certificate_key /etc/nginx/ssl/site.key;

  client_max_body_size 64M;

  access_log /var/log/nginx/site.access.log;

  location /nginx_status {
    stub_status on;
    access_log   off;
    allow 127.0.0.1;
    deny all;
  }

  location / {
    proxy_pass http://site-backend;
    proxy_set_header X-Real-IP  $remote_addr;
    proxy_set_header Host $host;
    location ~* \.(png|jpg|jpeg|gif|ico|bmp|swf)$ {
      expires 48h;
      log_not_found off;
      proxy_pass http://site-backend;    
      proxy_set_header X-Real-IP  $remote_addr;
      proxy_set_header Host $host;
      add_header Cache-Control public;
    }

    location ~* \.(js|css)$ {
      expires 24h;
      log_not_found off;
      proxy_pass http://site-backend;    
      proxy_set_header X-Real-IP  $remote_addr;
      proxy_set_header Host $host;
      add_header Cache-Control public;
    }

    location ~* \.(html|htm|xml)$ {
      expires 1h;
      log_not_found off;
      proxy_pass http://site-backend;
      proxy_set_header X-Real-IP  $remote_addr;
      proxy_set_header Host $host;
    }

    location /assets/files/ {
      expires 4000h;
      log_not_found off;
      proxy_pass http://site-backend;
      proxy_set_header X-Real-IP  $remote_addr;
      proxy_set_header Host $host;
      add_header Cache-Control public;
    }

    location /assets/content/ {
      expires 4000h;
      log_not_found off;
      proxy_pass http://site-backend;
      proxy_set_header X-Real-IP  $remote_addr;
      proxy_set_header Host $host;
      add_header Cache-Control public;
    }

    location /assets/ {
      expires 48h;
      log_not_found off;
      proxy_pass http://site-backend;
      proxy_set_header X-Real-IP  $remote_addr;
      proxy_set_header Host $host;
    }
  }

  location /externalmedia {
    proxy_pass http://static-storage:80;
    proxy_set_header X-Real-IP  $remote_addr;
    proxy_set_header Host $host;
  }
}

[Marcus Maciel]

Just using nginx as proxy enabling spdy I have same issue so I think this is a Major issue and not a minor issue like was reclassified .... Since in my understand when nginx reach limit of writting connections will stop to accept new connections right ?

[Marcus Maciel]

writting connections leak with nginx configured as a proxy when spdy is enabled....

[Valentin V. Bartenev]

Am I right that you all have nothing in your error logs?

Replying to Marcus Maciel <mmaciel@gmail.com>:

Since in my understand when nginx reach limit of writting connections will stop to accept new connections right ?

Not quite exactly. It just a counter in the stub status module that can be in a wrong state, and in case of spdy it does not correspond with real connections.

[Marcus Maciel]

I could not find anything on error logs... this should happen in any installation with spdy apparently.

[Christopher O'Connell]

I examined 2 machines exhibiting the problem in the status module and neither showed any unexpected errors in the error logs.

Thanks for clarifying that this is just an invalid counter and not a bug in the SSL implementation.

[Valentin V. Bartenev]

I actually just explained that the growth of "writing" counter may not mean literally leaking of connections. But since I still cannot reproduce the issue even using similar configs I can only guess what's wrong.

If somebody would be able to reduce its case to something simple and reproducible form scratch, then it will help a lot.

[Marcus Maciel]

Valentin, it actually take sometime to start the leak and in a lab environment without too many connections you probably will never see this issue.

You will need some good traffic running for some time to start to see this leak...

[Edward Ackroyd]

I can also reproduce this in 1.4.2: "Active connections" and "Writing" too high. This server has little traffic (used to have lots):

Active connections: 1110 
server accepts handled requests
 220221922 220221922 169671639 
Reading: 0 Writing: 1759 Waiting: 5

However, there are by no means that many "Active connections":

# netstat -n | egrep "tcp.*:(443|80) " | grep -o "[A-Z_]*" | sort | uniq -c
    222 ESTABLISHED
      8 TIME_WAIT

Eventually "Active connections" reaches worker_connections*worker_processes max and no more "Active connections" available.

Steps to reproduce: Set up nginx with SPDY, make lots of requests (from lots of different clients) (stop the traffic and see that Active connections and Writing never go down).

Here is my nginx.conf:

pid	nginx.pid;

worker_processes  6;

events {
    worker_connections  1024;
}

http {	
	keepalive_timeout 10s;
                    
	upstream up {
		server localhost:8080;
		keepalive 150;
	}
	
	server {
		listen 443 ssl spdy default_server;
		ssl_certificate      X.crt;
		ssl_certificate_key  X.pem;

		charset utf-8;

		location / {
			proxy_pass			http://up;
			proxy_http_version	1.1;
			proxy_set_header	Connection "";
			proxy_redirect		http:// https://;
			proxy_set_header	Host $host;
			proxy_set_header	X-IP $remote_addr;
		}
		
		location /nginx_status {
			stub_status on;
			access_log   off;
		}
	}
	
	
	server {
		listen 80;

		charset utf-8;

		location / {
			proxy_pass			http://up;
			proxy_http_version	1.1;
			proxy_set_header	Connection "";
			proxy_set_header	Host $host;
			proxy_set_header	X-IP $remote_addr;
		}
	}
}

[Valentin V. Bartenev]

It seems I found one case that can lead to such leaks. Could you test the patch below?

src/http/ngx_http_spdy.c

@@ -1814 +1814 @@
 
     rev->data = fc;
     rev->ready = 1;
-    rev->handler = ngx_http_empty_handler;
+    rev->handler = ngx_http_test_reading;
     rev->log = log;
 
     ngx_memcpy(wev, rev, sizeof(ngx_event_t));
 
     wev->write = 1;
+    wev->handler = ngx_http_empty_handler;
 
     ngx_memcpy(fc, sc->connection, sizeof(ngx_connection_t));
 

It is for 1.4.2, but for the other versions it should be applied well with a little offset. So anyone who has encounter this problem feel free to try the fix.

[Edward Ackroyd]

The patch does not compile:

src/http/ngx_http_spdy.c: In function ‘ngx_http_spdy_create_stream’:
src/http/ngx_http_spdy.c:1817:18: error: assignment from incompatible pointer type [-Werror]

changed code block after patch:

    rev->data = fc;
    rev->ready = 1;
    rev->handler = ngx_http_test_reading;
    rev->log = log;

    ngx_memcpy(wev, rev, sizeof(ngx_event_t));

    wev->write = 1;
    wev->handler = ngx_http_empty_handler;

[Valentin V. Bartenev]

Oops, sorry, it's wrong patch indeed. Accidentally I've built nginx without the changes and then believed that it works.

Here is a new patch:

src/http/ngx_http_spdy.c

@@ -145 +145 @@
 static void ngx_http_spdy_run_request(ngx_http_request_t *r);
 static ngx_int_t ngx_http_spdy_init_request_body(ngx_http_request_t *r);
 
+static void ngx_http_spdy_close_stream_handler(ngx_event_t *ev);
+
 static void ngx_http_spdy_handle_connection_handler(ngx_event_t *rev);
 static void ngx_http_spdy_keepalive_handler(ngx_event_t *rev);
 static void ngx_http_spdy_finalize_connection(ngx_http_spdy_connection_t *sc,
@@ -1814 +1816 @@
 
     rev->data = fc;
     rev->ready = 1;
-    rev->handler = ngx_http_empty_handler;
+    rev->handler = ngx_http_spdy_close_stream_handler;
     rev->log = log;
 
     ngx_memcpy(wev, rev, sizeof(ngx_event_t));
@@ -1879 +1881 @@
 }
 
 
+static void
+ngx_http_spdy_close_stream_handler(ngx_event_t *ev)
+{
+    ngx_connection_t    *fc;
+    ngx_http_request_t  *r;
+
+    fc = ev->data;
+    r = fc->data;
+
+    ngx_log_debug0(NGX_LOG_DEBUG_HTTP, r->connection->log, 0,
+                   "spdy close stream handler");
+
+    ngx_http_spdy_close_stream(r->spdy_stream, 0);
+}
+
+
 static ngx_http_spdy_stream_t *
 ngx_http_spdy_get_stream_by_id(ngx_http_spdy_connection_t *sc,
     ngx_uint_t sid)
@@ -2805 +2823 @@
 
     c->error = 1;
     c->read->handler = ngx_http_empty_handler;
+    c->write->handler = ngx_http_empty_handler;
 
     sc->last_out = NULL;
 

[Edward Ackroyd]

Thanks Valentin. I have a server running the patched version, initial values look good. Will report back once a good amount of traffic has past through the server.

[Edward Ackroyd]

The patch does not fix the issue. Here is a dump of nginx_status and sockets used by nginx:

Active connections: 437
server accepts handled requests
 2504744 2504744 2418189
Reading: 0 Writing: 563 Waiting: 148

    203 CLOSE_WAIT
      2 CLOSING
    158 ESTABLISHED
      4 FIN_WAIT
     79 TIME_WAIT

"Active connections" is wrong, even if you count those in CLOSE_WAIT
"Writing" is wrong, can't be larger than Active connections
In fact I think the only correct value is "requests".

In addition, when nginx is configured to use SPDY and proxy_cache it leaks (does not close) sockets in a rate of about 100 for every million requests (see the 203 in CLOSE_WAIT above). Does not do this when configured without proxy_cache.

[Valentin V. Bartenev]

Replying to Edward Ackroyd <edward.ackroyd@gmail.com>:

"Writing" is wrong, can't be larger than Active connections

It looks like you misunderstand this counter. The "Writing" and "Reading" counters are about requests, not about connections. With SPDY you can have a lot of requests with "Writing" state in one connection, and this is exactly what SPDY is for.

So with SPDY Writing+Reading request counters can be several times larger than Active connections.

[Edward Ackroyd]

For "Writing", in what time frame does nginx count the requests? What does a value of 563 really mean?

Do you agree the value for "Active connections" is wrong?

[Valentin V. Bartenev]

Replying to Edward Ackroyd <edward.ackroyd@gmail.com>:

For "Writing", in what time frame does nginx count the requests? What does a value of 563 really mean?

Every request from start reading request headers till the end of reading request headers is counted as "Reading". All the rest of the processing of the request (including processing of upstream and reading request body) is counted in "Writing".

This may seem strange, but there are historical reasons for this, and it is one of the reasons why the module is called "stub status", and why it is not documented in the official documentation.

Do you agree the value for "Active connections" is wrong?

Yes, it looks like the problem still isn't fixed.

[Valentin V. Bartenev]

​http://mailman.nginx.org/pipermail/nginx-devel/2013-September/004204.html is relevant to the ticket.

A patch that can fix the problem:

src/http/ngx_http_spdy.c

@@ -1204 +1204 @@
         }
 
         if (rb->post_handler) {
+            r->read_event_handler = ngx_http_block_reading;
             rb->post_handler(r);
         }
     }
@@ -2604 +2605 @@
 
     r->request_body->post_handler = post_handler;
 
+    r->read_event_handler = ngx_http_test_reading;
+    r->write_event_handler = ngx_http_request_empty_handler;
+
     return NGX_AGAIN;
 }
 

[Valentin V. Bartenev]

The issue should be fixed by revision 4d0c70541784 (released in nginx 1.5.6).

[Marcus Maciel]

In my understanding this is not fixed.

I'm running 1.5.6 and I still have this problem.

[Marcus Maciel]

leak continues on 1.5.6

[Marcus Maciel]

I'm using the package from

deb ​http://nginx.org/packages/mainline/ubuntu/ precise nginx
deb-src ​http://nginx.org/packages/mainline/ubuntu/ precise nginx

[Valentin V. Bartenev]

Replying to Marcus Maciel <marcus@underlinux.com.br>:

In my understanding this is not fixed.

I'm running 1.5.6 and I still have this problem.

Could you provide ​debug log with leaking connections in 1.5.6?

P.S. If you use packages from our repository, then you can install nginx-debug.

[Valentin V. Bartenev]

A writing connection leak was fixed in a279d2a33dbf (will be released with 1.5.8).