Commit fae2739f authored by Guillaume Bury's avatar Guillaume Bury

New log system, read README

parent 82df1543
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
......@@ -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 )
To be discussed:
Project name ? Resinet/resnet/rsnet
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)'Connecting to peers database...')
self._db = sqlite3.connect(os.path.join(db_dir_path, 'peers.db'),
utils.log('Database opened', 5)
logging.debug('Database opened')
utils.log('Preparing peers database...', 4)'Preparing peers database...')
self._db.execute("""CREATE TABLE IF NOT EXISTS peers (
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)'Clearing blacklist from flag %u' % flag)
self._db.execute("DELETE FROM blacklist WHERE flag = ?",
utils.log('Blacklist cleared', 5)'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)'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)'Refreshing the peers DB...')
utils.log('DB refreshed', 3)'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)'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)'Sending connection info to server...')
utils.log('Info sent', 5)
logging.debug('Info sent')
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)'Populating the peers DB...')
new_peer_list = self._proxy.getPeerList(self._db_size,
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)'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)'Getting Boot peer...')
proxy = xmlrpclib.ServerProxy(self._registry)
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:
......@@ -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 = ?",
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 = ?",
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 = ?",
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)'Incomming connection from %s' % (arg,))
elif script_type == 'client-disconnect':
utils.log('%s has disconnected' % (arg,), 3)'%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)'Received new external ip : %s'
% (external_ip,))
utils.log('Unknow message recieved from the openvpn pipe : '
+ msg, 1)
logging.debug('Unknow message recieved from the openvpn pipe : %s'
% msg)
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,
'--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',
'--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)'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 = args + interface_list
utils.log(args, 5)
logging.trace('%s' % args)
return subprocess.Popen(args, **kw)
......@@ -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''')
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 = ''
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):
......@@ -149,7 +150,7 @@ class main(object):
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,))
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:])
prefix, address = self.db.execute("""SELECT prefix, address
FROM peers WHERE prefix = ?""", (bootpeer,))
except StopIteration:
prefix, address = self._randomPeer()
prefix, address = self.db.execute("""SELECT prefix, address
FROM peers ORDER BY random() LIMIT 1""")
prefix, address = self._randomPeer()
r, w = os.pipe()
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
print "Unauthorized connection from %s which does not start with %s" % (client_ip,
logging.warning("Unauthorized connection from %s which does not start with %s"
% (utils.ipFromBin(client_ip), utils.ipFromBin(, '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()
print "Unauthorized connection from %s which does not start with %s" % (client_ip,
logging.warning("Unauthorized connection from %s which does not start with %s"
% (utils.ipFromBin(client_ip), utils.ipFromBin(, '0'))))
raise RuntimeError
if __name__ == "__main__":
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)'Connection with %s has failed with return code %s'
% (self._prefix, self.process.returncode))
return False
# self._updateBandwidth()
......@@ -60,14 +59,14 @@ class Connection:
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' %
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)'Refreshing the tunnels...')
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:
def _kill(self, prefix):
utils.log('Killing the connection with %s...' % (prefix,), 2)'Killing the connection with %s/%u...'
% (hex(int(prefix,2))[2:], len(prefix)))
connection = self._connection_dict.pop(prefix)
......@@ -130,16 +130,18 @@ class TunnelManager:
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)))
for prefix, address in self._peer_db.getUnusedPeers(
self._client_count - len(self._connection_dict)):
utils.log('Establishing a connection with %s' % prefix, 2)'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
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:
def _countRoutes(self):
utils.log('Starting to count the routes on each interface...', 3)
logging.debug('Starting to count the routes on each interface...')
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].routes), 5)
def killAll(self):
for prefix in self._connection_dict.keys():
......@@ -32,7 +32,7 @@ class Forwarder:
elif proto == 'tcp-server':
upnp_proto = 'TCP'
utils.log('Unknown protocol : %s' % proto, 1)'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', '')
#!/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
# Openvpn options
......@@ -94,24 +95,34 @@ def main():
openvpn_args = ovpnArgs(config.openvpn_args,, config.cert,
# Set logging
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)'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)'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
utils.log('Attempting automatic configuration via UPnP...', 4)'Attempting automatic configuration via UPnP...')
forwarder = upnpigd.Forwarder()
config.address = []
......@@ -120,14 +131,14 @@ def main():
if ext:
except upnpigd.NoUPnPDevice:
utils.log('No upnp device found', 4)'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():
while True:
utils.log('Sleeping ...', 2)'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():
except sqlite3.Error:
db_path = os.path.join(config.state, 'peers.db')
os.rename(db_path, db_path + '.bak')
os.execvp(sys.executable, sys.argv)
except KeyboardInterrupt:
Markdown is supported
0% or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment