Merge branch 'master' of https://git.erp5.org/repos/vifibnet

README

+New log system :
+    we use the logging module now. There are three levels for log messages :
+    - info : give basic information about what vifibnet is doing
+    - debug : display internal work of the script (finished action, detailed
+              information about tunnels, etc... )
+    - trace : for intensive debug, display configuration, arguments given to
+              processes, all information pertinent to debug but not required
+              mot of the time
+    Additionally, warning, error and exception can be used.
+    Note : logging.exception prints informations similar to pdb.set_trace()
+           info, which is pretty heavy, so for exception we expect ( for
+           instance, connection problems to the registry ), one can print the
+           exception as warning. ( see db.refresh() ).
+
 Vifibnet is a daemon setting up a resilient virtual private network over the
 internet
 

TODO

@@ -4,7 +4,7 @@ To be done :
         number of routes / tunnel
         favorise most used roads
 
-    Write docstrings for all class/methods/functions
+    ( Write docstrings for all class/methods/functions )
 
     We should replace dead connection much more often than we refresh tunnels otherwise, it brings instability
     	If we do this, we must protect some tunnels

db.py

-import sqlite3, socket, subprocess, xmlrpclib, time, os
+import logging, sqlite3, socket, subprocess, xmlrpclib, time, os
 import utils
 
 class PeerManager:
@@ -16,12 +16,12 @@ class PeerManager:
         self._pp = pp
         self._manual = manual
 
-        utils.log('Connectiong to peers database...', 4)
+        logging.info('Connecting to peers database...')
         self._db = sqlite3.connect(os.path.join(db_dir_path, 'peers.db'),
                                    isolation_level=None)
-        utils.log('Database opened', 5)
+        logging.debug('Database opened')
 
-        utils.log('Preparing peers database...', 4)
+        logging.info('Preparing peers database...')
         self._db.execute("""CREATE TABLE IF NOT EXISTS peers (
                             prefix TEXT PRIMARY KEY,
                             address TEXT NOT NULL,
@@ -46,53 +46,53 @@ class PeerManager:
             a = proxy.getPrivateAddress()
             self._db.execute("INSERT INTO config VALUES ('registry',?)", (a,))
         self._proxy = xmlrpclib.ServerProxy(a)
-        utils.log('Database prepared', 5)
+        logging.debug('Database prepared')
 
         self.next_refresh = time.time()
 
     def clear_blacklist(self, flag):
-        utils.log('Clearing blacklist from flag %u' % (flag,), 3)
+        logging.info('Clearing blacklist from flag %u' % flag)
         self._db.execute("DELETE FROM blacklist WHERE flag = ?",
                           (flag,))
-        utils.log('Blacklist cleared', 5)
+        logging.info('Blacklist cleared')
 
     def blacklist(self, prefix, flag):
-        utils.log('Blacklisting %s' % (prefix,), 4)
+        logging.ninfo('Blacklisting %s' % prefix)
         self._db.execute("DELETE FROM peers WHERE prefix = ?", (prefix,))
         self._db.execute("INSERT OR REPLACE INTO blacklist VALUES (?,?)",
                           (prefix, flag))
-        utils.log('%s blacklisted' % (prefix,), 5)
+        logging.debug('%s blacklisted' % prefix)
 
     def whitelist(self, prefix):
-        utils.log('Unblacklisting %s' % (prefix,), 4)
+        logging.info('Unblacklisting %s' % prefix)
         self._db.execute("DELETE FROM blacklist WHERE prefix = ?", (prefix,))
-        utils.log('%s whitelisted' % (prefix,), 5)
+        logging.debug('%s whitelisted' % prefix)
 
     def refresh(self):
-        utils.log('Refreshing the peers DB...', 2)
+        logging.info('Refreshing the peers DB...')
         try:
             self._declare()
             self._populate()
-            utils.log('DB refreshed', 3)
+            logging.info('DB refreshed')
             self.next_refresh = time.time() + self._refresh_time
             return True
         except socket.error, e:
-            utils.log(e, 4)
-            utils.log('Connection to server failed, retrying in 30s', 2)
+            logging.debug('socket.error : %s' % e)
+            logging.info('Connection to server failed, retrying in 30s')
             self.next_refresh = time.time() + 30
             return False
 
     def _declare(self):
         if self._address != None:
-            utils.log('Sending connection info to server...', 3)
+            logging.info('Sending connection info to server...')
             self._proxy.declare((self._internal_ip,
                     utils.address_str(self._address)))
-            utils.log('Info sent', 5)
+            logging.debug('Info sent')
         else:
-            utils.log("Warning : couldn't send ip, unknown external config", 4)
+            logging.warning("Warning : couldn't send ip, unknown external config")
 
     def _populate(self):
-        utils.log('Populating the peers DB...', 2)
+        logging.info('Populating the peers DB...')
         new_peer_list = self._proxy.getPeerList(self._db_size,
                 self._internal_ip)
         with self._db:
@@ -104,8 +104,8 @@ class PeerManager:
                                     VALUES (?,?)""", new_peer_list)
             self._db.execute("""DELETE FROM peers WHERE prefix IN
                                 (SELECT prefix FROM blacklist)""")
-        utils.log('DB populated', 3)
-        utils.log('New peers : %s' % ', '.join(map(str, new_peer_list)), 5)
+        logging.info('DB populated')
+        logging.trace('New peers : %s' % (', '.join(map(str, new_peer_list)),))
 
     def getUnusedPeers(self, peer_count):
         for populate in self.refresh, self._bootstrap, bool:
@@ -116,16 +116,16 @@ class PeerManager:
                 return peer_list
 
     def _bootstrap(self):
-        utils.log('Getting Boot peer...', 3)
+        logging.info('Getting Boot peer...')
         proxy = xmlrpclib.ServerProxy(self._registry)
         try:
             bootpeer = proxy.getBootstrapPeer(self._prefix).data
-            utils.log('Boot peer received from server', 4)
+            logging.debug('Boot peer received from server')
             p = subprocess.Popen(('openssl', 'rsautl', '-decrypt', '-inkey', self._key_path),
                     stdin=subprocess.PIPE, stdout=subprocess.PIPE)
             bootpeer = p.communicate(bootpeer).split()
             self.db.execute("INSERT INTO peers (prefix, address) VALUES (?,?)", bootpeer)
-            utils.log('Boot peer added', 4)
+            logging.debug('Boot peer added')
             return True
         except socket.error:
             pass
@@ -136,29 +136,29 @@ class PeerManager:
         return False
 
     def usePeer(self, prefix):
