cherrypy shutdown - sabnzbd still running

[bav]

Hello sabnzbd developers,

after many years of using sabnzbd/sabnzbd+ I'm experiencing a serious problem since a few days: The webserver is killed every few hours/days, but the sabnzbd process is still running!

Version: 0.6.14
OS: Ubuntu Oneiric Server
Install-type: python source (linux)
Skin (if applicable): Plush Gold
Firewall Software: None
Are you using IPV6? no
Is the issue reproducible? yes

The relevant log-lines look like:

Code: Select all

2012-03-06 09:34:52,386::ERROR::[_cplogging:55] [06/Mar/2012:09:34:52] ENGINE Error in HTTP server: shutting down
Traceback (most recent call last):
  File "/home/sabnzbd/cherrypy/process/servers.py", line 75, in _start_http_thread
  File "/home/sabnzbd/cherrypy/wsgiserver/__init__.py", line 1655, in start
    self.tick()
  File "/home/sabnzbd/cherrypy/wsgiserver/__init__.py", line 1703, in tick
    s, addr = self.socket.accept()
  File "<string>", line 4, in accept
  File "/home/sabnzbd/lib/python2.7/socket.py", line 202, in accept
error: [Errno 24] Too many open files

2012-03-06 09:34:52,419::INFO::[_cplogging:55] [06/Mar/2012:09:34:52] ENGINE Bus STOPPING
2012-03-06 09:34:52,447::INFO::[_cplogging:55] [06/Mar/2012:09:34:52] ENGINE HTTP Server cherrypy._cpwsgi_server.CPWSGIServer(('domain.name', sslport)) shut down
2012-03-06 09:34:52,467::ERROR::[_cplogging:55] [06/Mar/2012:09:34:52] ENGINE Error in HTTP server: shutting down
Traceback (most recent call last):
  File "/home/sabnzbd/cherrypy/process/servers.py", line 75, in _start_http_thread
    self.httpserver.start()
  File "/home/sabnzbd/cherrypy/wsgiserver/__init__.py", line 1655, in start
    self.tick()
  File "/home/sabnzbd/cherrypy/wsgiserver/__init__.py", line 1703, in tick
    s, addr = self.socket.accept()
  File "/home/sabnzbd/lib/python2.7/socket.py", line 202, in accept
    sock, addr = self._sock.accept()
error: [Errno 24] Too many open files

2012-03-06 09:34:52,468::INFO::[_cplogging:55] [06/Mar/2012:09:34:52] ENGINE Bus STOPPING
2012-03-06 09:34:52,468::INFO::[_cplogging:55] [06/Mar/2012:09:34:52] ENGINE HTTP Server cherrypy._cpwsgi_server.CPWSGIServer(('domain.name', sslport)) already shut down
2012-03-06 09:34:57,483::INFO::[_cplogging:55] [06/Mar/2012:09:34:57] ENGINE HTTP Server cherrypy._cpwsgi_server.CPWSGIServer(('domain.name', normalport)) shut down
2012-03-06 09:34:57,485::INFO::[_cplogging:55] [06/Mar/2012:09:34:57] ENGINE HTTP Server cherrypy._cpwsgi_server.CPWSGIServer(('domain.name', normalport)) shut down
2012-03-06 09:34:57,518::INFO::[_cplogging:55] [06/Mar/2012:09:34:57] ENGINE Stopped thread '_TimeoutMonitor'.
2012-03-06 09:34:57,519::INFO::[_cplogging:55] [06/Mar/2012:09:34:57] ENGINE Bus STOPPED
2012-03-06 09:34:57,519::INFO::[_cplogging:55] [06/Mar/2012:09:34:57] ENGINE Bus EXITING
2012-03-06 09:34:57,520::INFO::[_cplogging:55] [06/Mar/2012:09:34:57] ENGINE Bus EXITED
2012-03-06 09:34:57,520::INFO::[_cplogging:55] [06/Mar/2012:09:34:57] ENGINE Stopped thread '_TimeoutMonitor'.
2012-03-06 09:34:57,521::INFO::[_cplogging:55] [06/Mar/2012:09:34:57] ENGINE Bus STOPPED
2012-03-06 09:34:57,521::INFO::[_cplogging:55] [06/Mar/2012:09:34:57] ENGINE Bus EXITING
2012-03-06 09:34:57,522::INFO::[_cplogging:55] [06/Mar/2012:09:34:57] ENGINE Bus EXITED

What to do?

[shypike]

Do you have some third-party tool trying to connect to SABnzbd like mad?
Browser add-on?

[bav]

no, but a few friends connecting to that server, too

I cannot say what browsers/plugins they are using - but we never had that problem the last years.

It smells a bit like a DOS-Attack on cherrypy-server - is there any more logging that can shed some light on this issue?

[shypike]

You can start SABnzbd with the -w1 switch.
This will log all http requests too.

[bav]

thank you shypike, I'll give that a try and report back to you as soon as I have more info regarding that case.

[sander]

no, but a few friends connecting to that server, too

I cannot say what browsers/plugins they are using - but we never had that problem the last years.

It smells a bit like a DOS-Attack on cherrypy-server - is there any more logging that can shed some light on this issue?

To monitor this, you should run netstat. If sabnzbd is running on port 8080 and 9090, run it like this:

Code: Select all

sander@netbook:~$ netstat -apon |  grep -e 8080 -e 9090
(Not all processes could be identified, non-owned process info
 will not be shown, you would have to be root to see it all.)
tcp6       0      0 :::8080                 :::*                    LISTEN      17876/python     off (0.00/0/0)
tcp6       0      0 :::9090                 :::*                    LISTEN      17876/python     off (0.00/0/0)
tcp6       0      0 ::1:8080                ::1:52866               TIME_WAIT   -                timewait (52.57/0/0)
tcp6       0      0 ::1:8080                ::1:52864               TIME_WAIT   -                timewait (22.57/0/0)
tcp6       0      0 ::1:8080                ::1:52865               TIME_WAIT   -                timewait (22.57/0/0)
tcp6       0      0 ::1:8080                ::1:52867               TIME_WAIT   -                timewait (52.57/0/0)
sander@netbook:~$ 

You should see a maximum of 10 - 20 connections. If it goes up (100 connections or so), cherrypy will eventually give up.

Experience shows that especially the HTTPS port (so: 9090) is vulnerable for open sessions.

[hsrawat]

I also saw same issue during high load. Fixed issue and opened a bug for upstream cherrypy.
https://bitbucket.org/cherrypy/cherrypy ... nder-heavy

[hsrawat]

It very easy to re-produce. Just connect to http port in a loop. Or download some test tool to hit http port.
I have posted patch fix for above bug. Let me know if anyone need fix.

[sander]

It very easy to re-produce. Just connect to http port in a loop. Or download some test tool to hit http port.
I have posted patch fix for above bug. Let me know if anyone need fix.

I tried such a script some time ago (a lot of wget's and a lot of python-telnet's), and I couldn't trigger the problem in SABnzbd. Can you?

[hsrawat]

To trigger it with default setting you need lot of VM's. For single system test, you may want to make following changes in _cpserver.py

thread_pool = 5
thread_pool_max = -1
thread_pool_min_spare = 2
thread_pool_max_spare = 5


Start appserver. run pstack and make sure there are no more than 10 threads on startup. After that hit cherrypy port.

[hsrawat]

I used this tool
http://en.wikipedia.org/wiki/ApacheBench

[sander]

Ah, great tool. It's already installed on my Ubuntu system:

Code: Select all

sander@R540:~$ ab -n 100 -c 10 http://localhost:8080/
This is ApacheBench, Version 2.3 <$Revision: 655654 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/

Benchmarking localhost (be patient).....done


Server Software:        CherryPy/3.2.0
Server Hostname:        localhost
Server Port:            8080

Document Path:          /
Document Length:        23412 bytes

Concurrency Level:      10
Time taken for tests:   1.058 seconds
Complete requests:      100
Failed requests:        0
Write errors:           0
Total transferred:      2355400 bytes
HTML transferred:       2341200 bytes
Requests per second:    94.50 [#/sec] (mean)
Time per request:       105.819 [ms] (mean)
Time per request:       10.582 [ms] (mean, across all concurrent requests)
Transfer rate:          2173.72 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    0   0.2      0       1
Processing:    17  102  74.0     94     798
Waiting:       14   99  74.2     91     797
Total:         18  103  74.0     94     798

Percentage of the requests served within a certain time (ms)
  50%     94
  66%    103
  75%    108
  80%    111
  90%    128
  95%    138
  98%    164
  99%    798
 100%    798 (longest request)
sander@R540:~$

And this goes wrong:

Code: Select all

sander@R540:~$ ab -n 1000 -c 50 http://localhost:8080/
This is ApacheBench, Version 2.3 <$Revision: 655654 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/

Benchmarking localhost (be patient)
Completed 100 requests
Completed 200 requests
Completed 300 requests
Completed 400 requests
apr_socket_recv: Connection reset by peer (104)
Total of 411 requests completed
sander@R540:~$

Is that the bug we're talking about.

[hsrawat]

The problem happens if there are >150 (also depends on the system capability) concurrent connection, number of threads of the process will drop down.

ab -n 5000 -c 200 <host:port>

But before that you may want to check _cpserver.py threadpool settings. May be you are not using thread pool.

[sander]

I'm using a standard SABnzbd, and it says:

sander@R540:~/SABnzbd-0.7.9/cherrypy$ cat _cpserver.py | grep -i thread
thread_pool = 10
thread_pool_max = -1
sander@R540:~/SABnzbd-0.7.9/cherrypy$

So ... is my setup vulnerable?

[hsrawat]

Looks like you are using threadpool but not sure if you are using recent cherrypy. In any case if you check wsgiserver/__init__.py
and don't see min_spare and max_spare, then your setup is not vunerable. It's the introduction of min_spare and max_spare that has caused the problem.

class ThreadPool(object):
"""A Request Queue for the CherryPyWSGIServer which pools threads.

ThreadPool objects must provide min, get(), put(obj), start()
and stop(timeout) attributes.
"""

def __init__(self, server, min=20, max=-1, min_spare=5, max_spare=10):
self.server = server
self._stop = False