SABnzbd Forums


http://45.79.196.47/

Sabnzbd on seedbox with GUI binding to openvpn endpoint

http://45.79.196.47/viewtopic.php?t=20360

Page 1 of 2

Sabnzbd on seedbox with GUI binding to openvpn endpoint

Posted: March 10th, 2016, 5:57 am
by jgmtfia
I am testing sabnzbd on a seedbox. In order to not expose sabnzbd GUI ports to public internet I have setup an openVPN connection between the seedbox and my local machine. (because I don't have root on the seedbox, fancy routing, fire-walling isn't an option)

OpenVPN is functional, I can ssh from my local computer into the seedbox over the VPN connection. I can also direct Sabnzb to bind to the seedbox's vpn endpoint IP. And using a web browser I can also log into the sabnzbd GUI by pointing my local browser to the seedbox's enpoint address and the port assigned to sabnzbd (for a while, sometimes).

Here is how sabnzb is invoked:

Code: Select all

python ~/SABnzbd/SABnzbd.py -b0 -f ~/.sabnzbd/sabnzbd.ini --server 10.8.0.1:9833 --https 9834 --no_ipv6
Here is the log:

Code: Select all

2016-03-10 10:34:59,283::INFO::[SABnzbd:1262] --------------------------------
2016-03-10 10:34:59,284::INFO::[SABnzbd:1263] SABnzbd.py-0.7.20 (rev=1df2943d05d64915a166e2c97e1eef86f72e3ff3)
2016-03-10 10:34:59,284::INFO::[SABnzbd:1275] Platform = posix
2016-03-10 10:34:59,284::INFO::[SABnzbd:1276] Python-version = 2.7.10 (default, Mar  2 2016, 20:14:31) 
[GCC 4.9.2]
2016-03-10 10:34:59,284::INFO::[SABnzbd:1277] Arguments = /home/xxx/SABnzbd/SABnzbd.py -b0 -f /home/xxx/.sabnzbd/sabnzbd.ini --server 10.8.0.1:9833 --https 9834 --no_ipv6
2016-03-10 10:34:59,285::INFO::[SABnzbd:1327] Read INI file /home/xxx/.sabnzbd/sabnzbd.ini
2016-03-10 10:34:59,286::INFO::[__init__:943] Loading data for bookmarks.sab from /home/xxx/.sabnzbd/admin/bookmarks.sab
2016-03-10 10:34:59,287::INFO::[__init__:943] Loading data for rss_data.sab from /home/xxx/.sabnzbd/admin/rss_data.sab
2016-03-10 10:34:59,287::INFO::[__init__:943] Loading data for totals9.sab from /home/xxx/.sabnzbd/admin/totals9.sab
2016-03-10 10:34:59,287::INFO::[postproc:91] Loading postproc queue
2016-03-10 10:34:59,288::INFO::[__init__:943] Loading data for postproc1.sab from /home/xxx/.sabnzbd/admin/postproc1.sab
2016-03-10 10:34:59,288::INFO::[__init__:943] Loading data for queue9.sab from /home/xxx/.sabnzbd/admin/queue9.sab
2016-03-10 10:34:59,289::INFO::[__init__:943] Loading data for watched_data.sab from /home/xxx/.sabnzbd/admin/watched_data.sab
2016-03-10 10:34:59,290::INFO::[__init__:943] Loading data for Rating.sab from /home/xxx/.sabnzbd/admin/Rating.sab
2016-03-10 10:34:59,290::INFO::[__init__:946] /home/xxx/.sabnzbd/admin/Rating.sab missing, trying old cache
2016-03-10 10:34:59,290::INFO::[__init__:949] /home/xxx/.sabnzbd/cache/Rating.sab missing
2016-03-10 10:34:59,291::INFO::[scheduler:172] Setting schedule for midnight BPS reset
2016-03-10 10:34:59,291::INFO::[downloader:211] Resuming
2016-03-10 10:34:59,297::INFO::[__init__:335] All processes started
2016-03-10 10:34:59,298::INFO::[SABnzbd:335] Web dir is /home/xxx/SABnzbd/interfaces/Plush
2016-03-10 10:34:59,298::INFO::[SABnzbd:335] Web dir is /home/xxx/SABnzbd/interfaces/Config
2016-03-10 10:34:59,303::INFO::[SABnzbd:464] _yenc module... found!
2016-03-10 10:34:59,304::INFO::[SABnzbd:472] par2 binary... found (/usr/bin/par2)
2016-03-10 10:34:59,304::INFO::[SABnzbd:480] unrar binary... found (/usr/bin/unrar)
2016-03-10 10:34:59,304::INFO::[SABnzbd:485] unzip binary... found (/usr/bin/unzip)
2016-03-10 10:34:59,304::INFO::[SABnzbd:491] nice binary... found (/usr/bin/nice)
2016-03-10 10:34:59,304::INFO::[SABnzbd:495] ionice binary... found (/usr/bin/ionice)
2016-03-10 10:34:59,304::INFO::[SABnzbd:500] pyOpenSSL... found (True)
2016-03-10 10:34:59,306::INFO::[SABnzbd:1528] Starting web-interface on 10.8.0.1:9834
2016-03-10 10:35:00,308::INFO::[_cplogging:55] [10/Mar/2016:10:35:00] ENGINE Bus STARTING
2016-03-10 10:35:00,311::INFO::[_cplogging:55] [10/Mar/2016:10:35:00] ENGINE Started monitor thread '_TimeoutMonitor'.
2016-03-10 10:35:55,568::ERROR::[_cplogging:55] [10/Mar/2016:10:35:55] ENGINE Error in 'start' listener <bound method ServerAdapter.start of <cherrypy.process.servers.ServerAdapter object at 0x7f79283fc0d0>>
Traceback (most recent call last):
  File "/mnt/mpathq/xxx/SABnzbd/cherrypy/process/wspbus.py", line 147, in publish
    output.append(listener(*args, **kwargs))
  File "/mnt/mpathq/xxx/SABnzbd/cherrypy/process/servers.py", line 62, in start
    self.wait()
  File "/mnt/mpathq/xxx/SABnzbd/cherrypy/process/servers.py", line 103, in wait
    wait_for_occupied_port(host, port)
  File "/mnt/mpathq/xxx/SABnzbd/cherrypy/process/servers.py", line 275, in wait_for_occupied_port
    raise IOError("Port %r not bound on %r" % (port, host))
IOError: Port 9833 not bound on '10.8.0.1'

2016-03-10 10:36:50,823::ERROR::[_cplogging:55] [10/Mar/2016:10:36:50] ENGINE Error in 'start' listener <bound method Server.start of <cherrypy._cpserver.Server object at 0x7f792a8e0d10>>
Traceback (most recent call last):
  File "/mnt/mpathq/xxx/SABnzbd/cherrypy/process/wspbus.py", line 147, in publish
    output.append(listener(*args, **kwargs))
  File "/mnt/mpathq/xxx/SABnzbd/cherrypy/_cpserver.py", line 90, in start
    ServerAdapter.start(self)
  File "/mnt/mpathq/xxx/SABnzbd/cherrypy/process/servers.py", line 62, in start
    self.wait()
  File "/mnt/mpathq/xxx/SABnzbd/cherrypy/process/servers.py", line 103, in wait
    wait_for_occupied_port(host, port)
  File "/mnt/mpathq/xxx/SABnzbd/cherrypy/process/servers.py", line 275, in wait_for_occupied_port
    raise IOError("Port %r not bound on %r" % (port, host))
IOError: Port 9834 not bound on '10.8.0.1'

2016-03-10 10:36:50,824::ERROR::[_cplogging:55] [10/Mar/2016:10:36:50] ENGINE Shutting down due to error in start listener:
Traceback (most recent call last):
  File "/mnt/mpathq/xxx/SABnzbd/cherrypy/process/wspbus.py", line 184, in start
    self.publish('start')
  File "/mnt/mpathq/xxx/SABnzbd/cherrypy/process/wspbus.py", line 147, in publish
    output.append(listener(*args, **kwargs))
  File "/mnt/mpathq/xxx/SABnzbd/cherrypy/_cpserver.py", line 90, in start
    ServerAdapter.start(self)
  File "/mnt/mpathq/xxx/SABnzbd/cherrypy/process/servers.py", line 62, in start
    self.wait()
  File "/mnt/mpathq/xxx/SABnzbd/cherrypy/process/servers.py", line 103, in wait
    wait_for_occupied_port(host, port)
  File "/mnt/mpathq/xxx/SABnzbd/cherrypy/process/servers.py", line 275, in wait_for_occupied_port
    raise IOError("Port %r not bound on %r" % (port, host))
IOError: Port 9834 not bound on '10.8.0.1'

2016-03-10 10:36:50,824::INFO::[_cplogging:55] [10/Mar/2016:10:36:50] ENGINE Bus STOPPING
2016-03-10 10:36:50,824::INFO::[_cplogging:55] [10/Mar/2016:10:36:50] ENGINE HTTP Server cherrypy._cpwsgi_server.CPWSGIServer(('10.8.0.1', 9834)) already shut down
2016-03-10 10:36:50,825::INFO::[_cplogging:55] [10/Mar/2016:10:36:50] ENGINE HTTP Server cherrypy._cpwsgi_server.CPWSGIServer(('10.8.0.1', 9833)) already shut down
2016-03-10 10:36:50,875::INFO::[_cplogging:55] [10/Mar/2016:10:36:50] ENGINE Stopped thread '_TimeoutMonitor'.
2016-03-10 10:36:50,875::INFO::[_cplogging:55] [10/Mar/2016:10:36:50] ENGINE Bus STOPPED
2016-03-10 10:36:50,875::INFO::[_cplogging:55] [10/Mar/2016:10:36:50] ENGINE Bus EXITING
2016-03-10 10:36:50,876::INFO::[_cplogging:55] [10/Mar/2016:10:36:50] ENGINE Bus EXITED
2016-03-10 10:36:50,876::ERROR::[SABnzbd:1543] Failed to start web-interface: 
Traceback (most recent call last):
  File "/home/xxx/SABnzbd/SABnzbd.py", line 1535, in main
    cherrypy.engine.start()
  File "/mnt/mpathq/xxx/SABnzbd/cherrypy/process/wspbus.py", line 184, in start
    self.publish('start')
  File "/mnt/mpathq/xxx/SABnzbd/cherrypy/process/wspbus.py", line 147, in publish
    output.append(listener(*args, **kwargs))
  File "/mnt/mpathq/xxx/SABnzbd/cherrypy/_cpserver.py", line 90, in start
    ServerAdapter.start(self)
  File "/mnt/mpathq/xxx/SABnzbd/cherrypy/process/servers.py", line 62, in start
    self.wait()
  File "/mnt/mpathq/xxx/SABnzbd/cherrypy/process/servers.py", line 103, in wait
    wait_for_occupied_port(host, port)
  File "/mnt/mpathq/xxx/SABnzbd/cherrypy/process/servers.py", line 275, in wait_for_occupied_port
    raise IOError("Port %r not bound on %r" % (port, host))
IOError: Port 9834 not bound on '10.8.0.1'
2016-03-10 10:36:50,877::ERROR::[SABnzbd:304] Failed to start web-interface : Port 9834 not bound on '10.8.0.1'
2016-03-10 10:36:50,877::INFO::[__init__:373] SABnzbd shutting down...
2016-03-10 10:36:50,878::INFO::[__init__:919] Saving data for bookmarks.sab in /home/xxx/.sabnzbd/admin/bookmarks.sab
2016-03-10 10:36:50,878::INFO::[urlgrabber:72] URLGrabber shutting down
2016-03-10 10:36:50,879::INFO::[__init__:919] Saving data for watched_data.sab in /home/xxx/.sabnzbd/admin/watched_data.sab
2016-03-10 10:36:50,879::INFO::[dirscanner:268] Dirscanner shutting down
2016-03-10 10:36:51,381::INFO::[postproc:85] Saving postproc queue
2016-03-10 10:36:51,381::INFO::[__init__:919] Saving data for postproc1.sab in /home/xxx/.sabnzbd/admin/postproc1.sab
2016-03-10 10:36:51,382::INFO::[nzbqueue:218] Saving queue
2016-03-10 10:36:51,382::INFO::[__init__:919] Saving data for queue9.sab in /home/xxx/.sabnzbd/admin/queue9.sab
2016-03-10 10:36:51,382::INFO::[__init__:919] Saving data for totals9.sab in /home/xxx/.sabnzbd/admin/totals9.sab
2016-03-10 10:36:51,383::INFO::[__init__:919] Saving data for rss_data.sab in /home/xxx/.sabnzbd/admin/rss_data.sab
2016-03-10 10:36:51,383::INFO::[__init__:919] Saving data for bookmarks.sab in /home/xxx/.sabnzbd/admin/bookmarks.sab
2016-03-10 10:36:51,384::INFO::[__init__:919] Saving data for watched_data.sab in /home/xxx/.sabnzbd/admin/watched_data.sab
2016-03-10 10:36:51,384::INFO::[postproc:85] Saving postproc queue
2016-03-10 10:36:51,385::INFO::[__init__:919] Saving data for postproc1.sab in /home/xxx/.sabnzbd/admin/postproc1.sab
2016-03-10 10:36:51,385::INFO::[__init__:440] All processes stopped
But before killing, if I point my browser to 10.8.0.1:9834, something is still alive there serving the sabnzbd GUI. I'm not making this up. I can do things on the GUI, but downloads stop. the text log window just hangs forever until kill -9 puts it out of its misery.

Any ideas?

Re: Sabnzbd on seedbox with GUI binding to openvpn endpoint

Posted: March 10th, 2016, 6:09 am
by shypike
Have you tried release 1.0.0RC4?

Re: Sabnzbd on seedbox with GUI binding to openvpn endpoint

Posted: March 10th, 2016, 6:50 am
by jgmtfia
shypike wrote:Have you tried release 1.0.0RC4?
1.0.0.RC4 does this:

Code: Select all

python ~/Sabnzbd_new/AllofIt/SABnzbd.py  -f ~/.sabnzbd/sabnzbd.ini -b0 --server 10.8.0.1:9833 --https 9834   --logging=1
Different error now, and I no longer have to kill will -9. I was able to connect to the 9834 port before the crash

Code: Select all