-        utils.log('Updating peers database : using peer ' + str(prefix), 5)
-        self._db.execute("UPDATE peers SET used = 1 WHERE prefix = ?", 
+        logging.trace('Updating peers database : using peer %s' % prefix)
+        self._db.execute("UPDATE peers SET used = 1 WHERE prefix = ?",
                 (prefix,))
-        utils.log('DB updated', 5)
+        logging.debug('DB updated')
 
     def unusePeer(self, prefix):
-        utils.log('Updating peers database : unusing peer ' + str(prefix), 5)
-        self._db.execute("UPDATE peers SET used = 0 WHERE prefix = ?", 
+        logging.trace('Updating peers database : unusing peer %s' % prefix)
+        self._db.execute("UPDATE peers SET used = 0 WHERE prefix = ?",
                 (prefix,))
-        utils.log('DB updated', 5)
+        logging.debug('DB updated')
 
     def flagPeer(self, prefix):
-        utils.log('Updating peers database : flagging peer ' + str(prefix), 5)
+        logging.trace('Updating peers database : flagging peer %s' % prefix)
         self._db.execute("UPDATE peers SET used = -1 WHERE prefix = ?",
                 (prefix,))
-        utils.log('DB updated', 5)
+        logging.debug('DB updated')
 
     def handle_message(self, msg):
         script_type, arg = msg.split()
         if script_type == 'client-connect':
-            utils.log('Incomming connection from %s' % (arg,), 3)
+            logging.info('Incomming connection from %s' % (arg,))
         elif script_type == 'client-disconnect':
-            utils.log('%s has disconnected' % (arg,), 3)
+            logging.info('%s has disconnected' % (arg,))
         elif script_type == 'route-up':
             if not self._manual:
                 external_ip = arg
@@ -166,10 +166,10 @@ class PeerManager:
                                    for port, proto in self._pp)
                 if self._address != new_address:
                     self._address = new_address
-                    utils.log('Received new external ip : %s' 
-                              % (external_ip,), 3)
+                    logging.info('Received new external ip : %s'
+                              % (external_ip,))
                     self._declare()
         else:
-            utils.log('Unknow message recieved from the openvpn pipe : '
-                    + msg, 1)
+            logging.debug('Unknow message recieved from the openvpn pipe : %s'
+                    % msg)
 

plib.py

-import os, subprocess
+import os, subprocess, logging
 import utils
 
-verbose = None
+verbose = 0
 
 def openvpn(hello_interval, *args, **kw):
     args = ['openvpn',
@@ -14,15 +14,15 @@ def openvpn(hello_interval, *args, **kw):
         '--group', 'nogroup',
         '--verb', str(verbose),
         ] + list(args)
-    utils.log(args, 5)
+    logging.trace('%s' % (args,))
     return subprocess.Popen(args, **kw)
 
 def server(server_ip, ip_length, max_clients, dh_path, pipe_fd, port, proto, hello_interval, *args, **kw):
-    utils.log('Starting server...', 3)
+    logging.debug('Starting server...')
     return openvpn(hello_interval,
         '--tls-server',
         '--mode', 'server',
-        '--up', 'ovpn-server %s/%u' % (server_ip, 64), 
+        '--up', 'ovpn-server %s/%u' % (server_ip, 64),
         '--client-connect', 'ovpn-server ' + str(pipe_fd),
         '--client-disconnect', 'ovpn-server ' + str(pipe_fd),
         '--dh', dh_path,
@@ -32,7 +32,7 @@ def server(server_ip, ip_length, max_clients, dh_path, pipe_fd, port, proto, hel
         *args, **kw)
 
 def client(server_address, pipe_fd, hello_interval, *args, **kw):
-    utils.log('Starting client...', 5)
+    logging.debug('Starting client...')
     remote = ['--nobind',
               '--client',
               '--up', 'ovpn-client',
@@ -41,14 +41,14 @@ def client(server_address, pipe_fd, hello_interval, *args, **kw):
         for ip, port, proto in utils.address_list(server_address):
             remote += '--remote', ip, port, proto
     except ValueError, e:
-        utils.log('Error "%s" in unpacking address %s for openvpn client'
-                % (e, server_address,), 1)
+        logging.warning('Error "%s" in unpacking address %s for openvpn client'
+                % (e, server_address,))
     remote += args
     return openvpn(hello_interval, *remote, **kw)
 
 def router(network, internal_ip, interface_list,
            wireless, hello_interval, state_path, **kw):
-    utils.log('Starting babel...', 3)
+    logging.info('Starting babel...')
     args = ['babeld',
             '-C', 'redistribute local ip %s' % (internal_ip),
             '-C', 'redistribute local deny',
@@ -69,6 +69,6 @@ def router(network, internal_ip, interface_list,
     if wireless:
         args.append('-w')
     args = args + interface_list
-    utils.log(args, 5)
+    logging.trace('%s' % args)
     return subprocess.Popen(args, **kw)
 

registry.py

@@ -54,9 +54,9 @@ class main(object):
                 help='Path to certificate key')
         _('--mailhost', required=True,
                 help='SMTP server mail host')
-        _('--bootstrap', nargs=4, action="append",
-                help='''VPN prefix, ip address, port and protocol to send as
-                        bootstrap peers, instead of random ones''')
+        _('--bootstrap', action="append",
+                help='''VPN prefix of the peers to send as bootstrap peer,
+                        instead of random ones''')
         _('--private',
                 help='VPN IP of the node on which runs the registry')
         self.config = parser.parse_args()
@@ -124,7 +124,7 @@ class main(object):
         # Creating and sending email
         s = smtplib.SMTP(self.config.mailhost)
         me = 'postmaster@vifibnet.com'
-        msg = MIMEText('Hello world !\nYour token : %s' % (token,))
+        msg = MIMEText('Hello world !\nYour token : %s' % (token,)) # XXX
         msg['Subject'] = '[Vifibnet] Token Request'
         msg['From'] = me
         msg['To'] = email
@@ -140,7 +140,8 @@ class main(object):
                 prefix += '0'
                 self.db.execute("INSERT INTO vpn VALUES (?,null,null)", (prefix,))
             return prefix
-        raise RuntimeError  # TODO: raise better exception
+        logging.error('There are no more free /%s prefix available' % (prefix_len,))
+        raise RuntimeError
 
     def requestCertificate(self, handler, token, cert_req):
         try:
@@ -149,7 +150,7 @@ class main(object):
                 try:
                     token, email, prefix_len, _ = self.db.execute("SELECT * FROM tokens WHERE token = ?", (token,)).next()
                 except StopIteration:
-                    # TODO: return nice error message
+                    logging.exception('Bad token (%s) in request' %(token,))
                     raise
                 self.db.execute("DELETE FROM tokens WHERE token = ?", (token,))
 
@@ -183,18 +184,21 @@ class main(object):
     def getPrivateAddress(self, handler):
         return 'http://[%s]:%u' % (self.config.private, self.config.port)
 
+    def _randomPeer(self):
+        return self.db.execute("""SELECT prefix, address
+                        FROM peers ORDER BY random() LIMIT 1""").next()
+
     def getBootstrapPeer(self, handler, client_prefix):
-        # TODO: Insert a flag column for bootstrap ready servers in peers
-        # ( servers which shouldn't go down or change ip and port as opposed to servers owned by particulars )
-        # that way, we also ascertain that the server sent is not the new node....
         cert = self.db.execute("SELECT cert FROM vpn WHERE prefix = ?", (client_prefix,))
         if self.config.bootstrap:
             bootpeer = random.choice(self.config.bootstrap)
-            prefix = bootpeer[0]
-            address = ','.join(bootpeer[1:])
+            try:
+                prefix, address = self.db.execute("""SELECT prefix, address
+                                FROM peers WHERE prefix = ?""", (bootpeer,))
+            except StopIteration:
+                prefix, address = self._randomPeer()
         else:
-            prefix, address = self.db.execute("""SELECT prefix, address
-                              FROM peers ORDER BY random() LIMIT 1""")
+            prefix, address = self._randomPeer()
         r, w = os.pipe()
         try:
             threading.Thread(target=os.write, args=(w, cert)).start()
@@ -217,8 +221,8 @@ class main(object):
             self.db.execute("INSERT OR REPLACE INTO peers (prefix, address) VALUES (?,?)", (prefix, address))
             return True
         else:
-            # TODO: use log + DO NOT PRINT BINARY IP
-            print "Unauthorized connection from %s which does not start with %s" % (client_ip, self.network)
+            logging.warning("Unauthorized connection from %s which does not start with %s"
+                    % (utils.ipFromBin(client_ip), utils.ipFromBin(self.network.ljust(128, '0'))))
             return False
 
     def getPeerList(self, handler, n, client_address):
@@ -232,8 +236,8 @@ class main(object):
             print "sending peers"
             return self.db.execute("SELECT prefix, address FROM peers ORDER BY random() LIMIT ?", (n,)).fetchall()
         else:
-            # TODO: use log + DO NOT PRINT BINARY IP
-            print "Unauthorized connection from %s which does not start with %s" % (client_ip, self.network)
+            logging.warning("Unauthorized connection from %s which does not start with %s"
+                    % (utils.ipFromBin(client_ip), utils.ipFromBin(self.network.ljust(128, '0'))))
             raise RuntimeError
 
 if __name__ == "__main__":

tunnel.py

-import os, random, traceback, time, struct, subprocess, operator, math
+import os, random, traceback, time, struct, subprocess, operator, math, logging
 import plib, utils, db
 
-log = None
 smooth = 0.3     # this is used to smooth the traffic sampling. Lower value
                  # mean more smooth
 protected = 0.2  # ratio of the tunnels protected against kill because they are
@@ -30,8 +29,8 @@ class Connection:
     def refresh(self):
         # Check that the connection is alive
         if self.process.poll() != None:
-            utils.log('Connection with %s has failed with return code %s'
-                     % (self._prefix, self.process.returncode), 3)
+            logging.info('Connection with %s has failed with return code %s'
+                     % (self._prefix, self.process.returncode))
             return False
 
         # self._updateBandwidth()
@@ -60,14 +59,14 @@ class Connection:
                 else:
                     self.bandwidth = bw
 
-                utils.log('New bandwidth calculated on iface %s : %s' %
-                        (self.iface, self.bandwidth), 4)
+                logging.debug('New bandwidth calculated on iface %s : %s' %
+                        (self.iface, self.bandwidth))
 
             self._last_trafic_update = t
             self._last_trafic = trafic
-        except IOError:  # This just means that the interface is downs
-            utils.log('Unable to calculate bandwidth on iface %s' %
-                self.iface, 4)
+        except IOError:  # This just means that the interface is down
+            logging.debug('Unable to calculate bandwidth on iface %s' %
+                self.iface)
 
 
 class TunnelManager:
@@ -94,12 +93,12 @@ class TunnelManager:
         self._refresh_count = int(math.ceil(refresh_rate * self._client_count))
 
     def refresh(self):
-        utils.log('Refreshing the tunnels...', 2)
+        logging.info('Refreshing the tunnels...')
         self._cleanDeads()
         self._countRoutes()
         self._removeSomeTunnels()
         self._makeNewTunnels()
-        utils.log('Tunnels refreshed', 2)
+        logging.debug('Tunnels refreshed')
         self.next_refresh = time.time() + self._refresh_time
 
     def _cleanDeads(self):
@@ -120,7 +119,8 @@ class TunnelManager:
             self._kill(prefix)
 
     def _kill(self, prefix):
-        utils.log('Killing the connection with %s...' % (prefix,), 2)
+        logging.info('Killing the connection with %s/%u...'
+                % (hex(int(prefix,2))[2:], len(prefix)))
         connection = self._connection_dict.pop(prefix)
         try:
             connection.process.terminate()
@@ -130,16 +130,18 @@ class TunnelManager:
         self.free_interface_set.add(connection.iface)
         self._peer_db.unusePeer(prefix)
         del self._iface_to_prefix[connection.iface]
-        utils.log('Connection with %s killed' % (prefix,), 2)
+        logging.trace('Connection with %s/%u killed'
+                % (hex(int(prefix,2))[2:], len(prefix)))
 
     def _makeNewTunnels(self):
         i = 0
-        utils.log('Trying to make %i new tunnels...' %
-                (self._client_count - len(self._connection_dict)), 5)
+        logging.trace('Trying to make %i new tunnels...' %
+                (self._client_count - len(self._connection_dict)))
         try:
             for prefix, address in self._peer_db.getUnusedPeers(
                     self._client_count - len(self._connection_dict)):
-                utils.log('Establishing a connection with %s' % prefix, 2)
+                logging.info('Establishing a connection with %s/%u' %
+                        (hex(int(prefix, 2))[2:], len(prefix)))
                 iface = self.free_interface_set.pop()
                 self._connection_dict[prefix] = Connection(address,
                         self._write_pipe, self._hello, iface,
@@ -147,15 +149,15 @@ class TunnelManager:
                 self._iface_to_prefix[iface] = prefix
                 self._peer_db.usePeer(prefix)
                 i += 1
-            utils.log('%u new tunnels established' % (i,), 3)
+            logging.trace('%u new tunnels established' % (i,))
         except KeyError:
-            utils.log("""Can't establish connection with %s
-                    : no available interface""" % prefix, 2)
+            logging.warning("""Can't establish connection with %s
+                              : no available interface""" % prefix)
         except Exception:
             traceback.print_exc()
 
     def _countRoutes(self):
-        utils.log('Starting to count the routes on each interface...', 3)
+        logging.debug('Starting to count the routes on each interface...')
         self._peer_db.clear_blacklist(0)
         for iface in self._iface_to_prefix.keys():
             self._connection_dict[self._iface_to_prefix[iface]].routes = 0
@@ -166,21 +168,21 @@ class TunnelManager:
             if ip.startswith(self._network):
                 iface = line[-1]
                 subnet_size = int(line[1], 16)
-                utils.log('Route on iface %s detected to %s/%s'
-                        % (iface, ip, subnet_size), 8)
+                logging.trace('Route on iface %s detected to %s/%s'
+                        % (iface, ip, subnet_size))
                 if iface in self._iface_to_prefix.keys():
                     self._connection_dict[self._iface_to_prefix[iface]].routes += 1
                 if iface in self._iface_list and self._net_len < subnet_size < 128:
                     prefix = ip[self._net_len:subnet_size]
-                    utils.log('A route to %s has been discovered on the LAN'
-                            % (prefix,), 3)
+                    logging.debug('A route to %s (%s) has been discovered on the LAN'
+                            % (hex(int(prefix), 2)[2:], prefix))
                     self._peer_db.blacklist(prefix, 0)
 
-        utils.log("Routes have been counted", 3)
+        logging.debug("Routes have been counted")
         for p in self._connection_dict.keys():
-            utils.log('Routes on iface %s : %s' % (
+            logging.trace('Routes on iface %s : %s' % (
                 self._connection_dict[p].iface,
-                self._connection_dict[p].routes), 5)
+                self._connection_dict[p].routes))
 
     def killAll(self):
         for prefix in self._connection_dict.keys():

upnpigd.py

@@ -32,7 +32,7 @@ class Forwarder:
         elif proto == 'tcp-server':
             upnp_proto = 'TCP'
         else:
-            utils.log('Unknown protocol : %s' % proto, 1)
+            logging.info('Unknown protocol : %s' % proto)
             raise RuntimeError
 
         # Choose a free port
@@ -46,13 +46,13 @@ class Forwarder:
             # Make the redirection
             if self._u.addportmapping(external_port, 'UDP', self._u.lanaddr,
                     int(local_port), 'Vifib openvpn server', ''):
-                utils.log('Forwarding %s:%s to %s:%s' % (self._external_ip,
-                        external_port, self._u.lanaddr, local_port), 3)
+                logging.debug('Forwarding %s:%s to %s:%s' % (self._external_ip,
+                        external_port, self._u.lanaddr, local_port))
                 self._rules.append((external_port, int(local_port), upnp_proto))
                 return (self._external_ip, str(external_port), proto)
 
     def refresh(self):
-        utils.log('Refreshing port forwarding', 3)
+        logging.debug('Refreshing port forwarding')
         for external_port, local_port, proto in self._rules:
             self._u.addportmapping(external_port, proto, self._u.lanaddr,
                     local_port, 'Vifib openvpn server', '')

vifibnet.py

 #!/usr/bin/env python
-import argparse, errno, os, select, subprocess, sqlite3, time
+import argparse, errno, os, select, subprocess, sqlite3, time, logging
 from argparse import ArgumentParser
 import db, plib, upnpigd, utils, tunnel
 
@@ -38,18 +38,19 @@ def getConfig():
     # General Configuration options
     _('--ip', default=None, dest='address', action='append', nargs=3,
             help='Ip address, port and protocol advertised to other vpn nodes')
+    _('--registry', required=True,
+            help="HTTP URL of the discovery peer server,"
+                 " with public host (default port: 80)")
     _('--peers-db-refresh', default=3600, type=int,
             help='the time (seconds) to wait before refreshing the peers db')
     _('-l', '--log', default='/var/log',
             help='Path to vifibnet logs directory')
     _('-s', '--state', default='/var/lib/vifibnet',
-            help='Path to VPN state directory')
+            help='Path to vifibnet state directory')
     _('-v', '--verbose', default=0, type=int,
             help='Defines the verbose level')
     _('-i', '--interface', action='append', dest='iface_list', default=[],
             help='Extra interface for LAN discovery')
-    _('--registry', required=True,
-            help="Complete public address of the discovery peer server")
 
     # Routing algorithm options
     _('--hello', type=int, default=15,
@@ -62,7 +63,7 @@ def getConfig():
     _('--pp', nargs=2, action='append',
             help='Port and protocol to be used by other peers to connect')
     _('--tunnel-refresh', default=300, type=int,
-            help='the time (seconds) to wait before changing the connections')
+            help='time (seconds) to wait before changing the connections')
     _('--dh', required=True,
             help='Path to dh file')
     _('--ca', required=True,
@@ -74,7 +75,7 @@ def getConfig():
     # args to be removed ?
     _('--connection-count', default=20, type=int,
             help='Number of tunnels')
-    _('--refresh-rate', default=0.05, type=float,
+    _('--refresh-ratio', default=0.05, type=float,
             help='''The ratio of connections to drop when refreshing the
                     connections''')
     # Openvpn options
@@ -94,24 +95,34 @@ def main():
     openvpn_args = ovpnArgs(config.openvpn_args, config.ca, config.cert,
                                                  config.key)
 
+    # Set logging
+    logging.basicConfig(level=logging.DEBUG,
+            format='%(asctime)s : %(message)s',
+            datefmt='%d-%m-%Y %H:%M:%S')
+    logging.addLevelName(5, 'TRACE')
+    logging.trace = lambda *args, **kw: logging.log(5, *args, **kw)
+    logging.trace("Configuration :\n%s" % config)
+
     # Set global variables
     tunnel.log = config.log
-    utils.verbose = plib.verbose = config.verbose
-
-    utils.log("Configuration :\n" + str(config), 5)
+    plib.verbose = config.verbose
 
     # Create and open read_only pipe to get server events
-    utils.log('Creating pipe for server events...', 3)
+    logging.info('Creating pipe for server events...')
     r_pipe, write_pipe = os.pipe()
     read_pipe = os.fdopen(r_pipe)
-    utils.log('Pipe created', 5)
+    logging.debug('Pipe created')
 
     # Init db and tunnels
     forwarder = None
     if manual:
-        utils.log('Detected manual external configuration', 3)
+        logging.info('Detected manual external configuration')
+        for c, s in ('udp', 'udp'), ('tcp-client', 'tcp-server'):
+            if len(list(x for x in config.address if x[2] == c)) \
+             < len(list(x for x in config.pp if x[1] == s)):
+                pass # XXX: warn user about probable misconfiguration
     else:
-        utils.log('Attempting automatic configuration via UPnP...', 4)
+        logging.info('Attempting automatic configuration via UPnP...')
         try:
             forwarder = upnpigd.Forwarder()
             config.address = []
@@ -120,14 +131,14 @@ def main():
                 if ext:
                     config.address.append(ext)
         except upnpigd.NoUPnPDevice:
-            utils.log('No upnp device found', 4)
+            logging.info('No upnp device found')
 
     peer_db = db.PeerManager(config.state, config.registry, config.key,
             config.peers_db_refresh, config.address, internal_ip, prefix,
             manual, config.pp, 200)
     tunnel_manager = tunnel.TunnelManager(write_pipe, peer_db, openvpn_args,
             config.hello, config.tunnel_refresh, config.connection_count,
-            config.refresh_rate, config.iface_list, network)
+            config.refresh_ratio, config.iface_list, network)
 
     # Launch routing protocol. WARNING : you have to be root to start babeld
     interface_list = ['vifibnet'] + list(tunnel_manager.free_interface_set) \
@@ -152,7 +163,7 @@ def main():
     try:
         try:
             while True:
-                utils.log('Sleeping ...', 2)
+                logging.info('Sleeping ...')
                 nextUpdate = min(tunnel_manager.next_refresh, peer_db.next_refresh)
                 if forwarder != None:
                     nextUpdate = min(nextUpdate, forwarder.next_refresh)
@@ -179,6 +190,7 @@ def main():
                 pass
     except sqlite3.Error:
         traceback.print_exc()
+        db_path = os.path.join(config.state, 'peers.db')
         os.rename(db_path, db_path + '.bak')
         os.execvp(sys.executable, sys.argv)
     except KeyboardInterrupt: