Clean install 0.8.0Beta3 on CentOS 7, host: 0.0.0.0 issues

[groentebroer]

Hi All,

I am using SABnzb for years now, thanks for that!

I installed my new home server with CentOS 7, and 0.8.0Beta3.
I do not seem to get SABnzb running on both my external IP and LAN IP.
(When I configure it to use my internal IP directly or external IP directly it works on both individually.)

Using: 0.0.0.0 as host seemed to do the trick before, but now I get a CherryPy error:

Code: Select all

2015-12-22 15:47:44,321::INFO::[_cplogging:216] [22/Dec/2015:15:47:44] ENGINE Bus STARTING
2015-12-22 15:47:44,331::INFO::[_cplogging:216] [22/Dec/2015:15:47:44] ENGINE Started monitor thread '_TimeoutMonitor'.
2015-12-22 15:47:44,435::INFO::[_cplogging:216] [22/Dec/2015:15:47:44] ENGINE Serving on http://0.0.0.0:8080
2015-12-22 15:47:49,477::ERROR::[_cplogging:216] [22/Dec/2015:15:47:49] ENGINE Shutting down due to error in start listener:
Traceback (most recent call last):
  File "/home/sabnzb/sabnzbd/cherrypy/process/wspbus.py", line 243, in start
    self.publish('start')
  File "/home/sabnzb/sabnzbd/cherrypy/process/wspbus.py", line 221, in publish
    level=40, traceback=True)
  File "/home/sabnzb/sabnzbd/cherrypy/process/wspbus.py", line 446, in log
    self.publish('log', msg, level)
  File "/home/sabnzb/sabnzbd/cherrypy/process/wspbus.py", line 223, in publish
    raise exc
ChannelFailures: TypeError('not enough arguments for format string',)

2015-12-22 15:47:49,479::INFO::[_cplogging:216] [22/Dec/2015:15:47:49] ENGINE Bus STOPPING
2015-12-22 15:47:49,480::INFO::[_cplogging:216] [22/Dec/2015:15:47:49] ENGINE HTTP Server cherrypy._cpwsgi_server.CPWSGIServer(('192.168.106.254', 8080)) already shut down
2015-12-22 15:47:49,487::INFO::[_cplogging:216] [22/Dec/2015:15:47:49] ENGINE HTTP Server cherrypy._cpwsgi_server.CPWSGIServer(('0.0.0.0', 8080)) shut down
2015-12-22 15:47:49,488::INFO::[_cplogging:216] [22/Dec/2015:15:47:49] ENGINE Stopped thread '_TimeoutMonitor'.
2015-12-22 15:47:49,489::INFO::[_cplogging:216] [22/Dec/2015:15:47:49] ENGINE Bus STOPPED
2015-12-22 15:47:49,490::INFO::[_cplogging:216] [22/Dec/2015:15:47:49] ENGINE Bus EXITING
2015-12-22 15:47:49,491::INFO::[_cplogging:216] [22/Dec/2015:15:47:49] ENGINE Bus EXITED

Commandline:

Code: Select all

/usr/bin/python SABnzbd.py -l 2 --config-file=/tmp/sabnzbd3.ini -s 0.0.0.0

Does anybody know what to do or try? I tried extra logging, but this does not seem to apply to CherryPy output.

Any help would be appreciated.
(Could it be 0.8.0Beta3 related? Have not tried 0.6.x yet.)

Regards,
Groentebroer

[sander]

Groentebroer, what happens with:

Code: Select all

ping -c4 0.0.0.0

[groentebroer]

Thanks for your quick response!

Code: Select all

ping -c4 0.0.0.0

Gives me:

Code: Select all

ping -c4 0.0.0.0
PING 0.0.0.0 (127.0.0.1) 56(84) bytes of data.
64 bytes from 127.0.0.1: icmp_seq=1 ttl=64 time=0.131 ms
64 bytes from 127.0.0.1: icmp_seq=2 ttl=64 time=0.093 ms
64 bytes from 127.0.0.1: icmp_seq=3 ttl=64 time=0.091 ms
64 bytes from 127.0.0.1: icmp_seq=4 ttl=64 time=0.090 ms

--- 0.0.0.0 ping statistics ---
4 packets transmitted, 4 received, 0% packet loss, time 2999ms
rtt min/avg/max/mdev = 0.090/0.101/0.131/0.018 ms

Edit:
To connect to the internet I use PPP0e.
I also have Docker installed, which might be of influence?

[sander]

Next test: Can you run this program:

Code: Select all

'''
    Simple socket server
'''
 
import socket
import sys
HOST = '0.0.0.0'
PORT = 8888 # Arbitrary non-privileged port
 
s = socket.socket(socket.AF_INET, socket.SOCK_STREAM)
print 'Socket created'
 
#Bind socket to local host and port
try:
    s.bind((HOST, PORT))
except socket.error as msg:
    print 'Bind failed. Error Code : ' + str(msg[0]) + ' Message ' + msg[1]
    sys.exit()
     
print 'Socket bind complete'
 
#Start listening on socket
s.listen(5)
print 'Socket now listening'
 
#now keep talking with the client
while 1:
    #wait to accept a connection - blocking call
    conn, addr = s.accept()
    print 'Connected with ' + addr[0] + ':' + str(addr[1])
     
s.close()

[groentebroer]

Wow, you are fast ;-).

Running it seems to work.
I see no errors and see the "socket created".
When I change the port to 8080, I get socket created as well, while SABnzb is running on the public IP on 8080 (should this also work)?

Edit: Arch, sorry wanted to fast. Only copied the first lines of code. Will check the rest now.

[groentebroer]

Oke, sorry that I did not copy all the code at once.

Running the complete code:

Code: Select all

~]$ python stest.py
Socket created
Socket bind complete
Socket now listening

Connecting to localhost on 8888 works:

Code: Select all

~]$ telnet localhost 8888
Trying 127.0.0.1...
Connected to localhost.
Escape character is '^]'.

Which results in a connection on the script stdout:

Code: Select all

Connected with 127.0.0.1:37668

Changing the port to 8080 works as well. (Stopping SABnzbd on the public IP on 8080, because when this still runs, it complains about the address being in use.)

[sander]

So you can bind on 0.0.0.0? Strange.

Let's approach it from the other side:

Code: Select all

>>> "%s %s" % 'hello', 'world'
Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
TypeError: not enough arguments for format string

sabnzbdplus/cherrypy/process/wspbus.py:

Code: Select all

    def publish(self, channel, *args, **kwargs):
        """Return output of all subscribers for the given channel."""
        if channel not in self.listeners:
            return []

        exc = ChannelFailures()
        output = []

        items = [(self._priorities[(channel, listener)], listener)
                 for listener in self.listeners[channel]]
        try:
            items.sort(key=lambda item: item[0])
        except TypeError:
            # Python 2.3 had no 'key' arg, but that doesn't matter
            # since it could sort dissimilar types just fine.
            items.sort()
        for priority, listener in items:
            try:
                output.append(listener(*args, **kwargs))
            except KeyboardInterrupt:
                raise
            except SystemExit:
                e = sys.exc_info()[1]
                # If we have previous errors ensure the exit code is non-zero
                if exc and e.code == 0:
                    e.code = 1
                raise
            except:
                exc.handle_exception()
                if channel == 'log':
                    # Assume any further messages to 'log' will fail.
                    pass
                else:
                    self.log("Error in %r listener %r" % (channel, listener),
                             level=40, traceback=True)
        if exc:
            raise exc
        return output

Line 223 is that penultimate line "raise exc".

Combining the two snippets above, it's tempting to think the problem is caused by:

Code: Select all

self.log("Error in %r listener %r" % (channel, listener),

but even if channel or listener set to None, that does not result in the error you see.

TBC

[sander]

More trial and error:

Add to /etc/hosts:

Code: Select all

0.0.0.0		anyhost

Then run like this:

Code: Select all

sabnzbdplus -l 2 --config-file=/tmp/sabnzbd$$.ini -s anyhost

[groentebroer]

Thanks Sander!

Oke, I tried modifying the code a little to:

Code: Select all

            except:
                exc.handle_exception()
                if channel == 'log':
                    # Assume any further messages to 'log' will fail.
                    self.log('cccc')
                    self.log("Error in %r listener %r" % (channel,listener))
                    pass
                else:
                    self.log("Error in %r listener %r" % (channel, listener),
                             level=40, traceback=True)
        if exc:
            if channel == 'log':
                self.log('aaaa')
            else:
                self.log('bbbb')
            raise exc
        return output

So it seems that the error is related to the 'log" channel, with a specific listner.
When I use the "level" and "traceback" settings in logging, the scripts stops with maximum recursion.

The output of the above is:

Code: Select all

2015-12-22 22:56:38,807::INFO::[SABnzbd:1361] SSL actually supported protocols ['t1', 'v23', 'v3', 'v2']
2015-12-22 22:56:38,812::INFO::[SABnzbd:1507] Starting web-interface on 0.0.0.0:8080
2015-12-22 22:56:38,814::INFO::[_cplogging:216] [22/Dec/2015:22:56:38] ENGINE Bus STARTING
2015-12-22 22:56:38,825::INFO::[_cplogging:216] [22/Dec/2015:22:56:38] ENGINE Started monitor thread '_TimeoutMonitor'.
2015-12-22 22:56:38,929::INFO::[_cplogging:216] [22/Dec/2015:22:56:38] ENGINE Serving on http://0.0.0.0:8080
2015-12-22 22:56:43,970::INFO::[_cplogging:216] [22/Dec/2015:22:56:43] ENGINE cccc
2015-12-22 22:56:43,972::INFO::[_cplogging:216] [22/Dec/2015:22:56:43] ENGINE Error in 'log' listener <function _buslog at 0x11c9758>
2015-12-22 22:56:43,973::INFO::[_cplogging:216] [22/Dec/2015:22:56:43] ENGINE aaaa
2015-12-22 22:56:43,974::ERROR::[_cplogging:216] [22/Dec/2015:22:56:43] ENGINE Shutting down due to error in start listener:
Traceback (most recent call last):
  File "/home/sabnzb/sabnzbd/cherrypy/process/wspbus.py", line 249, in start
    self.publish('start')
  File "/home/sabnzb/sabnzbd/cherrypy/process/wspbus.py", line 223, in publish
    level=40, traceback=True)
  File "/home/sabnzb/sabnzbd/cherrypy/process/wspbus.py", line 452, in log
    self.publish('log', msg, level)
  File "/home/sabnzb/sabnzbd/cherrypy/process/wspbus.py", line 229, in publish
    raise exc
ChannelFailures: TypeError('not enough arguments for format string',)

2015-12-22 22:56:43,976::INFO::[_cplogging:216] [22/Dec/2015:22:56:43] ENGINE Bus STOPPING
2015-12-22 22:56:43,977::INFO::[_cplogging:216] [22/Dec/2015:22:56:43] ENGINE HTTP Server cherrypy._cpwsgi_server.CPWSGIServer(('192.168.106.254', 8080)) already shut down
2015-12-22 22:56:43,984::INFO::[_cplogging:216] [22/Dec/2015:22:56:43] ENGINE HTTP Server cherrypy._cpwsgi_server.CPWSGIServer(('0.0.0.0', 8080)) shut down
2015-12-22 22:56:43,985::INFO::[_cplogging:216] [22/Dec/2015:22:56:43] ENGINE Stopped thread '_TimeoutMonitor'.
2015-12-22 22:56:43,987::INFO::[_cplogging:216] [22/Dec/2015:22:56:43] ENGINE Bus STOPPED
2015-12-22 22:56:43,988::INFO::[_cplogging:216] [22/Dec/2015:22:56:43] ENGINE Bus EXITING
2015-12-22 22:56:43,989::INFO::[_cplogging:216] [22/Dec/2015:22:56:43] ENGINE Bus EXITED

Will try your suggestions now.

[groentebroer]

Hi Sander,

Your suggestion actually makes it running!
(I can connect on it "Local lan" and remote ("via VPN and back ;-)").

LOG output:

Code: Select all

2015-12-22 23:03:05,391::INFO::[SABnzbd:1361] SSL actually supported protocols ['t1', 'v23', 'v3', 'v2']
2015-12-22 23:03:05,395::INFO::[SABnzbd:1507] Starting web-interface on anyhost:8080
2015-12-22 23:03:05,397::INFO::[_cplogging:216] [22/Dec/2015:23:03:05] ENGINE Bus STARTING
2015-12-22 23:03:05,407::INFO::[_cplogging:216] [22/Dec/2015:23:03:05] ENGINE Started monitor thread '_TimeoutMonitor'.
2015-12-22 23:03:05,512::INFO::[_cplogging:216] [22/Dec/2015:23:03:05] ENGINE Serving on http://anyhost:8080
2015-12-22 23:03:05,514::INFO::[_cplogging:216] [22/Dec/2015:23:03:05] ENGINE Bus STARTED
2015-12-22 23:03:05,516::INFO::[zconfig:64] No Bonjour/ZeroConfig support installed
2015-12-22 23:03:05,517::INFO::[panic:265] Launching browser with http://anyhost:8080/sabnzbd
2015-12-22 23:03:05,519::DEBUG::[notifier:112] Sending registration to localhost:23053
2015-12-22 23:03:05,521::DEBUG::[notifier:102] Checking icon
2015-12-22 23:03:05,524::DEBUG::[notifier:219] To : localhost:23053 <<class 'gntp.GNTPRegister'>>
2015-12-22 23:03:05,526::DEBUG::[growler:197] Cannot register with Growl [Errno 111] Connection refused
2015-12-22 23:03:06,019::DEBUG::[misc:565] Unsupported release number (0.8.x), will not check
2015-12-22 23:03:06,020::INFO::[SABnzbd:1579] Starting SABnzbd.py-0.8.x
2015-12-22 23:03:06,021::DEBUG::[__init__:359] Starting postprocessor

via command:

Code: Select all

/usr/bin/python SABnzbd.py -l 2 --config-file=/tmp/sabnzbd10.ini -s anyhost

What could this mean?
And how to "fix" it properly?

[groentebroer]

Will be out now, so next reply might take some hours. Thanks already for your help. Hope you will have more insights in how to nail this thing .

[sander]

OK, so after starting with anyhost: can fill out 0.0.0.0 as SABnzbd Host in Config -> General, and restart SABnzbd. Does that work?

[groentebroer]

Hi,

That does not seem to work either. After setting it in the web interface to 0.0.0.0 instead of "anyhost" it fails to start with the same error:

Code: Select all

  File "/home/sabnzb/sabnzbd/cherrypy/process/wspbus.py", line 229, in publish
    raise exc
ChannelFailures: TypeError('not enough arguments for format string',)

Do not know if this might help, but another strange thing is that when using "-s 0.0.0.0" on the commandline after a couple of eronomous restarts, it complains that the port is already in use. I can resolve this bij changing the config file (reference to ini file), after which it will work again. When I have this error and use "anyhost" after that, it does not complain.

Error I get somethimes:

Code: Select all

2015-12-23 09:04:11,043::INFO::[_cplogging:216] [23/Dec/2015:09:04:11] ENGINE Started monitor thread '_TimeoutMonitor'.
2015-12-23 09:04:11,147::INFO::[_cplogging:216] [23/Dec/2015:09:04:11] ENGINE Serving on http://192.168.106.254:8080
2015-12-23 09:04:11,154::ERROR::[_cplogging:216] [23/Dec/2015:09:04:11] ENGINE Error in HTTP server: shutting down
Traceback (most recent call last):
  File "/home/sabnzb/sabnzbd/cherrypy/process/servers.py", line 206, in _start_http_thread
    self.httpserver.start()
  File "/home/sabnzb/sabnzbd/cherrypy/wsgiserver/wsgiserver2.py", line 1973, in start
    raise socket.error(msg)
error: No socket could be created -- (('0.0.0.0', 8080): [Errno 98] Address already in use)

2015-12-23 09:04:11,156::INFO::[_cplogging:216] [23/Dec/2015:09:04:11] ENGINE Bus STOPPING
2015-12-23 09:04:11,163::INFO::[_cplogging:216] [23/Dec/2015:09:04:11] ENGINE HTTP Server cherrypy._cpwsgi_server.CPWSGIServer(('192.168.106.254', 8080)) shut down
2015-12-23 09:04:11,164::INFO::[_cplogging:216] [23/Dec/2015:09:04:11] ENGINE HTTP Server cherrypy._cpwsgi_server.CPWSGIServer(('0.0.0.0', 8080)) already shut down
2015-12-23 09:04:11,165::INFO::[_cplogging:216] [23/Dec/2015:09:04:11] ENGINE Stopped thread '_TimeoutMonitor'.

[groentebroer]

Looking again at the logs, it seems to find my local IP and my Public IP as the same IP:

Code: Select all

2015-12-23 09:05:00,452::INFO::[SABnzbd:1239] --------------------------------
2015-12-23 09:05:00,453::INFO::[SABnzbd:1240] SABnzbd.py-0.8.x (rev=unknown)
2015-12-23 09:05:00,454::INFO::[SABnzbd:1252] Platform = posix
2015-12-23 09:05:00,455::INFO::[SABnzbd:1253] Python-version = 2.7.5 (default, Nov 20 2015, 02:00:19)
[GCC 4.8.5 20150623 (Red Hat 4.8.5-4)]
2015-12-23 09:05:00,456::INFO::[SABnzbd:1254] Arguments = SABnzbd.py -l 2 --config-file=/tmp/sabnzborig1.ini
2015-12-23 09:05:00,458::DEBUG::[SABnzbd:1261] My local IPv4 address = 77.<scrubbed>
2015-12-23 09:05:00,860::DEBUG::[SABnzbd:1267] My public IPv4 address = 77.<scrubbed>
2015-12-23 09:05:00,861::DEBUG::[SABnzbd:1275] Could not determine my IPv6 address
2015-12-23 09:05:00,916::DEBUG::[SABnzbd:1281] CPU Pystone available performance is 19999
2015-12-23 09:05:00,917::DEBUG::[SABnzbd:1286] CPU model name is Intel(R) Atom(TM) CPU D2550   @ 1.86GHz
2015-12-23 09:05:00,918::INFO::[SABnzbd:1299] Read INI file /tmp/sabnzborig1.ini
2015-12-23 09:05:00,963::DEBUG::[__init__:1154] Test IPv6: Cannot reach IPv6 test host. Disabling IPv6
2015-12-23 09:05:00,964::DEBUG::[__init__:295] External IPv6 test result: False
2015-12-23 09:05:00,966::INFO::[__init__:958] Loading data for rss_data.sab from /tmp/admin/rss_data.sab

[sander]

Looking again at the logs, it seems to find my local IP and my Public IP as the same IP:

On what kind of system are you running SABnzbd? Is it a system at home, behind a router/modem (NAT-device)?

Or a VPS? Or has it a VPN?

Does "ifconfig" show an RFC1918 address (so: 192.168 or 10.x)?