(virtualenv) xxx@columbia ~ $ python ~/Sabnzbd_new/AllofIt/SABnzbd.py  -f ~/.sabnzbd/sabnzbd.ini -b0 --server 10.8.0.1:9833 --https 9834   
--logging=1
2016-03-10 11:44:31,088::INFO::[SABnzbd:1243] --------------------------------
2016-03-10 11:44:31,089::INFO::[SABnzbd:1244] SABnzbd.py-0.8.x (rev=unknown)
2016-03-10 11:44:31,089::INFO::[SABnzbd:1245] Full executable path = /home/xxx/Sabnzbd_new/AllofIt/SABnzbd.py
2016-03-10 11:44:31,089::INFO::[SABnzbd:1257] Platform = posix
2016-03-10 11:44:31,089::INFO::[SABnzbd:1258] Python-version = 2.7.10 (default, Mar  2 2016, 20:14:31) 
[GCC 4.9.2]
2016-03-10 11:44:31,089::INFO::[SABnzbd:1259] Arguments = /home/xxx/Sabnzbd_new/AllofIt/SABnzbd.py -f /home/xxx/.sabnzbd/sabnzbd.ini -b0 
--server 10.8.0.1:9833 --https 9834 --logging=1
2016-03-10 11:44:31,089::INFO::[SABnzbd:1304] Read INI file /home/xxx/.sabnzbd/sabnzbd.ini
2016-03-10 11:44:31,090::INFO::[__init__:965] Loading data for queue9.sab from /home/xxx/.sabnzbd/admin/queue9.sab
2016-03-10 11:44:31,117::INFO::[__init__:965] Loading data for rss_data.sab from /home/xxx/.sabnzbd/admin/rss_data.sab
2016-03-10 11:44:31,118::INFO::[__init__:965] Loading data for totals10.sab from /home/xxx/.sabnzbd/admin/totals10.sab
2016-03-10 11:44:31,118::INFO::[__init__:968] /home/xxx/.sabnzbd/admin/totals10.sab missing
2016-03-10 11:44:31,118::INFO::[__init__:965] Loading data for totals9.sab from /home/xxx/.sabnzbd/admin/totals9.sab
2016-03-10 11:44:31,147::INFO::[postproc:89] Loading postproc queue
2016-03-10 11:44:31,148::INFO::[__init__:965] Loading data for postproc2.sab from /home/xxx/.sabnzbd/admin/postproc2.sab
2016-03-10 11:44:31,148::INFO::[__init__:968] /home/xxx/.sabnzbd/admin/postproc2.sab missing
2016-03-10 11:44:31,148::INFO::[__init__:965] Loading data for queue10.sab from /home/xxx/.sabnzbd/admin/queue10.sab
2016-03-10 11:44:31,149::INFO::[__init__:968] /home/xxx/.sabnzbd/admin/queue10.sab missing
2016-03-10 11:44:31,149::INFO::[__init__:965] Loading data for queue9.sab from /home/xxx/.sabnzbd/admin/queue9.sab
2016-03-10 11:44:31,150::INFO::[__init__:965] Loading data for watched_data2.sab from /home/xxx/.sabnzbd/admin/watched_data2.sab
2016-03-10 11:44:31,150::INFO::[__init__:968] /home/xxx/.sabnzbd/admin/watched_data2.sab missing
2016-03-10 11:44:31,151::INFO::[__init__:965] Loading data for Rating.sab from /home/xxx/.sabnzbd/admin/Rating.sab
2016-03-10 11:44:31,151::INFO::[__init__:968] /home/xxx/.sabnzbd/admin/Rating.sab missing
2016-03-10 11:44:31,152::INFO::[scheduler:190] Setting schedule for midnight BPS reset
2016-03-10 11:44:31,152::INFO::[downloader:241] Resuming
2016-03-10 11:44:31,167::INFO::[__init__:349] All processes started
2016-03-10 11:44:31,167::INFO::[SABnzbd:355] Web dir is /home/xxx/Sabnzbd_new/AllofIt/interfaces/Plush
2016-03-10 11:44:31,167::INFO::[SABnzbd:355] Web dir is /home/xxx/Sabnzbd_new/AllofIt/interfaces/Config
2016-03-10 11:44:31,188::INFO::[SABnzbd:483] _yenc module... found!
2016-03-10 11:44:31,188::INFO::[SABnzbd:491] par2 binary... found (/usr/bin/par2)
2016-03-10 11:44:31,188::INFO::[SABnzbd:496] par2-classic binary... found (/usr/bin/par2)
2016-03-10 11:44:31,188::INFO::[SABnzbd:499] UNRAR binary... found (/usr/bin/unrar)
2016-03-10 11:44:31,188::INFO::[SABnzbd:505] unzip binary... found (/usr/bin/unzip)
2016-03-10 11:44:31,189::INFO::[SABnzbd:511] 7za binary... found (/usr/bin/7za)
2016-03-10 11:44:31,189::INFO::[SABnzbd:518] nice binary... found (/usr/bin/nice)
2016-03-10 11:44:31,189::INFO::[SABnzbd:522] ionice binary... found (/usr/bin/ionice)
2016-03-10 11:44:31,189::INFO::[SABnzbd:527] pyOpenSSL... found (True)
2016-03-10 11:44:31,189::INFO::[SABnzbd:1367] SSL version OpenSSL 1.0.2g  1 Mar 2016
2016-03-10 11:44:31,189::INFO::[SABnzbd:1368] pyOpenSSL version 0.15.1
2016-03-10 11:44:31,190::INFO::[SABnzbd:1369] SSL potentially supported protocols ['SSLv23', 'SSLv3', 'TLSv1', 'TLSv1_1', 'TLSv1_2']
2016-03-10 11:44:31,190::INFO::[SABnzbd:1370] SSL actually supported protocols ['t12', 't11', 't1', 'v23', 'v3']
2016-03-10 11:44:31,191::INFO::[SABnzbd:1516] Starting web-interface on 10.8.0.1:9834
2016-03-10 11:44:32,192::INFO::[_cplogging:216] [10/Mar/2016:11:44:32] ENGINE Bus STARTING
2016-03-10 11:44:32,195::INFO::[_cplogging:216] [10/Mar/2016:11:44:32] ENGINE Started monitor thread '_TimeoutMonitor'.
2016-03-10 11:46:12,601::ERROR::[_cplogging:216] [10/Mar/2016:11:46:12] ENGINE Shutting down due to error in start listener:
Traceback (most recent call last):
  File "/mnt/mpathq/xxx/Sabnzbd_new/AllofIt/cherrypy/process/wspbus.py", line 243, in start
    self.publish('start')
  File "/mnt/mpathq/xxx/Sabnzbd_new/AllofIt/cherrypy/process/wspbus.py", line 221, in publish
    level=40, traceback=True)
  File "/mnt/mpathq/xxx/Sabnzbd_new/AllofIt/cherrypy/process/wspbus.py", line 446, in log
    self.publish('log', msg, level)
  File "/mnt/mpathq/xxx/Sabnzbd_new/AllofIt/cherrypy/process/wspbus.py", line 223, in publish
    raise exc
ChannelFailures: TypeError('not enough arguments for format string',)

2016-03-10 11:46:12,601::INFO::[_cplogging:216] [10/Mar/2016:11:46:12] ENGINE Bus STOPPING
2016-03-10 11:46:12,601::INFO::[_cplogging:216] [10/Mar/2016:11:46:12] ENGINE HTTP Server cherrypy._cpwsgi_server.CPWSGIServer(('10.8.0.1', 
9833)) already shut down
2016-03-10 11:46:12,602::INFO::[_cplogging:216] [10/Mar/2016:11:46:12] ENGINE HTTP Server cherrypy._cpwsgi_server.CPWSGIServer(('10.8.0.1', 
9834)) already shut down
2016-03-10 11:46:12,602::INFO::[_cplogging:216] [10/Mar/2016:11:46:12] ENGINE Stopped thread '_TimeoutMonitor'.
2016-03-10 11:46:12,602::INFO::[_cplogging:216] [10/Mar/2016:11:46:12] ENGINE Bus STOPPED
2016-03-10 11:46:12,602::INFO::[_cplogging:216] [10/Mar/2016:11:46:12] ENGINE Bus EXITING
2016-03-10 11:46:12,602::INFO::[_cplogging:216] [10/Mar/2016:11:46:12] ENGINE Bus EXITED
(virtualenv) xxx@columbia ~ $

Re: Sabnzbd on seedbox with GUI binding to openvpn endpoint

Posted: March 10th, 2016, 7:02 am
by shypike
That is weird.
BTW: "ChannelFailures: TypeError('not enough arguments for format string')" is an error in Python itself.
The only times I have seen it is when CherryPy wants to log a problem with an IPv6 address.
So this would indicate that CherryPy is struggling with an IPv6 address,
which should be the case in the default situation.
Can you try to start again with this extra parameter?
--ipv6_hosting=0
If that doesn't help, try:
--ipv6_hosting=1

Re: Sabnzbd on seedbox with GUI binding to openvpn endpoint

Posted: March 10th, 2016, 7:19 am
by jgmtfia
shypike wrote: --ipv6_hosting=0

Code: Select all

(virtualenv) xxx@columbia ~ $ python ~/Sabnzbd_new/AllofIt/SABnzbd.py  -f ~/.sabnzbd/sabnzbd.ini -b0 --server 10.8.0.1:9833 --https 9834   
--logging=1 --ipv6_hosting=0
2016-03-10 12:13:36,657::INFO::[SABnzbd:1243] --------------------------------
2016-03-10 12:13:36,657::INFO::[SABnzbd:1244] SABnzbd.py-0.8.x (rev=unknown)
2016-03-10 12:13:36,657::INFO::[SABnzbd:1245] Full executable path = /home/xxx/Sabnzbd_new/AllofIt/SABnzbd.py
2016-03-10 12:13:36,658::INFO::[SABnzbd:1257] Platform = posix
2016-03-10 12:13:36,658::INFO::[SABnzbd:1258] Python-version = 2.7.10 (default, Mar  2 2016, 20:14:31) 
[GCC 4.9.2]
2016-03-10 12:13:36,658::INFO::[SABnzbd:1259] Arguments = /home/xxx/Sabnzbd_new/AllofIt/SABnzbd.py -f /home/xxx/.sabnzbd/sabnzbd.ini -b0 
--server 10.8.0.1:9833 --https 9834 --logging=1 --ipv6_hosting=0
2016-03-10 12:13:36,658::INFO::[SABnzbd:1304] Read INI file /home/xxx/.sabnzbd/sabnzbd.ini
2016-03-10 12:13:36,659::INFO::[__init__:965] Loading data for queue9.sab from /home/xxx/.sabnzbd/admin/queue9.sab
2016-03-10 12:13:36,696::INFO::[__init__:965] Loading data for rss_data.sab from /home/xxx/.sabnzbd/admin/rss_data.sab
2016-03-10 12:13:36,696::INFO::[__init__:965] Loading data for totals10.sab from /home/xxx/.sabnzbd/admin/totals10.sab
2016-03-10 12:13:36,696::INFO::[__init__:968] /home/xxx/.sabnzbd/admin/totals10.sab missing
2016-03-10 12:13:36,696::INFO::[__init__:965] Loading data for totals9.sab from /home/xxx/.sabnzbd/admin/totals9.sab
2016-03-10 12:13:36,729::INFO::[postproc:89] Loading postproc queue
2016-03-10 12:13:36,729::INFO::[__init__:965] Loading data for postproc2.sab from /home/xxx/.sabnzbd/admin/postproc2.sab
2016-03-10 12:13:36,730::INFO::[__init__:968] /home/xxx/.sabnzbd/admin/postproc2.sab missing
2016-03-10 12:13:36,730::INFO::[__init__:965] Loading data for queue10.sab from /home/xxx/.sabnzbd/admin/queue10.sab
2016-03-10 12:13:36,730::INFO::[__init__:968] /home/xxx/.sabnzbd/admin/queue10.sab missing
2016-03-10 12:13:36,731::INFO::[__init__:965] Loading data for queue9.sab from /home/xxx/.sabnzbd/admin/queue9.sab
2016-03-10 12:13:36,732::INFO::[__init__:965] Loading data for watched_data2.sab from /home/xxx/.sabnzbd/admin/watched_data2.sab
2016-03-10 12:13:36,732::INFO::[__init__:968] /home/xxx/.sabnzbd/admin/watched_data2.sab missing
2016-03-10 12:13:36,732::INFO::[__init__:965] Loading data for Rating.sab from /home/xxx/.sabnzbd/admin/Rating.sab
2016-03-10 12:13:36,733::INFO::[__init__:968] /home/xxx/.sabnzbd/admin/Rating.sab missing
2016-03-10 12:13:36,733::INFO::[scheduler:190] Setting schedule for midnight BPS reset
2016-03-10 12:13:36,734::INFO::[downloader:241] Resuming
2016-03-10 12:13:36,748::INFO::[__init__:349] All processes started
2016-03-10 12:13:36,748::INFO::[SABnzbd:355] Web dir is /home/xxx/Sabnzbd_new/AllofIt/interfaces/Plush
2016-03-10 12:13:36,749::INFO::[SABnzbd:355] Web dir is /home/xxx/Sabnzbd_new/AllofIt/interfaces/Config
2016-03-10 12:13:36,771::INFO::[SABnzbd:483] _yenc module... found!
2016-03-10 12:13:36,771::INFO::[SABnzbd:491] par2 binary... found (/usr/bin/par2)
2016-03-10 12:13:36,771::INFO::[SABnzbd:496] par2-classic binary... found (/usr/bin/par2)
2016-03-10 12:13:36,772::INFO::[SABnzbd:499] UNRAR binary... found (/usr/bin/unrar)
2016-03-10 12:13:36,772::INFO::[SABnzbd:505] unzip binary... found (/usr/bin/unzip)
2016-03-10 12:13:36,772::INFO::[SABnzbd:511] 7za binary... found (/usr/bin/7za)
2016-03-10 12:13:36,772::INFO::[SABnzbd:518] nice binary... found (/usr/bin/nice)
2016-03-10 12:13:36,772::INFO::[SABnzbd:522] ionice binary... found (/usr/bin/ionice)
2016-03-10 12:13:36,773::INFO::[SABnzbd:527] pyOpenSSL... found (True)
2016-03-10 12:13:36,773::INFO::[SABnzbd:1367] SSL version OpenSSL 1.0.2g  1 Mar 2016
2016-03-10 12:13:36,773::INFO::[SABnzbd:1368] pyOpenSSL version 0.15.1
2016-03-10 12:13:36,774::INFO::[SABnzbd:1369] SSL potentially supported protocols ['SSLv23', 'SSLv3', 'TLSv1', 'TLSv1_1', 'TLSv1_2']
2016-03-10 12:13:36,774::INFO::[SABnzbd:1370] SSL actually supported protocols ['t12', 't11', 't1', 'v23', 'v3']
2016-03-10 12:13:36,776::INFO::[SABnzbd:1516] Starting web-interface on 10.8.0.1:9834
2016-03-10 12:13:37,778::INFO::[_cplogging:216] [10/Mar/2016:12:13:37] ENGINE Bus STARTING
2016-03-10 12:13:37,782::INFO::[_cplogging:216] [10/Mar/2016:12:13:37] ENGINE Started monitor thread '_TimeoutMonitor'.
2016-03-10 12:15:18,088::ERROR::[_cplogging:216] [10/Mar/2016:12:15:18] ENGINE Shutting down due to error in start listener:
Traceback (most recent call last):
  File "/mnt/mpathq/xxx/Sabnzbd_new/AllofIt/cherrypy/process/wspbus.py", line 243, in start
    self.publish('start')
  File "/mnt/mpathq/xxx/Sabnzbd_new/AllofIt/cherrypy/process/wspbus.py", line 221, in publish
    level=40, traceback=True)
  File "/mnt/mpathq/xxx/Sabnzbd_new/AllofIt/cherrypy/process/wspbus.py", line 446, in log
    self.publish('log', msg, level)
  File "/mnt/mpathq/xxx/Sabnzbd_new/AllofIt/cherrypy/process/wspbus.py", line 223, in publish
    raise exc
ChannelFailures: TypeError('not enough arguments for format string',)

2016-03-10 12:15:18,089::INFO::[_cplogging:216] [10/Mar/2016:12:15:18] ENGINE Bus STOPPING
2016-03-10 12:15:18,089::INFO::[_cplogging:216] [10/Mar/2016:12:15:18] ENGINE HTTP Server cherrypy._cpwsgi_server.CPWSGIServer(('10.8.0.1', 
9833)) already shut down
2016-03-10 12:15:18,090::INFO::[_cplogging:216] [10/Mar/2016:12:15:18] ENGINE HTTP Server cherrypy._cpwsgi_server.CPWSGIServer(('10.8.0.1', 
9834)) already shut down
2016-03-10 12:15:18,090::INFO::[_cplogging:216] [10/Mar/2016:12:15:18] ENGINE Stopped thread '_TimeoutMonitor'.
2016-03-10 12:15:18,090::INFO::[_cplogging:216] [10/Mar/2016:12:15:18] ENGINE Bus STOPPED
2016-03-10 12:15:18,090::INFO::[_cplogging:216] [10/Mar/2016:12:15:18] ENGINE Bus EXITING
2016-03-10 12:15:18,091::INFO::[_cplogging:216] [10/Mar/2016:12:15:18] ENGINE Bus EXITED
shypike wrote: --ipv6_hosting=1

Code: Select all

(virtualenv) xxx@columbia ~ $ python ~/Sabnzbd_new/AllofIt/SABnzbd.py  -f ~/.sabnzbd/sabnzbd.ini -b0 --server 10.8.0.1:9833 --https 9834   
--logging=1 --ipv6_hosting=1
2016-03-10 12:16:18,648::INFO::[SABnzbd:1243] --------------------------------
2016-03-10 12:16:18,648::INFO::[SABnzbd:1244] SABnzbd.py-0.8.x (rev=unknown)
2016-03-10 12:16:18,649::INFO::[SABnzbd:1245] Full executable path = /home/xxx/Sabnzbd_new/AllofIt/SABnzbd.py
2016-03-10 12:16:18,649::INFO::[SABnzbd:1257] Platform = posix
2016-03-10 12:16:18,649::INFO::[SABnzbd:1258] Python-version = 2.7.10 (default, Mar  2 2016, 20:14:31) 
[GCC 4.9.2]
2016-03-10 12:16:18,649::INFO::[SABnzbd:1259] Arguments = /home/xxx/Sabnzbd_new/AllofIt/SABnzbd.py -f /home/xxx/.sabnzbd/sabnzbd.ini -b0 
--server 10.8.0.1:9833 --https 9834 --logging=1 --ipv6_hosting=1
2016-03-10 12:16:18,650::INFO::[SABnzbd:1304] Read INI file /home/xxx/.sabnzbd/sabnzbd.ini
2016-03-10 12:16:18,651::INFO::[__init__:965] Loading data for queue9.sab from /home/xxx/.sabnzbd/admin/queue9.sab
2016-03-10 12:16:18,665::INFO::[__init__:965] Loading data for rss_data.sab from /home/xxx/.sabnzbd/admin/rss_data.sab
2016-03-10 12:16:18,665::INFO::[__init__:965] Loading data for totals10.sab from /home/xxx/.sabnzbd/admin/totals10.sab
2016-03-10 12:16:18,666::INFO::[__init__:968] /home/xxx/.sabnzbd/admin/totals10.sab missing
2016-03-10 12:16:18,666::INFO::[__init__:965] Loading data for totals9.sab from /home/xxx/.sabnzbd/admin/totals9.sab
2016-03-10 12:16:18,688::INFO::[postproc:89] Loading postproc queue
2016-03-10 12:16:18,688::INFO::[__init__:965] Loading data for postproc2.sab from /home/xxx/.sabnzbd/admin/postproc2.sab
2016-03-10 12:16:18,688::INFO::[__init__:968] /home/xxx/.sabnzbd/admin/postproc2.sab missing
2016-03-10 12:16:18,689::INFO::[__init__:965] Loading data for queue10.sab from /home/xxx/.sabnzbd/admin/queue10.sab
2016-03-10 12:16:18,689::INFO::[__init__:968] /home/xxx/.sabnzbd/admin/queue10.sab missing
2016-03-10 12:16:18,689::INFO::[__init__:965] Loading data for queue9.sab from /home/xxx/.sabnzbd/admin/queue9.sab
2016-03-10 12:16:18,690::INFO::[__init__:965] Loading data for watched_data2.sab from /home/xxx/.sabnzbd/admin/watched_data2.sab
2016-03-10 12:16:18,690::INFO::[__init__:968] /home/xxx/.sabnzbd/admin/watched_data2.sab missing
2016-03-10 12:16:18,690::INFO::[__init__:965] Loading data for Rating.sab from /home/xxx/.sabnzbd/admin/Rating.sab
2016-03-10 12:16:18,690::INFO::[__init__:968] /home/xxx/.sabnzbd/admin/Rating.sab missing
2016-03-10 12:16:18,691::INFO::[scheduler:190] Setting schedule for midnight BPS reset
2016-03-10 12:16:18,691::INFO::[downloader:241] Resuming
2016-03-10 12:16:18,702::INFO::[__init__:349] All processes started
2016-03-10 12:16:18,703::INFO::[SABnzbd:355] Web dir is /home/xxx/Sabnzbd_new/AllofIt/interfaces/Plush
2016-03-10 12:16:18,703::INFO::[SABnzbd:355] Web dir is /home/xxx/Sabnzbd_new/AllofIt/interfaces/Config
2016-03-10 12:16:18,722::INFO::[SABnzbd:483] _yenc module... found!
2016-03-10 12:16:18,722::INFO::[SABnzbd:491] par2 binary... found (/usr/bin/par2)
2016-03-10 12:16:18,723::INFO::[SABnzbd:496] par2-classic binary... found (/usr/bin/par2)
2016-03-10 12:16:18,723::INFO::[SABnzbd:499] UNRAR binary... found (/usr/bin/unrar)
2016-03-10 12:16:18,723::INFO::[SABnzbd:505] unzip binary... found (/usr/bin/unzip)
2016-03-10 12:16:18,723::INFO::[SABnzbd:511] 7za binary... found (/usr/bin/7za)
2016-03-10 12:16:18,723::INFO::[SABnzbd:518] nice binary... found (/usr/bin/nice)
2016-03-10 12:16:18,724::INFO::[SABnzbd:522] ionice binary... found (/usr/bin/ionice)
2016-03-10 12:16:18,724::INFO::[SABnzbd:527] pyOpenSSL... found (True)
2016-03-10 12:16:18,724::INFO::[SABnzbd:1367] SSL version OpenSSL 1.0.2g  1 Mar 2016
2016-03-10 12:16:18,724::INFO::[SABnzbd:1368] pyOpenSSL version 0.15.1
2016-03-10 12:16:18,725::INFO::[SABnzbd:1369] SSL potentially supported protocols ['SSLv23', 'SSLv3', 'TLSv1', 'TLSv1_1', 'TLSv1_2']
2016-03-10 12:16:18,725::INFO::[SABnzbd:1370] SSL actually supported protocols ['t12', 't11', 't1', 'v23', 'v3']
2016-03-10 12:16:18,727::INFO::[SABnzbd:1516] Starting web-interface on 10.8.0.1:9834
2016-03-10 12:16:19,729::INFO::[_cplogging:216] [10/Mar/2016:12:16:19] ENGINE Bus STARTING
2016-03-10 12:16:19,733::INFO::[_cplogging:216] [10/Mar/2016:12:16:19] ENGINE Started monitor thread '_TimeoutMonitor'.
2016-03-10 12:18:00,040::ERROR::[_cplogging:216] [10/Mar/2016:12:18:00] ENGINE Shutting down due to error in start listener:
Traceback (most recent call last):
  File "/mnt/mpathq/xxx/Sabnzbd_new/AllofIt/cherrypy/process/wspbus.py", line 243, in start
    self.publish('start')
  File "/mnt/mpathq/xxx/Sabnzbd_new/AllofIt/cherrypy/process/wspbus.py", line 221, in publish
    level=40, traceback=True)
  File "/mnt/mpathq/xxx/Sabnzbd_new/AllofIt/cherrypy/process/wspbus.py", line 446, in log
    self.publish('log', msg, level)
  File "/mnt/mpathq/xxx/Sabnzbd_new/AllofIt/cherrypy/process/wspbus.py", line 223, in publish
    raise exc
ChannelFailures: TypeError('not enough arguments for format string',)

2016-03-10 12:18:00,040::INFO::[_cplogging:216] [10/Mar/2016:12:18:00] ENGINE Bus STOPPING
2016-03-10 12:18:00,041::INFO::[_cplogging:216] [10/Mar/2016:12:18:00] ENGINE HTTP Server cherrypy._cpwsgi_server.CPWSGIServer(('10.8.0.1', 
9833)) already shut down
2016-03-10 12:18:00,041::INFO::[_cplogging:216] [10/Mar/2016:12:18:00] ENGINE HTTP Server cherrypy._cpwsgi_server.CPWSGIServer(('10.8.0.1', 
9834)) already shut down
2016-03-10 12:18:00,041::INFO::[_cplogging:216] [10/Mar/2016:12:18:00] ENGINE Stopped thread '_TimeoutMonitor'.
2016-03-10 12:18:00,041::INFO::[_cplogging:216] [10/Mar/2016:12:18:00] ENGINE Bus STOPPED
2016-03-10 12:18:00,041::INFO::[_cplogging:216] [10/Mar/2016:12:18:00] ENGINE Bus EXITING
2016-03-10 12:18:00,042::INFO::[_cplogging:216] [10/Mar/2016:12:18:00] ENGINE Bus EXITED

Re: Sabnzbd on seedbox with GUI binding to openvpn endpoint

Posted: March 10th, 2016, 7:34 am
by shypike
OK, same result.
Sadly the actual problem isn't logged, due to the bug in Python.

Can you do a bit of hacking in SABnzbd's CherryPy module?

File cherrpy/process/wspbus.py, contains at line 442:

Code: Select all

    def log(self, msg="", level=20, traceback=False):
        """Log the given message. Append the last traceback if requested."""
        if traceback:
            msg += "\n" + "".join(_traceback.format_exception(*sys.exc_info()))
        self.publish('log', msg, level)
Can you add a line here?

Code: Select all

    def log(self, msg="", level=20, traceback=False):
        """Log the given message. Append the last traceback if requested."""
        if traceback:
            msg += "\n" + "".join(_traceback.format_exception(*sys.exc_info()))
            msg = msg.replace('%', '#')
        self.publish('log', msg, level)
The line with "replace" is new here.
Careful with indentation. Don't use tabs, but units of 4 spaces.

Then start SABnzbd again and report the result.
It won't solve the problem, but at least we can see what is the real error.

Re: Sabnzbd on seedbox with GUI binding to openvpn endpoint

Posted: March 10th, 2016, 12:21 pm
by jgmtfia
shypike wrote: Can you do a bit of hacking in SABnzbd's CherryPy module?
No problem - this evening, mountain time.

Re: Sabnzbd on seedbox with GUI binding to openvpn endpoint

Posted: March 10th, 2016, 5:23 pm
by shypike
Please try this piece of patched code instead.
The previous one won't work.

Code: Select all

    def log(self, msg="", level=20, traceback=False):
        """Log the given message. Append the last traceback if requested."""
        if traceback:
            errors = sys.exc_info()
            if '%' in errors[1].message:
                errors[1].args = (errors[1].args[0].replace('%', '%%'), )
                errors[1].message = errors[1].message.replace('%', '%%')
            msg += "\n" + "".join(_traceback.format_exception(*errors))
        self.publish('log', msg, level)
My suspicion is that SABnzbd is trying to bind itself to an IPv6 address and this fails.
Do you know whether your seedbox is assigned an IPv6 address by your hosting service?

Re: Sabnzbd on seedbox with GUI binding to openvpn endpoint

Posted: March 10th, 2016, 6:55 pm
by jgmtfia
My suspicion is that SABnzbd is trying to bind itself to an IPv6 address and this fails.
Do you know whether your seedbox is assigned an IPv6 address by your hosting service?
I don't see any ipv6 addresses/evidence.

Code: Select all

(virtualenv) xxx@columbia ~ $ ifconfig
bond0: flags=5187<UP,BROADCAST,RUNNING,MASTER,MULTICAST>  mtu 1500
        inet 123.123.123.123  netmask 255.255.255.0  broadcast 123.123.123.255
        ether 0c:0c:0c:0c:0c:0c  txqueuelen 1000  (Ethernet)
        RX packets 0  bytes 0 (0.0 B)
        RX errors 0  dropped 0  overruns 0  frame 0
        TX packets 0  bytes 0 (0.0 B)
        TX errors 0  dropped 0 overruns 0  carrier 0  collisions 0

eno1: flags=6211<UP,BROADCAST,RUNNING,SLAVE,MULTICAST>  mtu 1500
        ether 0c:c4:7a:bd:7c:34  txqueuelen 1000  (Ethernet)
        RX packets 0  bytes 0 (0.0 B)
        RX errors 0  dropped 0  overruns 0  frame 0
        TX packets 0  bytes 0 (0.0 B)
        TX errors 0  dropped 0 overruns 0  carrier 0  collisions 0

...

lo: flags=73<UP,LOOPBACK,RUNNING>  mtu 65536
        inet 127.0.0.1  netmask 255.0.0.0
        loop  txqueuelen 0  (Local Loopback)
        RX packets 0  bytes 0 (0.0 B)
        RX errors 0  dropped 0  overruns 0  frame 0
        TX packets 0  bytes 0 (0.0 B)
        TX errors 0  dropped 0 overruns 0  carrier 0  collisions 0

tun0: flags=4305<UP,POINTOPOINT,RUNNING,NOARP,MULTICAST>  mtu 1500
        inet 10.8.0.1  netmask 255.255.255.255  destination 10.8.0.2
        unspec 00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00  txqueuelen 100  (UNSPEC)
        RX packets 0  bytes 0 (0.0 B)
        RX errors 0  dropped 0  overruns 0  frame 0
        TX packets 0  bytes 0 (0.0 B)
        TX errors 0  dropped 0 overruns 0  carrier 0  collisions 0
shypike wrote:Please try this piece of patched code instead.
Nothing looks different (I did verify the new version of wspbus.py was being used.)

before patch

Code: Select all

2016-03-10 12:18:00,040::ERROR::[_cplogging:216] [10/Mar/2016:12:18:00] ENGINE Shutting down due to error in start listener:
Traceback (most recent call last):
  File "/mnt/mpathq/xxx/Sabnzbd_new/AllofIt/cherrypy/process/wspbus.py", line 243, in start
    self.publish('start')
  File "/mnt/mpathq/xxx/Sabnzbd_new/AllofIt/cherrypy/process/wspbus.py", line 221, in publish
    level=40, traceback=True)
  File "/mnt/mpathq/xxx/Sabnzbd_new/AllofIt/cherrypy/process/wspbus.py", line 446, in log
    self.publish('log', msg, level)
  File "/mnt/mpathq/xxx/Sabnzbd_new/AllofIt/cherrypy/process/wspbus.py", line 223, in publish
    raise exc
ChannelFailures: TypeError('not enough arguments for format string',)
After patch

Code: Select all

2016-03-10 23:50:41,352::ERROR::[_cplogging:216] [10/Mar/2016:23:50:41] ENGINE Shutting down due to error in start listener:
Traceback (most recent call last):
  File "/mnt/mpathq/xxx/Sabnzbd_new/AllofIt/cherrypy/process/wspbus.py", line 243, in start
    self.publish('start')
  File "/mnt/mpathq/xxx/Sabnzbd_new/AllofIt/cherrypy/process/wspbus.py", line 221, in publish
    level=40, traceback=True)
  File "/mnt/mpathq/xxx/Sabnzbd_new/AllofIt/cherrypy/process/wspbus.py", line 450, in log
    self.publish('log', msg, level)
  File "/mnt/mpathq/xxx/Sabnzbd_new/AllofIt/cherrypy/process/wspbus.py", line 223, in publish
    raise exc
ChannelFailures: TypeError('not enough arguments for format string',)
The complete dump:

Code: Select all

(virtualenv) xxx@columbia ~ $ python ~/Sabnzbd_new/AllofIt/SABnzbd.py  -f ~/.sabnzbd/sabnzbd.ini -b0 --server 10.8.0.1:9833 --https 9834 
--ipv6_hosting=0 --logging=2
2016-03-10 23:48:59,753::INFO::[SABnzbd:1243] --------------------------------
2016-03-10 23:48:59,753::INFO::[SABnzbd:1244] SABnzbd.py-0.8.x (rev=unknown)
2016-03-10 23:48:59,753::INFO::[SABnzbd:1245] Full executable path = /home/xxx/Sabnzbd_new/AllofIt/SABnzbd.py
2016-03-10 23:48:59,754::INFO::[SABnzbd:1257] Platform = posix
2016-03-10 23:48:59,754::INFO::[SABnzbd:1258] Python-version = 2.7.10 (default, Mar  9 2016, 06:13:37) 
[GCC 4.9.2]
2016-03-10 23:48:59,754::INFO::[SABnzbd:1259] Arguments = /home/xxx/Sabnzbd_new/AllofIt/SABnzbd.py -f /home/xxx/.sabnzbd/sabnzbd.ini -b0 
--server 10.8.0.1:9833 --https 9834 --ipv6_hosting=0 --logging=2
2016-03-10 23:48:59,754::DEBUG::[SABnzbd:1266] My local IPv4 address = 192.131.44.90
2016-03-10 23:48:59,859::DEBUG::[SABnzbd:1274] Could not determine my public IPv4 address
2016-03-10 23:48:59,859::DEBUG::[SABnzbd:1278] My IPv6 address = 2620:b8:4000:1000::90:0
2016-03-10 23:48:59,873::DEBUG::[SABnzbd:1286] CPU Pystone available performance is 80295
2016-03-10 23:48:59,873::DEBUG::[SABnzbd:1291] CPU model name is Intel(R) Xeon(R) CPU E5-2699 v3 @ 2.30GHz
2016-03-10 23:48:59,873::INFO::[SABnzbd:1304] Read INI file /home/xxx/.sabnzbd/sabnzbd.ini
2016-03-10 23:48:59,897::DEBUG::[__init__:1176] Test IPv6: IPv6 test successful. Enabling IPv6
2016-03-10 23:48:59,897::DEBUG::[__init__:296] External IPv6 test result: True
2016-03-10 23:48:59,898::INFO::[__init__:965] Loading data for rss_data.sab from /home/xxx/.sabnzbd/admin/rss_data.sab
2016-03-10 23:48:59,898::INFO::[__init__:965] Loading data for totals10.sab from /home/xxx/.sabnzbd/admin/totals10.sab
2016-03-10 23:48:59,899::DEBUG::[bpsmeter:192] Read quota q=0.0 l=0.0 reset=0
2016-03-10 23:48:59,899::INFO::[postproc:89] Loading postproc queue
2016-03-10 23:48:59,899::INFO::[__init__:965] Loading data for postproc2.sab from /home/xxx/.sabnzbd/admin/postproc2.sab
2016-03-10 23:48:59,900::INFO::[__init__:965] Loading data for queue10.sab from /home/xxx/.sabnzbd/admin/queue10.sab
2016-03-10 23:48:59,900::DEBUG::[downloader:154] Initializing downloader/decoder
2016-03-10 23:48:59,902::INFO::[__init__:965] Loading data for watched_data2.sab from /home/xxx/.sabnzbd/admin/watched_data2.sab
2016-03-10 23:48:59,902::INFO::[__init__:965] Loading data for Rating.sab from /home/xxx/.sabnzbd/admin/Rating.sab
2016-03-10 23:48:59,903::INFO::[__init__:968] /home/xxx/.sabnzbd/admin/Rating.sab missing
2016-03-10 23:48:59,903::DEBUG::[scheduler:168] Scheduling RSS interval task every 60 min (delay=36)
2016-03-10 23:48:59,904::DEBUG::[scheduler:180] Scheduling VersionCheck on day 1 at 20:51
2016-03-10 23:48:59,904::INFO::[scheduler:190] Setting schedule for midnight BPS reset
2016-03-10 23:48:59,904::INFO::[downloader:241] Resuming
2016-03-10 23:48:59,905::DEBUG::[__init__:554] PAUSED_ALL inactive
2016-03-10 23:48:59,924::INFO::[__init__:349] All processes started
2016-03-10 23:48:59,924::INFO::[SABnzbd:355] Web dir is /home/xxx/Sabnzbd_new/AllofIt/interfaces/Plush
2016-03-10 23:48:59,924::INFO::[SABnzbd:355] Web dir is /home/xxx/Sabnzbd_new/AllofIt/interfaces/Config
2016-03-10 23:48:59,925::DEBUG::[SABnzbd:1341] Unwanted extensions are ... []
2016-03-10 23:48:59,945::DEBUG::[newsunpack:149] UNRAR binary version 5.31
2016-03-10 23:48:59,945::INFO::[SABnzbd:483] _yenc module... found!
2016-03-10 23:48:59,946::INFO::[SABnzbd:491] par2 binary... found (/usr/bin/par2)
2016-03-10 23:48:59,946::INFO::[SABnzbd:496] par2-classic binary... found (/usr/bin/par2)
2016-03-10 23:48:59,946::INFO::[SABnzbd:499] UNRAR binary... found (/usr/bin/unrar)
2016-03-10 23:48:59,946::INFO::[SABnzbd:505] unzip binary... found (/usr/bin/unzip)
2016-03-10 23:48:59,946::INFO::[SABnzbd:511] 7za binary... found (/usr/bin/7za)
2016-03-10 23:48:59,946::INFO::[SABnzbd:518] nice binary... found (/usr/bin/nice)
2016-03-10 23:48:59,947::INFO::[SABnzbd:522] ionice binary... found (/usr/bin/ionice)
2016-03-10 23:48:59,947::INFO::[SABnzbd:527] pyOpenSSL... found (True)
2016-03-10 23:48:59,947::INFO::[SABnzbd:1367] SSL version OpenSSL 1.0.2g  1 Mar 2016
2016-03-10 23:48:59,947::INFO::[SABnzbd:1368] pyOpenSSL version 0.15.1
2016-03-10 23:48:59,947::INFO::[SABnzbd:1369] SSL potentially supported protocols ['SSLv23', 'SSLv3', 'TLSv1', 'TLSv1_1', 'TLSv1_2']
2016-03-10 23:48:59,947::INFO::[SABnzbd:1370] SSL actually supported protocols ['t12', 't11', 't1', 'v23', 'v3']
2016-03-10 23:48:59,949::INFO::[SABnzbd:1516] Starting web-interface on 10.8.0.1:9834
2016-03-10 23:49:00,950::INFO::[_cplogging:216] [10/Mar/2016:23:49:00] ENGINE Bus STARTING
2016-03-10 23:49:00,953::INFO::[_cplogging:216] [10/Mar/2016:23:49:00] ENGINE Started monitor thread '_TimeoutMonitor'.
2016-03-10 23:50:41,352::ERROR::[_cplogging:216] [10/Mar/2016:23:50:41] ENGINE Shutting down due to error in start listener:
Traceback (most recent call last):
  File "/mnt/mpathq/xxx/Sabnzbd_new/AllofIt/cherrypy/process/wspbus.py", line 243, in start
    self.publish('start')
  File "/mnt/mpathq/xxx/Sabnzbd_new/AllofIt/cherrypy/process/wspbus.py", line 221, in publish
    level=40, traceback=True)
  File "/mnt/mpathq/xxx/Sabnzbd_new/AllofIt/cherrypy/process/wspbus.py", line 450, in log
    self.publish('log', msg, level)
  File "/mnt/mpathq/xxx/Sabnzbd_new/AllofIt/cherrypy/process/wspbus.py", line 223, in publish
    raise exc
ChannelFailures: TypeError('not enough arguments for format string',)

2016-03-10 23:50:41,352::INFO::[_cplogging:216] [10/Mar/2016:23:50:41] ENGINE Bus STOPPING
2016-03-10 23:50:41,353::INFO::[_cplogging:216] [10/Mar/2016:23:50:41] ENGINE HTTP Server cherrypy._cpwsgi_server.CPWSGIServer(('10.8.0.1', 
9833)) already shut down
2016-03-10 23:50:41,353::INFO::[_cplogging:216] [10/Mar/2016:23:50:41] ENGINE HTTP Server None already shut down
2016-03-10 23:50:41,353::INFO::[_cplogging:216] [10/Mar/2016:23:50:41] ENGINE Stopped thread '_TimeoutMonitor'.
2016-03-10 23:50:41,353::INFO::[_cplogging:216] [10/Mar/2016:23:50:41] ENGINE Bus STOPPED
2016-03-10 23:50:41,353::INFO::[_cplogging:216] [10/Mar/2016:23:50:41] ENGINE Bus EXITING
2016-03-10 23:50:41,354::INFO::[_cplogging:216] [10/Mar/2016:23:50:41] ENGINE Bus EXITED

Re: Sabnzbd on seedbox with GUI binding to openvpn endpoint

Posted: March 10th, 2016, 10:23 pm
by sander
You wrote
I don't see any ipv6 addresses/evidence.
and/but:

Code: Select all

2016-03-10 23:48:59,754::DEBUG::[SABnzbd:1266] My local IPv4 address = 192.131.44.90
2016-03-10 23:48:59,859::DEBUG::[SABnzbd:1274] Could not determine my public IPv4 address
2016-03-10 23:48:59,859::DEBUG::[SABnzbd:1278] My IPv6 address = 2620:b8:4000:1000::90:0
... therer's the proof your system has IPv6.

Re: Sabnzbd on seedbox with GUI binding to openvpn endpoint

Posted: March 10th, 2016, 11:47 pm
by jgmtfia
sander wrote: and/but:

Code: Select all

2016-03-10 23:48:59,754::DEBUG::[SABnzbd:1266] My local IPv4 address = 192.131.44.90
2016-03-10 23:48:59,859::DEBUG::[SABnzbd:1274] Could not determine my public IPv4 address
2016-03-10 23:48:59,859::DEBUG::[SABnzbd:1278] My IPv6 address = 2620:b8:4000:1000::90:0
... therer's the proof your system has IPv6.
Curious. That address does resolve to the same host. Strange it does not show up with ifconfig.

So what test should be next?

Re: Sabnzbd on seedbox with GUI binding to openvpn endpoint

Posted: March 11th, 2016, 12:07 am
by jgmtfia
I hacked a False into the ipV6 connectivity checker so it always returns false. Still same behavior.

Code: Select all


(virtualenv) xxx@columbia ~ $ python ~/Sabnzbd_new/AllofIt/SABnzbd.py  -f ~/.sabnzbd/sabnzbd.ini -b0 --server 10.8.0.1:9833 --https 9834 
--ipv6_hosting=0 --logging=2
2016-03-11 05:03:32,962::INFO::[SABnzbd:1243] --------------------------------
2016-03-11 05:03:32,963::INFO::[SABnzbd:1244] SABnzbd.py-0.8.x (rev=unknown)
2016-03-11 05:03:32,963::INFO::[SABnzbd:1245] Full executable path = /home/xxx/Sabnzbd_new/AllofIt/SABnzbd.py
2016-03-11 05:03:32,963::INFO::[SABnzbd:1257] Platform = posix
2016-03-11 05:03:32,963::INFO::[SABnzbd:1258] Python-version = 2.7.10 (default, Mar  9 2016, 06:13:37) 
[GCC 4.9.2]
2016-03-11 05:03:32,964::INFO::[SABnzbd:1259] Arguments = /home/xxx/Sabnzbd_new/AllofIt/SABnzbd.py -f /home/xxx/.sabnzbd/sabnzbd.ini -b0 
--server 10.8.0.1:9833 --https 9834 --ipv6_hosting=0 --logging=2
2016-03-11 05:03:32,964::DEBUG::[SABnzbd:1266] My local IPv4 address = 192.131.44.90
2016-03-11 05:03:33,070::DEBUG::[SABnzbd:1274] Could not determine my public IPv4 address
2016-03-11 05:03:33,071::DEBUG::[SABnzbd:1278] My IPv6 address = 2620:b8:4000:1000::90:0
2016-03-11 05:03:33,089::DEBUG::[SABnzbd:1286] CPU Pystone available performance is 59527
2016-03-11 05:03:33,089::DEBUG::[SABnzbd:1291] CPU model name is Intel(R) Xeon(R) CPU E5-2699 v3 @ 2.30GHz
2016-03-11 05:03:33,090::INFO::[SABnzbd:1304] Read INI file /home/xxx/.sabnzbd/sabnzbd.ini
2016-03-11 05:03:33,091::DEBUG::[__init__:296] External IPv6 test result: False
2016-03-11 05:03:33,091::INFO::[__init__:965] Loading data for rss_data.sab from /home/xxx/.sabnzbd/admin/rss_data.sab
2016-03-11 05:03:33,091::INFO::[__init__:965] Loading data for totals10.sab from /home/xxx/.sabnzbd/admin/totals10.sab
2016-03-11 05:03:33,092::DEBUG::[bpsmeter:192] Read quota q=0.0 l=0.0 reset=0
2016-03-11 05:03:33,092::INFO::[postproc:89] Loading postproc queue
2016-03-11 05:03:33,092::INFO::[__init__:965] Loading data for postproc2.sab from /home/xxx/.sabnzbd/admin/postproc2.sab
2016-03-11 05:03:33,093::INFO::[__init__:965] Loading data for queue10.sab from /home/xxx/.sabnzbd/admin/queue10.sab
2016-03-11 05:03:33,093::DEBUG::[downloader:154] Initializing downloader/decoder
2016-03-11 05:03:33,094::INFO::[__init__:965] Loading data for watched_data2.sab from /home/xxx/.sabnzbd/admin/watched_data2.sab
2016-03-11 05:03:33,095::INFO::[__init__:965] Loading data for Rating.sab from /home/xxx/.sabnzbd/admin/Rating.sab
2016-03-11 05:03:33,095::INFO::[__init__:968] /home/xxx/.sabnzbd/admin/Rating.sab missing
2016-03-11 05:03:33,096::DEBUG::[scheduler:168] Scheduling RSS interval task every 60 min (delay=38)
2016-03-11 05:03:33,096::DEBUG::[scheduler:180] Scheduling VersionCheck on day 1 at 20:33
2016-03-11 05:03:33,096::INFO::[scheduler:190] Setting schedule for midnight BPS reset
2016-03-11 05:03:33,096::INFO::[downloader:241] Resuming
2016-03-11 05:03:33,097::DEBUG::[__init__:554] PAUSED_ALL inactive
2016-03-11 05:03:33,110::INFO::[__init__:349] All processes started
2016-03-11 05:03:33,110::INFO::[SABnzbd:355] Web dir is /home/xxx/Sabnzbd_new/AllofIt/interfaces/Plush
2016-03-11 05:03:33,111::INFO::[SABnzbd:355] Web dir is /home/xxx/Sabnzbd_new/AllofIt/interfaces/Config
2016-03-11 05:03:33,111::DEBUG::[SABnzbd:1341] Unwanted extensions are ... []
2016-03-11 05:03:33,130::DEBUG::[newsunpack:149] UNRAR binary version 5.31
2016-03-11 05:03:33,131::INFO::[SABnzbd:483] _yenc module... found!
2016-03-11 05:03:33,131::INFO::[SABnzbd:491] par2 binary... found (/usr/bin/par2)
2016-03-11 05:03:33,131::INFO::[SABnzbd:496] par2-classic binary... found (/usr/bin/par2)
2016-03-11 05:03:33,131::INFO::[SABnzbd:499] UNRAR binary... found (/usr/bin/unrar)
2016-03-11 05:03:33,131::INFO::[SABnzbd:505] unzip binary... found (/usr/bin/unzip)
2016-03-11 05:03:33,131::INFO::[SABnzbd:511] 7za binary... found (/usr/bin/7za)
2016-03-11 05:03:33,132::INFO::[SABnzbd:518] nice binary... found (/usr/bin/nice)
2016-03-11 05:03:33,132::INFO::[SABnzbd:522] ionice binary... found (/usr/bin/ionice)
2016-03-11 05:03:33,132::INFO::[SABnzbd:527] pyOpenSSL... found (True)
2016-03-11 05:03:33,132::INFO::[SABnzbd:1367] SSL version OpenSSL 1.0.2g  1 Mar 2016
2016-03-11 05:03:33,132::INFO::[SABnzbd:1368] pyOpenSSL version 0.15.1
2016-03-11 05:03:33,132::INFO::[SABnzbd:1369] SSL potentially supported protocols ['SSLv23', 'SSLv3', 'TLSv1', 'TLSv1_1', 'TLSv1_2']
2016-03-11 05:03:33,133::INFO::[SABnzbd:1370] SSL actually supported protocols ['t12', 't11', 't1', 'v23', 'v3']
2016-03-11 05:03:33,134::INFO::[SABnzbd:1516] Starting web-interface on 10.8.0.1:9834
2016-03-11 05:03:34,135::INFO::[_cplogging:216] [11/Mar/2016:05:03:34] ENGINE Bus STARTING
2016-03-11 05:03:34,139::INFO::[_cplogging:216] [11/Mar/2016:05:03:34] ENGINE Started monitor thread '_TimeoutMonitor'.
2016-03-11 05:05:14,542::ERROR::[_cplogging:216] [11/Mar/2016:05:05:14] ENGINE Shutting down due to error in start 
listener:AAAAAAAAAAAAAAAAAAAAAA
Traceback (most recent call last):
  File "/mnt/mpathq/xxx/Sabnzbd_new/AllofIt/cherrypy/process/wspbus.py", line 243, in start
    self.publish('start')
  File "/mnt/mpathq/xxx/Sabnzbd_new/AllofIt/cherrypy/process/wspbus.py", line 221, in publish
    level=40, traceback=True)
  File "/mnt/mpathq/xxx/Sabnzbd_new/AllofIt/cherrypy/process/wspbus.py", line 450, in log
    self.publish('log', msg, level)
  File "/mnt/mpathq/xxx/Sabnzbd_new/AllofIt/cherrypy/process/wspbus.py", line 223, in publish
    raise exc
ChannelFailures: TypeError('not enough arguments for format string',)

2016-03-11 05:05:14,542::INFO::[_cplogging:216] [11/Mar/2016:05:05:14] ENGINE Bus STOPPING
2016-03-11 05:05:14,543::INFO::[_cplogging:216] [11/Mar/2016:05:05:14] ENGINE HTTP Server cherrypy._cpwsgi_server.CPWSGIServer(('10.8.0.1', 
9833)) already shut down
2016-03-11 05:05:14,543::INFO::[_cplogging:216] [11/Mar/2016:05:05:14] ENGINE HTTP Server None already shut down
2016-03-11 05:05:14,543::INFO::[_cplogging:216] [11/Mar/2016:05:05:14] ENGINE Stopped thread '_TimeoutMonitor'.
2016-03-11 05:05:14,543::INFO::[_cplogging:216] [11/Mar/2016:05:05:14] ENGINE Bus STOPPED
2016-03-11 05:05:14,543::INFO::[_cplogging:216] [11/Mar/2016:05:05:14] ENGINE Bus EXITING
2016-03-11 05:05:14,544::INFO::[_cplogging:216] [11/Mar/2016:05:05:14] ENGINE Bus EXITED

Re: Sabnzbd on seedbox with GUI binding to openvpn endpoint

Posted: March 11th, 2016, 12:47 am
by jgmtfia
I was able to get everything to work if I did this:

Code: Select all

diff --git a/cherrypy/process/servers.py b/cherrypy/process/servers.py
index 6f8088b..50f8f1c 100644
--- a/cherrypy/process/servers.py
+++ b/cherrypy/process/servers.py
@@ -440,6 +440,7 @@ def wait_for_free_port(host, port, timeout=None):
 
 
 def wait_for_occupied_port(host, port, timeout=None):
+    return
     """Wait for the specified port to become active (receive requests)."""
     if not host:
         raise ValueError("Host values of '' or None are not allowed.")
and this (forcing IPv6 checks to fail)

Code: Select all

diff --git a/sabnzbd/__init__.py b/sabnzbd/__init__.py
index f184fb0..26bf476 100644
--- a/sabnzbd/__init__.py
+++ b/sabnzbd/__init__.py
@@ -1158,6 +1158,8 @@ def proxy_pre_queue(name, pp, cat, script, priority, size, groups):
 
 def test_ipv6():
     """ Check if external IPv6 addresses are reachable """
+
+    return False
     if not cfg.selftest_host():
         # User disabled the test, assume active IPv6
         return True
both gross hacks, but may provide some clues?

Re: Sabnzbd on seedbox with GUI binding to openvpn endpoint

Posted: March 11th, 2016, 2:53 am
by shypike
We recently introduced the --ipv6_hosting parameter (default off).
It looks like we implemented it in such a way that it only suppresses local IPv6 addresses.
As you can see, it isn't suppressing public IPv6.
I'll work this out with Sander.
Our fix will look a bit like you're "crude" solution, so keep using that for now.
Thanks for being so patient with us and for the detailed reporting.
I'll get back to you as soon as we have a proper solution.

The second puzzle is why your public IPv6 isn't working with SABnzbd/CherryPy.

Re: Sabnzbd on seedbox with GUI binding to openvpn endpoint

Posted: March 11th, 2016, 6:57 am
by sander
A few remarks:

Seedbox ánd VPN ánd IPv6 ... that's about triple bingo score for complexity:
seedbox ... I've the idea it's an account on a machine (so: not a VPS), and thus you cannot freely use all ports.
VPN ... very well possible that jgmtfia's VPN only does IPv4
IPv6 ... always interesting effects ... ;-) But we can't ignore those effects anymore because of the IPv6 proliferation, see http://www.worldipv6launch.org/apps/ipv ... -nets.html ... IPv6 is mainstream for Comcast (42%) and other ISPs and their customers.

About jgmtfia's IPv6: 2620:b8:4000:1000::90:0 = columbia.whatbox.ca. I'm assuming that is the seedbox provider, and NOT the VPN provider. Correct, jgmtfia?
If so, the seeedbox is providing the IPv6 (possibly behind NAT), and possibly the VPN is only doing IPv4, leaving the IPv6 in place on another interface ... :(



@shyypike:
--ipv6_hosting ... I have to find out what you have done. Because, if you implemented, "SAB, don't bind to IPv6 for listening", I really wonder why the manual cherrypy stuff is still needed. Incomplete implementation?
test_ipv6() ... AFAIK that's only used for outgoing connections to newsserver. So it should never influence the listening binding. On top of that: IMHO test_ipv6() should go completely; because of happy_eyeballs it's not needed anymore at all
All times are UTC-05:00
Page 1 of 2

Powered by phpBB® Forum Software © phpBB Limited