From: Leandro Lucarella <llucax@gmail.com>
Date: Mon, 24 Dec 2007 05:24:38 +0000 (-0300)
Subject: Merge branch 'master' of git.llucax.com.ar:/var/lib/git/software/pymin into logging
X-Git-Url: https://git.llucax.com/software/pymin.git/commitdiff_plain/6e49be26bf70a6fcd4b29ffc8cb270edf2e3c500?hp=91cc87ccd8910e4bbeecf2981d6c07b8578b28c0

Merge branch 'master' of git.llucax.com.ar:/var/lib/git/software/pymin into logging

* 'master' of git.llucax.com.ar:/var/lib/git/software/pymin:
  Add protocol specification of firewall and nat commands.
  Added the protocol specification.
  Root class inyects ip forwrading in constructor.
  Added route handling capabilities and service restarting
  Fix so that when a device is brought back up, the routes
  Added support to hook services to IPHandler.
  Support for inactive devices added in IPHandler.

Conflicts:

	pymin/services/ip/__init__.py
---

diff --git a/config.py b/config.py
index a0b5498..7a9b604 100644
--- a/config.py
+++ b/config.py
@@ -1,5 +1,13 @@
 # vim: set et sts=4 sw=4 encoding=utf-8 :
 
+# First of all, we need to setup the logging framework
+import logging
+logging.basicConfig(
+        level   = logging.DEBUG,
+        format  = '%(asctime)s %(name)-24s %(levelname)-8s %(message)s',
+        datefmt = '%a, %d %b %Y %H:%M:%S',
+)
+
 from pymin.services import *
 from pymin.dispatcher import Handler
 from os.path import join
diff --git a/pymin/dispatcher.py b/pymin/dispatcher.py
index 24f0d1f..bde8603 100644
--- a/pymin/dispatcher.py
+++ b/pymin/dispatcher.py
@@ -8,6 +8,7 @@ and translates commands to functions/objects/methods.
 """
 
 import re
+import logging ; log = logging.getLogger('pymin.dispatcher')
 
 __ALL__ = ('Error', 'HandlerError', 'CommandNotFoundError', 'Handler',
             'Dispatcher', 'handler', 'is_handler', 'get_help')
@@ -434,6 +435,7 @@ class Dispatcher:
 
         See Dispatcher class documentation for more info.
         """
+        log.debug(u'Dispatcher(%r)', root)
         self.root = root
 
     def dispatch(self, route):
@@ -445,28 +447,44 @@ class Dispatcher:
 
         route - *unicode* string with the command route.
         """
+        log.debug('Dispatcher.dispatch(%r)', route)
         command = list()
         (route, kwargs) = parse_command(route)
+        log.debug(u'Dispatcher.dispatch: route=%r, kwargs=%r', route, kwargs)
         if not route:
+            log.debug(u'Dispatcher.dispatch: command not specified')
             raise CommandNotSpecifiedError()
         handler = self.root
         while not is_handler(handler):
+            log.debug(u'Dispatcher.dispatch: handler=%r, route=%r',
+                        handler, route)
             if len(route) is 0:
                 if isinstance(handler, Handler):
+                    log.debug(u'Dispatcher.dispatch: command is a handler')
                     raise CommandIsAHandlerError(command)
+                log.debug(u'Dispatcher.dispatch: command not found')
                 raise CommandNotFoundError(command)
             command.append(route[0])
+            log.debug(u'Dispatcher.dispatch: command=%r', command)
             if route[0] == 'parent':
+                log.debug(u'Dispatcher.dispatch: is parent => not found')
                 raise CommandNotFoundError(command)
             if not hasattr(handler, route[0].encode('utf-8')):
                 if isinstance(handler, Handler) and len(command) > 1:
+                    log.debug(u'Dispatcher.dispatch: command not in handler')
                     raise CommandNotInHandlerError(command)
+                log.debug(u'Dispatcher.dispatch: command not found')
                 raise CommandNotFoundError(command)
             handler = getattr(handler, route[0].encode('utf-8'))
             route = route[1:]
+        log.debug(u'Dispatcher.dispatch: %r is a handler, calling it with '
+                    u'route=%r, kwargs=%r', handler, route, kwargs)
         try:
+            r = handler(*route, **kwargs)
+            log.debug(u'Dispatcher.dispatch: handler returned %s', r)
             return handler(*route, **kwargs)
         except TypeError, e:
+            log.debug(u'Dispatcher.dispatch: type error (%r)', e)
             m = args_re.match(unicode(e))
             if m:
                 (quant, n_ok, n_bad)  = m.groups()
@@ -477,18 +495,29 @@ class Dispatcher:
                 pl = ''
                 if n_ok > 1:
                     pl = 's'
-                raise WrongArgumentsError(handler, u'takes %s %s argument%s, '
+                e = WrongArgumentsError(handler, u'takes %s %s argument%s, '
                             '%s given' % (quant, n_ok, pl, n_bad))
+                log.debug(u'Dispatcher.dispatch: wrong arguments (%r)', e)
+                raise e
             m = kw_re.match(unicode(e))
             if m:
                 (kw,)  = m.groups()
-                raise WrongArgumentsError(handler,
+                e = WrongArgumentsError(handler,
                         u'got an unexpected keyword argument %s' % kw)
+                log.debug(u'Dispatcher.dispatch: wrong arguments (%r)', e)
+                raise e
+            log.debug(u'Dispatcher.dispatch: some other TypeError, re-raising')
             raise
 
 
 if __name__ == '__main__':
 
+    logging.basicConfig(
+        level   = logging.DEBUG,
+        format  = '%(asctime)s %(levelname)-8s %(message)s',
+        datefmt = '%H:%M:%S',
+    )
+
     @handler(u"test: Print all the arguments, return nothing")
     def test_func(*args):
         print 'func:', args
diff --git a/pymin/eventloop.py b/pymin/eventloop.py
index 86b8932..c9f6ade 100644
--- a/pymin/eventloop.py
+++ b/pymin/eventloop.py
@@ -10,6 +10,7 @@ import select
 import errno
 import signal
 from select import POLLIN, POLLPRI, POLLERR
+import logging ; log = logging.getLogger('pymin.eventloop')
 
 __ALL__ = ('EventLoop', 'LoopInterruptedError')
 
@@ -93,6 +94,8 @@ class EventLoop:
 
         See EventLoop class documentation for more info.
         """
+        log.debug(u'EventLoop(%r, %r, %r, %r)', file, handler,
+                    timer, timer_handler)
         self.poll = select.poll()
         self._stop = False
         self.__register(file)
@@ -134,6 +137,7 @@ class EventLoop:
         The event loop will be interrupted as soon as the current handler
         finishes.
         """
+        log.debug(u'EventLoop.stop()')
         self._stop = True
 
     def loop(self, once=False):
@@ -142,6 +146,7 @@ class EventLoop:
         Wait for events and handle then when they arrive. If once is True,
         then only 1 event is processed and then this method returns.
         """
+        log.debug(u'EventLoop.loop(%s)', once)
         # Flag modified by the signal handler
         global timeout
         # If we use a timer, we set up the signal
@@ -151,6 +156,7 @@ class EventLoop:
             signal.alarm(self.timer)
         while True:
             try:
+                log.debug(u'EventLoop.loop: polling')
                 res = self.poll.poll()
             except select.error, e:
                 # The error is not an interrupt caused by the alarm, then raise
@@ -158,14 +164,17 @@ class EventLoop:
                     raise LoopInterruptedError(e)
             # There was a timeout, so execute the timer handler
             if timeout:
+                log.debug(u'EventLoop.loop: timer catched, handling...')
                 timeout = False
                 self.handle_timer()
                 signal.alarm(self.timer)
             # Not a timeout, execute the regular handler
             else:
+                log.debug(u'EventLoop.loop: no timeout, handle event')
                 self.handle()
             # Look if we have to stop
             if self._stop or once:
+                log.debug(u'EventLoop.loop: stopped')
                 self._stop = False
                 break
 
@@ -179,6 +188,12 @@ class EventLoop:
 
 if __name__ == '__main__':
 
+    logging.basicConfig(
+        level   = logging.DEBUG,
+        format  = '%(asctime)s %(levelname)-8s %(message)s',
+        datefmt = '%H:%M:%S',
+    )
+
     import os
     import time
 
diff --git a/pymin/pymindaemon.py b/pymin/pymindaemon.py
index 8ed3f15..a65f19c 100644
--- a/pymin/pymindaemon.py
+++ b/pymin/pymindaemon.py
@@ -10,6 +10,7 @@ command-line.
 
 import signal
 import socket
+import logging ; log = logging.getLogger('pymin.pymindaemon')
 
 from pymin.dispatcher import handler
 from pymin import dispatcher
@@ -42,6 +43,7 @@ class PyminDaemon(eventloop.EventLoop):
 
         See PyminDaemon class documentation for more info.
         """
+        log.debug(u'PyminDaemon(%r, %r, %r)', root, bind_addr, timer)
         # Create and bind socket
         sock = socket.socket(socket.AF_INET, socket.SOCK_DGRAM)
         sock.setsockopt(socket.SOL_SOCKET, socket.SO_REUSEADDR, 1)
@@ -53,10 +55,12 @@ class PyminDaemon(eventloop.EventLoop):
         self.dispatcher = dispatcher.Dispatcher(root)
         # Signal handling
         def quit(signum, frame):
-            print "Shuting down ..."
+            log.debug(u'PyminDaemon quit() handler: signal %r', signum)
+            log.info(u'Shutting down...')
             self.stop() # tell main event loop to stop
         def reload_config(signum, frame):
-            print "Reloading configuration..."
+            log.debug(u'PyminDaemon reload_config() handler: signal %r', signum)
+            log.info(u'Reloading configuration...')
             # TODO iterate handlers list propagating reload action
         signal.signal(signal.SIGINT, quit)
         signal.signal(signal.SIGTERM, quit)
@@ -65,6 +69,7 @@ class PyminDaemon(eventloop.EventLoop):
     def handle(self):
         r"handle() -> None :: Handle incoming events using the dispatcher."
         (msg, addr) = self.file.recvfrom(65535)
+        log.debug(u'PyminDaemon.handle: message %r from %r', msg, addr)
         try:
             result = self.dispatcher.dispatch(unicode(msg, 'utf-8'))
             if result is not None:
@@ -76,12 +81,13 @@ class PyminDaemon(eventloop.EventLoop):
         except Exception, e:
             import traceback
             result = u'Internal server error\n'
-            traceback.print_exc() # TODO logging!
             response = u'ERROR '
+            log.exception(u'PyminDaemon.handle: unhandled exception')
         if result is None:
             response += u'0\n'
         else:
             response += u'%d\n%s' % (len(result), result)
+        log.debug(u'PyminDaemon.handle: response %r to %r', response, addr)
         self.file.sendto(response.encode('utf-8'), addr)
 
     def handle_timer(self):
@@ -90,13 +96,21 @@ class PyminDaemon(eventloop.EventLoop):
 
     def run(self):
         r"run() -> None :: Run the event loop (shortcut to loop())"
+        log.debug(u'PyminDaemon.loop()')
         try:
             return self.loop()
         except eventloop.LoopInterruptedError, e:
+            log.debug(u'PyminDaemon.loop: interrupted')
             pass
 
 if __name__ == '__main__':
 
+    logging.basicConfig(
+        level   = logging.DEBUG,
+        format  = '%(asctime)s %(levelname)-8s %(message)s',
+        datefmt = '%H:%M:%S',
+    )
+
     class Root(dispatcher.Handler):
         @handler(u"Print all the arguments, return nothing.")
         def test(self, *args):
diff --git a/pymin/services/dhcp/__init__.py b/pymin/services/dhcp/__init__.py
index de1515b..51f7ecb 100644
--- a/pymin/services/dhcp/__init__.py
+++ b/pymin/services/dhcp/__init__.py
@@ -1,6 +1,7 @@
 # vim: set encoding=utf-8 et sw=4 sts=4 :
 
 from os import path
+import logging ; log = logging.getLogger('pymin.services.dhcp')
 
 from pymin.seqtools import Sequence
 from pymin.dispatcher import Handler, handler, HandlerError
@@ -84,6 +85,7 @@ class DhcpHandler(Restorable, ConfigWriter, ReloadHandler, TransactionalHandler,
 
     def __init__(self, pickle_dir='.', config_dir='.'):
         r"Initialize DhcpHandler object, see class documentation for details."
+        log.debug(u'DhcpHandler(%r, %r)', pickle_dir, config_dir)
         self._persistent_dir = pickle_dir
         self._config_writer_cfg_dir = config_dir
         self._config_build_templates()
@@ -96,6 +98,12 @@ class DhcpHandler(Restorable, ConfigWriter, ReloadHandler, TransactionalHandler,
 
 if __name__ == '__main__':
 
+    logging.basicConfig(
+        level   = logging.DEBUG,
+        format  = '%(asctime)s %(levelname)-8s %(message)s',
+        datefmt = '%H:%M:%S',
+    )
+
     import os
 
     h = DhcpHandler()
diff --git a/pymin/services/dns/__init__.py b/pymin/services/dns/__init__.py
index 9324afb..f57386c 100644
--- a/pymin/services/dns/__init__.py
+++ b/pymin/services/dns/__init__.py
@@ -3,6 +3,7 @@
 # TODO COMMENT
 from os import path
 from os import unlink
+import logging ; log = logging.getLogger('pymin.services.dns')
 
 from pymin.seqtools import Sequence
 from pymin.dispatcher import handler, HandlerError, Handler
@@ -105,6 +106,7 @@ class DnsHandler(Restorable, ConfigWriter, InitdHandler, TransactionalHandler,
 
     def __init__(self, pickle_dir='.', config_dir='.'):
         r"Initialize DnsHandler object, see class documentation for details."
+        log.debug(u'DnsHandler(%r, %r)', pickle_dir, config_dir)
         self._persistent_dir = pickle_dir
         self._config_writer_cfg_dir = config_dir
         self._update = False
@@ -123,10 +125,14 @@ class DnsHandler(Restorable, ConfigWriter, InitdHandler, TransactionalHandler,
 
     def _write_config(self):
         r"_write_config() -> None :: Generate all the configuration files."
+        log.debug(u'DnsHandler._write_config()')
         delete_zones = list()
         for a_zone in self.zones.values():
+            log.debug(u'DnsHandler._write_config: processing zone %s', a_zone)
             if a_zone._update or a_zone._add:
                 if not a_zone._add and self._service_running:
+                    log.debug(u'DnsHandler._write_config: zone updated and '
+                                u'the service is running, freezing zone')
                     call(('rndc', 'freeze', a_zone.name))
                 vars = dict(
                     zone = a_zone,
@@ -138,18 +144,22 @@ class DnsHandler(Restorable, ConfigWriter, InitdHandler, TransactionalHandler,
                                             self._zone_filename(a_zone), vars)
                 a_zone._update = False
                 if not a_zone._add and self._service_running:
+                    log.debug(u'DnsHandler._write_config: unfreezing zone')
                     call(('rndc', 'thaw', a_zone.name))
                 else :
                     self._update = True
                     a_zone._add = False
             if a_zone._delete:
                 #borro el archivo .zone
+                log.debug(u'DnsHandler._write_config: zone deleted, removing '
+                            u'the file %r', self._zone_filename(a_zone))
                 try:
                     self._update = True
                     unlink(self._zone_filename(a_zone))
                 except OSError:
                     #la excepcion pude darse en caso que haga un add de una zona y
                     #luego el del, como no hice commit, no se crea el archivo
+                    log.debug(u'DnsHandler._write_config: file not found')
                     pass
                 delete_zones.append(a_zone.name)
         #borro las zonas
@@ -164,19 +174,28 @@ class DnsHandler(Restorable, ConfigWriter, InitdHandler, TransactionalHandler,
 
     # HACK!!!!
     def handle_timer(self):
+        log.debug(u'DnsHandler.handle_timer()')
         import subprocess
         p = subprocess.Popen(('pgrep', '-f', '/usr/sbin/named'),
                                 stdout=subprocess.PIPE)
         pid = p.communicate()[0]
         if p.returncode == 0 and len(pid) > 0:
+            log.debug(u'DnsHandler.handle_timer: pid present, running')
             self._service_running = True
         else:
+            log.debug(u'DnsHandler.handle_timer: pid absent, NOT running')
             self._service_running = False
 
 
 
 if __name__ == '__main__':
 
+    logging.basicConfig(
+        level   = logging.DEBUG,
+        format  = '%(asctime)s %(levelname)-8s %(message)s',
+        datefmt = '%H:%M:%S',
+    )
+
     dns = DnsHandler();
 
     dns.set('isp_dns1','la_garcha.com')
diff --git a/pymin/services/firewall/__init__.py b/pymin/services/firewall/__init__.py
index 06b4191..8809235 100644
--- a/pymin/services/firewall/__init__.py
+++ b/pymin/services/firewall/__init__.py
@@ -4,6 +4,7 @@
 # of using script templates.
 
 from os import path
+import logging ; log = logging.getLogger('pymin.services.firewall')
 
 from pymin.seqtools import Sequence
 from pymin.dispatcher import Handler, handler, HandlerError
@@ -93,6 +94,7 @@ class FirewallHandler(Restorable, ConfigWriter, ServiceHandler,
 
     def __init__(self, pickle_dir='.', config_dir='.'):
         r"Initialize the object, see class documentation for details."
+        log.debug(u'FirewallHandler(%r, %r)', pickle_dir, config_dir)
         self._persistent_dir = pickle_dir
         self._config_writer_cfg_dir = config_dir
         self._service_start = ('sh', path.join(self._config_writer_cfg_dir,
@@ -110,6 +112,12 @@ class FirewallHandler(Restorable, ConfigWriter, ServiceHandler,
 
 if __name__ == '__main__':
 
+    logging.basicConfig(
+        level   = logging.DEBUG,
+        format  = '%(asctime)s %(levelname)-8s %(message)s',
+        datefmt = '%H:%M:%S',
+    )
+
     import os
 
     fw_handler = FirewallHandler()
diff --git a/pymin/services/ip/__init__.py b/pymin/services/ip/__init__.py
index b1d50b2..a7e23cb 100644
--- a/pymin/services/ip/__init__.py
+++ b/pymin/services/ip/__init__.py
@@ -2,13 +2,15 @@
 
 from subprocess import Popen, PIPE
 from os import path
+import logging ; log = logging.getLogger('pymin.services.ip')
 
 from pymin.seqtools import Sequence
 from pymin.dispatcher import handler, HandlerError, Handler
 from pymin.services.util import Restorable, ConfigWriter, InitdHandler, \
                                 TransactionalHandler, SubHandler, call, \
                                 get_network_devices, ListComposedSubHandler, \
-                                DictComposedSubHandler, Device, Address, ExecutionError
+                                DictComposedSubHandler, Device, Address, \
+                                ExecutionError
 
 __ALL__ = ('IpHandler',)
 
@@ -150,6 +152,7 @@ class DeviceHandler(SubHandler):
     handler_help = u"Manage network devices"
 
     def __init__(self, parent):
+        log.debug(u'DeviceHandler(%r)', parent)
         # FIXME remove templates to execute commands
         from mako.template import Template
         self.parent = parent
@@ -159,11 +162,13 @@ class DeviceHandler(SubHandler):
 
     @handler(u'Bring the device up')
     def up(self, name):
+        log.debug(u'DeviceHandler.up(%r)', name)
         if name in self.parent.devices:
             call(self.device_template.render(dev=name, action='up'), shell=True)
             #bring up all the route asocitaed to the device
             for route in self.parent.devices[name].routes:
                 try:
+                    log.debug(u'IpHandler.up: adding %r', route)
                     call(self.parent._render_config('route_add', dict(
                             dev = name,
                             net_addr = route.net_addr,
@@ -172,27 +177,32 @@ class DeviceHandler(SubHandler):
                         )
                     ), shell=True)
                 except ExecutionError, e:
-                    print e
+                    log.debug(u'IpHandler.up: error adding %r -> %r', route, e)
             self.parent._bring_up_no_dev_routes()
             self.parent._restart_services()
         else:
+            log.debug(u'DeviceHandler.up: device not found')
             raise DeviceNotFoundError(name)
 
     @handler(u'Bring the device down')
     def down(self, name):
+        log.debug(u'DeviceHandler.down(%r)', name)
         if name in self.parent.devices:
             call(self.device_template.render(dev=name, action='down'), shell=True)
             self.parent._bring_up_no_dev_routes()
             self.parent._restart_services()
         else:
+            log.debug(u'DeviceHandler.up: device not found')
             raise DeviceNotFoundError(name)
 
     @handler(u'List all devices')
     def list(self):
+        log.debug(u'DeviceHandler.list()')
         return self.parent.devices.keys()
 
     @handler(u'Get information about a device')
     def show(self):
+        log.debug(u'DeviceHandler.show()')
         return self.parent.devices.items()
 
 class IpHandler(Restorable, ConfigWriter, TransactionalHandler):
@@ -213,6 +223,7 @@ class IpHandler(Restorable, ConfigWriter, TransactionalHandler):
 
     def __init__(self, pickle_dir='.', config_dir='.'):
         r"Initialize DhcpHandler object, see class documentation for details."
+        log.debug(u'IpHandler(%r, %r)', pickle_dir, config_dir)
         self._persistent_dir = pickle_dir
         self._config_writer_cfg_dir = config_dir
         self._config_build_templates()
@@ -227,15 +238,19 @@ class IpHandler(Restorable, ConfigWriter, TransactionalHandler):
 
     def _write_config(self):
         r"_write_config() -> None :: Execute all commands."
+        log.debug(u'IpHandler._write_config()')
         for device in self.devices.values():
+            log.debug(u'IpHandler._write_config: processing device %s', device)
             if device.active:
                 self._write_config_for_device(device)
         self._bring_up_no_dev_routes()
         self._write_hops()
 
     def _bring_up_no_dev_routes(self):
+        log.debug(u'IpHandler._bring_up_no_dev_routes()')
         for route in self.no_device_routes:
             try:
+                log.debug(u'IpHandler._bring_up_no_dev_routes: add %r', route)
                 call(self._render_config('route_add', dict(
                         dev = None,
                         net_addr = route.net_addr,
@@ -244,16 +259,20 @@ class IpHandler(Restorable, ConfigWriter, TransactionalHandler):
                     )
                 ), shell=True)
             except ExecutionError, e:
-                print e
+                log.debug(u'IpHandler._write_config: error flushing -> %r', e)
 
     def _write_hops(self):
         r"_write_hops() -> None :: Execute all hops."
+        log.debug(u'IpHandler._write_hops()')
         if self.hops:
+            log.debug(u'IpHandler._write_hops: we have hops: %r', self.hops)
             try:
+                log.debug(u'IpHandler._write_hops: flushing default hops')
                 call('ip route del default', shell=True)
             except ExecutionError, e:
-                print e
+                log.debug(u'IpHandler._write_hops: error adding -> %r', e)
             try:
+                log.debug(u'IpHandler._write_hops: configuring hops')
                 #get hops for active devices
                 active_hops = dict()
                 for h in self.hops:
@@ -265,23 +284,32 @@ class IpHandler(Restorable, ConfigWriter, TransactionalHandler):
                         )
                 ), shell=True)
             except ExecutionError, e:
-                print e
+                log.debug(u'IpHandler._write_hops: error adding -> %r', e)
 
     def _write_config_for_device(self, device):
-        r"_write_config_for_device(self, device) -> None :: Execute all commands for a device."
+        r"_write_config_for_device(self, device) -> None :: Execute commands."
+        log.debug(u'IpHandler._write_config_for_device()')
         try:
-            call(self._render_config('route_flush', dict(dev=device.name)), shell=True)
+            log.debug(u'IpHandler._write_config_for_device: flushing routes...')
+            call(self._render_config('route_flush', dict(dev=device.name)),
+                        shell=True)
         except ExecutionError, e:
-            print e
+            log.debug(u'IpHandler._write_config_for_device: error flushing '
+                        u'-> %r', e)
         try:
-            call(self._render_config('ip_flush', dict(dev=device.name)), shell=True)
+            log.debug(u'IpHandler._write_config_for_device: flushing addrs...')
+            call(self._render_config('ip_flush', dict(dev=device.name)),
+                        shell=True)
         except ExecutionError, e:
-            print e
+            log.debug(u'IpHandler._write_config_for_device: error flushing '
+                        u'-> %r', e)
         for address in device.addrs.values():
             broadcast = address.broadcast
             if broadcast is None:
                 broadcast = '+'
             try:
+                log.debug(u'IpHandler._write_config_for_device: adding %r',
+                            address)
                 call(self._render_config('ip_add', dict(
                     dev = device.name,
                     addr = address.ip,
@@ -291,9 +319,12 @@ class IpHandler(Restorable, ConfigWriter, TransactionalHandler):
                     )
                 ), shell=True)
             except ExecutionError, e:
-                print e
+                log.debug(u'IpHandler._write_config_for_device: error adding '
+                            u'-> %r', e)
         for route in device.routes:
             try:
+                log.debug(u'IpHandler._write_config_for_device: adding %r',
+                            route)
                 call(self._render_config('route_add', dict(
                         dev = device.name,
                         net_addr = route.net_addr,
@@ -302,18 +333,21 @@ class IpHandler(Restorable, ConfigWriter, TransactionalHandler):
                     )
                 ), shell=True)
             except ExecutionError, e:
-                print e
+                log.debug(u'IpHandler._write_config_for_device: error adding '
+                            u'-> %r', e)
 
     def handle_timer(self):
+        log.debug(u'IpHandler.handle_timer()')
         self.refresh_devices()
 
-
     def refresh_devices(self):
+        log.debug(u'IpHandler.update_devices()')
         devices = get_network_devices()
         #add not registered and active devices
         go_active = False
         for k,v in devices.items():
             if k not in self.devices:
+                log.debug(u'IpHandler.update_devices: adding %r', v)
                 self.devices[k] = v
             elif not self.devices[k].active:
                 self.active = True
@@ -328,6 +362,7 @@ class IpHandler(Restorable, ConfigWriter, TransactionalHandler):
         for k in self.devices.keys():
             go_down = False
             if k not in devices:
+                log.debug(u'IpHandler.update_devices: removing %s', k)
                 self.devices[k].active = False
                 go_down = True
             if go_down:
@@ -358,7 +393,13 @@ class IpHandler(Restorable, ConfigWriter, TransactionalHandler):
 
 if __name__ == '__main__':
 
-    ip = IpHanlder()
+    logging.basicConfig(
+        level   = logging.DEBUG,
+        format  = '%(asctime)s %(levelname)-8s %(message)s',
+        datefmt = '%H:%M:%S',
+    )
+
+    ip = IpHandler()
     print '----------------------'
     ip.hop.add('201.21.32.53','eth0')
     ip.hop.add('205.65.65.25','eth1')
diff --git a/pymin/services/nat/__init__.py b/pymin/services/nat/__init__.py
index a30f4c7..21a357e 100644
--- a/pymin/services/nat/__init__.py
+++ b/pymin/services/nat/__init__.py
@@ -1,6 +1,7 @@
 # vim: set encoding=utf-8 et sw=4 sts=4 :
 
 from os import path
+import logging ; log = logging.getLogger('pymin.services.nat')
 
 from pymin.seqtools import Sequence
 from pymin.dispatcher import Handler, handler, HandlerError
@@ -204,21 +205,27 @@ class NatHandler(Restorable, ConfigWriter, ReloadHandler, ServiceHandler,
     )
 
     def _service_start(self):
+        log.debug(u'NatHandler._service_start(): flushing nat table')
         call(('iptables', '-t', 'nat', '-F'))
         for (index, port) in enumerate(self.ports):
+            log.debug(u'NatHandler._service_start: adding port %r', port)
             call(['iptables'] + port.as_call_list(index+1))
         for (index, snat) in enumerate(self.snats):
+            log.debug(u'NatHandler._service_start: adding snat %r', snat)
             call(['iptables'] + snat.as_call_list(index+1))
         for (index, masq) in enumerate(self.masqs):
+            log.debug(u'NatHandler._service_start: adding masq %r', masq)
             call(['iptables'] + masq.as_call_list(index+1))
 
     def _service_stop(self):
+        log.debug(u'NatHandler._service_stop(): flushing nat table')
         call(('iptables', '-t', 'nat', '-F'))
 
     _service_restart = _service_start
 
     def __init__(self, pickle_dir='.'):
         r"Initialize the object, see class documentation for details."
+        log.debug(u'NatHandler(%r)', pickle_dir)
         self._persistent_dir = pickle_dir
         ServiceHandler.__init__(self)
         self.forward = PortForwardHandler(self)
@@ -228,6 +235,12 @@ class NatHandler(Restorable, ConfigWriter, ReloadHandler, ServiceHandler,
 
 if __name__ == '__main__':
 
+    logging.basicConfig(
+        level   = logging.DEBUG,
+        format  = '%(asctime)s %(levelname)-8s %(message)s',
+        datefmt = '%H:%M:%S',
+    )
+
     import os
 
     handler = NatHandler()
diff --git a/pymin/services/ppp/__init__.py b/pymin/services/ppp/__init__.py
index db2a535..1dce315 100644
--- a/pymin/services/ppp/__init__.py
+++ b/pymin/services/ppp/__init__.py
@@ -4,6 +4,7 @@ import os
 import subprocess
 from os import path
 from signal import SIGTERM
+import logging ; log = logging.getLogger('pymin.services.ppp')
 
 from pymin.seqtools import Sequence
 from pymin.dispatcher import Handler, handler, HandlerError
@@ -89,51 +90,69 @@ class PppHandler(Restorable, ConfigWriter, ReloadHandler, TransactionalHandler):
 
     def __init__(self, pickle_dir='.', config_dir='.'):
         r"Initialize Ppphandler object, see class documentation for details."
+        log.debug(u'PppHandler(%r, %r)', pickle_dir, config_dir)
         self._persistent_dir = pickle_dir
         self._config_writer_cfg_dir = config_dir
         self._config_build_templates()
         self._restore()
+        log.debug(u'PppHandler(): restoring connections...')
         for conn in self.conns.values():
             if conn._running:
+                log.debug(u'PppHandler(): starting connection %r', conn.name)
                 conn._running = False
                 self.start(conn.name)
         self.conn = ConnectionHandler(self)
 
     @handler(u'Start one or all the connections.')
     def start(self, name=None):
+        log.debug(u'PppHandler.start(%r)', name)
         names = [name]
         if name is None:
             names = self.conns.keys()
         for name in names:
             if name in self.conns:
                 if not self.conns[name]._running:
+                    log.debug(u'PppHandler.start: starting connection %r', name)
                     call(('pppd', 'call', name))
                     self.conns[name]._running = True
                     self._dump_attr('conns')
             else:
+                log.debug(u'PppHandler.start: connection not found')
                 raise ConnectionNotFoundError(name)
 
     @handler(u'Stop one or all the connections.')
     def stop(self, name=None):
+        log.debug(u'PppHandler.stop(%r)', name)
+        names = [name]
         names = [name]
         if name is None:
             names = self.conns.keys()
         for name in names:
             if name in self.conns:
                 if self.conns[name]._running:
-                    if path.exists('/var/run/ppp-' + name + '.pid'):
-                        pid = file('/var/run/ppp-' + name + '.pid').readline()
+                    pid_file = '/var/run/ppp-' + name + '.pid'
+                    log.debug(u'PppHandler.stop: getting pid from %r', pid_file)
+                    if path.exists(pid_file):
+                        pid = file(pid_file).readline()
+                        pid = int(pid.strip())
                         try:
-                            os.kill(int(pid.strip()), SIGTERM)
-                        except OSError:
-                            pass # XXX report error?
+                            log.debug(u'PppHandler.stop: killing pid %r', pid)
+                            os.kill(pid, SIGTERM)
+                        except OSError, e:
+                            log.debug(u'PppHandler.stop: error killing: %r', e)
+                    else:
+                        log.debug(u'PppHandler.stop: pid file not found')
                     self.conns[name]._running = False
                     self._dump_attr('conns')
+                else:
+                    log.debug(u'PppHandler.stop: connection not running')
             else:
+                log.debug(u'PppHandler.stop: connection not found')
                 raise ConnectionNotFoundError(name)
 
     @handler(u'Restart one or all the connections (even disconnected ones).')
     def restart(self, name=None):
+        log.debug(u'PppHandler.restart(%r)', name)
         names = [name]
         if name is None:
             names = self.conns.keys()
@@ -144,6 +163,7 @@ class PppHandler(Restorable, ConfigWriter, ReloadHandler, TransactionalHandler):
     @handler(u'Restart only one or all the already running connections.')
     def reload(self, name=None):
         r"reload() -> None :: Reload the configuration of the service."
+        log.debug(u'PppHandler.reload(%r)', name)
         names = [name]
         if name is None:
             names = self.conns.keys()
@@ -155,25 +175,32 @@ class PppHandler(Restorable, ConfigWriter, ReloadHandler, TransactionalHandler):
     @handler(u'Tell if the service is running.')
     def running(self, name=None):
         r"reload() -> None :: Reload the configuration of the service."
+        log.debug(u'PppHandler.running(%r)', name)
         if name is None:
             return [c.name for c in self.conns.values() if c._running]
         if name in self.conns:
             return int(self.conns[name]._running)
         else:
+            log.debug(u'PppHandler.running: connection not found')
             raise ConnectionNotFoundError(name)
 
     def handle_timer(self):
+        log.debug(u'PppHandler.handle_timer()')
         for c in self.conns.values():
+            log.debug(u'PppHandler.handle_timer: processing connection %r', c)
             p = subprocess.Popen(('pgrep', '-f', 'pppd call ' + c.name),
                                     stdout=subprocess.PIPE)
             pid = p.communicate()[0]
-            if p.wait() == 0 and len(pid) > 0:
+            if p.returncode == 0 and len(pid) > 0:
+                log.debug(u'PppHandler.handle_timer: pid present, running')
                 c._running = True
             else:
+                log.debug(u'PppHandler.handle_timer: pid absent, NOT running')
                 c._running = False
 
     def _write_config(self):
         r"_write_config() -> None :: Generate all the configuration files."
+        log.debug(u'PppHandler._write_config()')
         #guardo los pass que van el pap-secrets
         vars_pap = dict()
         for conn in self.conns.values():
@@ -197,6 +224,12 @@ class PppHandler(Restorable, ConfigWriter, ReloadHandler, TransactionalHandler):
 
 if __name__ == '__main__':
 
+    logging.basicConfig(
+        level   = logging.DEBUG,
+        format  = '%(asctime)s %(levelname)-8s %(message)s',
+        datefmt = '%H:%M:%S',
+    )
+
     p = PppHandler()
     p.conn.add('ppp_c','nico','nico',type='PPP',device='tty0')
     p.conn.add('pppoe_c','fede','fede',type='OE',device='tty1')
diff --git a/pymin/services/proxy/__init__.py b/pymin/services/proxy/__init__.py
index a02e6c5..1e24cd4 100644
--- a/pymin/services/proxy/__init__.py
+++ b/pymin/services/proxy/__init__.py
@@ -1,6 +1,7 @@
 # vim: set encoding=utf-8 et sw=4 sts=4 :
 
 from os import path
+import logging ; log = logging.getLogger('pymin.services.proxy')
 
 from pymin.seqtools import Sequence
 from pymin.dispatcher import Handler, handler, HandlerError
@@ -67,6 +68,7 @@ class ProxyHandler(Restorable, ConfigWriter, InitdHandler,
 
     def __init__(self, pickle_dir='.', config_dir='.'):
         r"Initialize DhcpHandler object, see class documentation for details."
+        log.debug(u'ProxyHandler(%r, %r)', pickle_dir, config_dir)
         self._persistent_dir = pickle_dir
         self._config_writer_cfg_dir = config_dir
         self._config_build_templates()
@@ -82,6 +84,12 @@ class ProxyHandler(Restorable, ConfigWriter, InitdHandler,
 
 if __name__ == '__main__':
 
+    logging.basicConfig(
+        level   = logging.DEBUG,
+        format  = '%(asctime)s %(levelname)-8s %(message)s',
+        datefmt = '%H:%M:%S',
+    )
+
     px = ProxyHandler()
     px.set('ip','192.66.66.66')
     px.set('port','666')
diff --git a/pymin/services/util.py b/pymin/services/util.py
index cb97815..69864cf 100644
--- a/pymin/services/util.py
+++ b/pymin/services/util.py
@@ -8,6 +8,7 @@ try:
     import cPickle as pickle
 except ImportError:
     import pickle
+import logging ; log = logging.getLogger('pymin.services.util')
 
 from pymin.dispatcher import Handler, handler, HandlerError, \
                                 CommandNotFoundError
@@ -210,17 +211,16 @@ def get_peers():
 def call(command, stdin=subprocess.PIPE, stdout=subprocess.PIPE,
             stderr=subprocess.PIPE, close_fds=True, universal_newlines=True,
             **kw):
+    log.debug(u'call(%r)', command)
     if DEBUG:
-        if not isinstance(command, basestring):
-            command = ' '.join(command)
-        print 'Executing command:', command
+        log.debug(u'call: not really executing, DEBUG mode')
         return
     try:
-        print 'Executing command:', command
-        r = subprocess.check_call(command, stdin=stdin, stdout=stdout,
+        subprocess.check_call(command, stdin=stdin, stdout=stdout,
                     stderr=stderr, close_fds=close_fds,
                     universal_newlines=universal_newlines, **kw)
     except Exception, e:
+        log.debug(u'call: Execution error %r', e)
         raise ExecutionError(command, e)
 
 class Persistent:
@@ -278,14 +278,22 @@ class Persistent:
 
     def _dump_attr(self, attrname):
         r"_dump_attr() -> None :: Dump a specific variable to a pickle file."
+        fname = self._pickle_filename(attrname)
+        attr = getattr(self, attrname)
+        log.debug(u'Persistent._dump_attr(%r) -> file=%r, value=%r',
+                attrname, fname, attr)
         f = file(self._pickle_filename(attrname), 'wb')
-        pickle.dump(getattr(self, attrname), f, 2)
+        pickle.dump(attr, f, 2)
         f.close()
 
     def _load_attr(self, attrname):
         r"_load_attr() -> object :: Load a specific pickle file."
-        f = file(self._pickle_filename(attrname))
-        setattr(self, attrname, pickle.load(f))
+        fname = self._pickle_filename(attrname)
+        f = file(fname)
+        attr = pickle.load(f)
+        log.debug(u'Persistent._load_attr(%r) -> file=%r, value=%r',
+                attrname, fname, attr)
+        setattr(self, attrname, attr)
         f.close()
 
     def _pickle_filename(self, name):
@@ -329,18 +337,27 @@ class Restorable(Persistent):
 
     def _restore(self):
         r"_restore() -> bool :: Restore persistent data or create a default."
+        log.debug(u'Restorable._restore()')
         try:
+            log.debug(u'Restorable._restore: trying to load...')
             self._load()
+            log.debug(u'Restorable._restore: load OK')
             return True
         except IOError:
+            log.debug(u'Restorable._restore: load FAILED, making defaults: %r',
+                        self._restorable_defaults)
             for (k, v) in self._restorable_defaults.items():
                 setattr(self, k, v)
             # TODO tener en cuenta servicios que hay que levantar y los que no
             if hasattr(self, 'commit'):
+                log.debug(u'Restorable._restore: commit() found, commiting...')
                 self.commit()
                 return False
+            log.debug(u'Restorable._restore: dumping new defaults...')
             self._dump()
             if hasattr(self, '_write_config'):
+                log.debug(u'Restorable._restore: _write_config() found, '
+                            u'writing new config...')
                 self._write_config()
             return False
 
@@ -404,6 +421,7 @@ class ConfigWriter:
 
     def _config_build_templates(self):
         r"_config_writer_templates() -> None :: Build the template objects."
+        log.debug(u'ConfigWriter.build_templates()')
         if isinstance(self._config_writer_files, basestring):
             self._config_writer_files = (self._config_writer_files,)
         if not hasattr(self, '_config_writer_templates') \
@@ -428,6 +446,8 @@ class ConfigWriter:
                 vars = dict()
         elif callable(vars):
             vars = vars(template_name)
+        log.debug(u'ConfigWriter._render_config: rendering template %r with '
+                    u'vars=%r', template_name, vars)
         return self._config_writer_templates[template_name].render(**vars)
 
     def _get_config_path(self, template_name, config_filename=None):
@@ -458,8 +478,11 @@ class ConfigWriter:
                 vars = dict()
         elif callable(vars):
             vars = vars(template_name)
-        f = file(self._get_config_path(template_name, config_filename), 'w')
+        fname = self._get_config_path(template_name, config_filename)
+        f = file(fname, 'w')
         ctx = Context(f, **vars)
+        log.debug(u'ConfigWriter._write_single_config: rendering template '
+                    u'%r with vars=%r to file %r', template_name, vars, fname)
         self._config_writer_templates[template_name].render_context(ctx)
         f.close()
 
@@ -496,23 +519,31 @@ class ServiceHandler(Handler, Restorable):
 
     def __init__(self, start=None, stop=None, restart=None, reload=None):
         r"Initialize the object, see the class documentation for details."
+        log.debug(u'ServiceHandler(%r, %r, %r, %r)', start, stop, restart,
+                    reload)
         for (name, action) in dict(start=start, stop=stop, restart=restart,
                                                     reload=reload).items():
             if action is not None:
-                setattr(self, '_service_%s' % name, action)
+                attr_name = '_service_%s' % name
+                log.debug(u'ServiceHandler: using %r as %s', attr_name, action)
+                setattr(self, attr_name, action)
         self._persistent_attrs = list(self._persistent_attrs)
         self._persistent_attrs.append('_service_running')
         if '_service_running' not in self._restorable_defaults:
             self._restorable_defaults['_service_running'] = False
+        log.debug(u'ServiceHandler: restoring service configuration...')
         self._restore()
         if self._service_running:
+            log.debug(u'ServiceHandler: service was running, starting it...')
             self._service_running = False
             self.start()
 
     @handler(u'Start the service.')
     def start(self):
         r"start() -> None :: Start the service."
+        log.debug(u'ServiceHandler.start()')
         if not self._service_running:
+            log.debug(u'ServiceHandler.start: not running, starting it...')
             if callable(self._service_start):
                 self._service_start()
             else:
@@ -522,8 +553,10 @@ class ServiceHandler(Handler, Restorable):
 
     @handler(u'Stop the service.')
     def stop(self):
+        log.debug(u'ServiceHandler.stop()')
         r"stop() -> None :: Stop the service."
         if self._service_running:
+            log.debug(u'ServiceHandler.stop: running, stoping it...')
             if callable(self._service_stop):
                 self._service_stop()
             else:
@@ -534,6 +567,7 @@ class ServiceHandler(Handler, Restorable):
     @handler(u'Restart the service.')
     def restart(self):
         r"restart() -> None :: Restart the service."
+        log.debug(u'ServiceHandler.restart()')
         if callable(self._service_restart):
             self._service_restart()
         else:
@@ -544,7 +578,9 @@ class ServiceHandler(Handler, Restorable):
     @handler(u'Reload the service config (without restarting, if possible).')
     def reload(self):
         r"reload() -> None :: Reload the configuration of the service."
+        log.debug(u'ServiceHandler.reload()')
         if self._service_running:
+            log.debug(u'ServiceHandler.reload: running, reloading...')
             if callable(self._service_reload):
                 self._service_reload()
             else:
@@ -553,6 +589,7 @@ class ServiceHandler(Handler, Restorable):
     @handler(u'Tell if the service is running.')
     def running(self):
         r"reload() -> None :: Reload the configuration of the service."
+        log.debug(u'ServiceHandler.running() -> %r', self._service_running)
         if self._service_running:
             return 1
         else:
@@ -569,6 +606,7 @@ class RestartHandler(Handler):
     @handler(u'Restart the service (alias to stop + start).')
     def restart(self):
         r"restart() -> None :: Restart the service calling stop() and start()."
+        log.debug(u'RestartHandler.restart()')
         self.stop()
         self.start()
 
@@ -582,7 +620,9 @@ class ReloadHandler(Handler):
     @handler(u'Reload the service config (alias to restart).')
     def reload(self):
         r"reload() -> None :: Reload the configuration of the service."
+        log.debug(u'ReloadHandler.reload()')
         if hasattr(self, '_service_running') and self._service_running:
+            log.debug(u'ReloadHandler.reload: running, reloading...')
             self.restart()
 
 class InitdHandler(ServiceHandler):
@@ -611,6 +651,7 @@ class InitdHandler(ServiceHandler):
 
     def __init__(self, initd_name=None, initd_dir=None):
         r"Initialize the object, see the class documentation for details."
+        log.debug(u'InitdHandler(%r, %r)', initd_name, initd_dir)
         if initd_name is not None:
             self._initd_name = initd_name
         if initd_dir is not None:
@@ -622,12 +663,16 @@ class InitdHandler(ServiceHandler):
         ServiceHandler.__init__(self, **actions)
 
     def handle_timer(self):
+        # TODO documentation
+        log.debug(u'InitdHandler.handle_timer(): self=%r', self)
         p = subprocess.Popen(('pgrep', '-f', self._initd_name),
                                 stdout=subprocess.PIPE)
         pid = p.communicate()[0]
         if p.returncode == 0 and len(pid) > 0:
+            log.debug(u'InitdHandler.handle_timer: pid present, running')
             self._service_running = True
         else:
+            log.debug(u'InitdHandler.handle_timer: pid absent, NOT running')
             self._service_running = False
 
 class TransactionalHandler(Handler):
@@ -649,18 +694,28 @@ class TransactionalHandler(Handler):
     @handler(u'Commit the changes (reloading the service, if necessary).')
     def commit(self):
         r"commit() -> None :: Commit the changes and reload the service."
+        log.debug(u'TransactionalHandler.commit()')
         if hasattr(self, '_dump'):
+            log.debug(u'TransactionalHandler.commit: _dump() present, '
+                        u'dumping...')
             self._dump()
         unchanged = False
         if hasattr(self, '_write_config'):
+            log.debug(u'TransactionalHandler.commit: _write_config() present, '
+                        u'writing config...')
             unchanged = self._write_config()
         if not unchanged and hasattr(self, 'reload'):
+            log.debug(u'TransactionalHandler.commit: reload() present, and'
+                        u'configuration changed, reloading...')
             self.reload()
 
     @handler(u'Discard all the uncommited changes.')
     def rollback(self):
         r"rollback() -> None :: Discard the changes not yet commited."
+        log.debug(u'TransactionalHandler.reload()')
         if hasattr(self, '_load'):
+            log.debug(u'TransactionalHandler.reload: _load() present, loading'
+                        u'pickled values...')
             self._load()
 
 class ParametersHandler(Handler):
@@ -684,33 +739,41 @@ class ParametersHandler(Handler):
 
     def __init__(self, attr=None):
         r"Initialize the object, see the class documentation for details."
+        log.debug(u'ParametersHandler(%r)', attr)
         if attr is not None:
             self._parameters_attr = attr
 
     @handler(u'Set a service parameter.')
     def set(self, param, value):
         r"set(param, value) -> None :: Set a service parameter."
+        log.debug(u'ParametersHandler.set(%r, %r)', param, value)
         if not param in self.params:
+            log.debug(u'ParametersHandler.set: parameter not found')
             raise ParameterNotFoundError(param)
         self.params[param] = value
         if hasattr(self, '_update'):
+            log.debug(u'ParametersHandler.set: _update found, setting to True')
             self._update = True
 
     @handler(u'Get a service parameter.')
     def get(self, param):
         r"get(param) -> None :: Get a service parameter."
+        log.debug(u'ParametersHandler.get(%r)', param)
         if not param in self.params:
+            log.debug(u'ParametersHandler.get: parameter not found')
             raise ParameterNotFoundError(param)
         return self.params[param]
 
     @handler(u'List all available service parameters.')
     def list(self):
         r"list() -> tuple :: List all the parameter names."
+        log.debug(u'ParametersHandler.list()')
         return self.params.keys()
 
     @handler(u'Get all service parameters, with their values.')
     def show(self):
         r"show() -> (key, value) tuples :: List all the parameters."
+        log.debug(u'ParametersHandler.show()')
         return self.params.items()
 
 class SubHandler(Handler):
@@ -724,6 +787,7 @@ class SubHandler(Handler):
 
     def __init__(self, parent):
         r"Initialize the object, see the class documentation for details."
+        log.debug(u'SubHandler(%r)', parent)
         self.parent = parent
 
 class ContainerSubHandler(SubHandler):
@@ -753,6 +817,7 @@ class ContainerSubHandler(SubHandler):
 
     def __init__(self, parent, attr=None, cls=None):
         r"Initialize the object, see the class documentation for details."
+        log.debug(u'ContainerSubHandler(%r, %r, %r)', parent, attr, cls)
         self.parent = parent
         if attr is not None:
             self._cont_subhandler_attr = attr
@@ -774,17 +839,21 @@ class ContainerSubHandler(SubHandler):
     @handler(u'Add a new item')
     def add(self, *args, **kwargs):
         r"add(...) -> None :: Add an item to the list."
+        log.debug(u'ContainerSubHandler.add(%r, %r)', args, kwargs)
         item = self._cont_subhandler_class(*args, **kwargs)
         if hasattr(item, '_add'):
+            log.debug(u'ContainerSubHandler.add: _add found, setting to True')
             item._add = True
         key = item
         if isinstance(self._attr(), dict):
             key = item.as_tuple()[0]
         # do we have the same item? then raise an error
         if key in self._vattr():
+            log.debug(u'ContainerSubHandler.add: allready exists')
             raise ItemAlreadyExistsError(item)
         # do we have the same item, but logically deleted? then update flags
         if key in self._attr():
+            log.debug(u'ContainerSubHandler.add: was deleted, undeleting it')
             index = key
             if not isinstance(self._attr(), dict):
                 index = self._attr().index(item)
@@ -801,39 +870,51 @@ class ContainerSubHandler(SubHandler):
     @handler(u'Update an item')
     def update(self, index, *args, **kwargs):
         r"update(index, ...) -> None :: Update an item of the container."
+        log.debug(u'ContainerSubHandler.update(%r, %r, %r)',
+                    index, args, kwargs)
         # TODO make it right with metaclasses, so the method is not created
         # unless the update() method really exists.
-        # TODO check if the modified item is the same of an existing one
         if not isinstance(self._attr(), dict):
             index = int(index) # TODO validation
         if not hasattr(self._cont_subhandler_class, 'update'):
+            log.debug(u'ContainerSubHandler.update: update() not found, '
+                        u"can't really update, raising command not found")
             raise CommandNotFoundError(('update',))
         try:
             item = self._vattr()[index]
             item.update(*args, **kwargs)
             if hasattr(item, '_update'):
+                log.debug(u'ContainerSubHandler.update: _update found, '
+                            u'setting to True')
                 item._update = True
         except LookupError:
+            log.debug(u'ContainerSubHandler.update: item not found')
             raise ItemNotFoundError(index)
 
     @handler(u'Delete an item')
     def delete(self, index):
         r"delete(index) -> None :: Delete an item of the container."
+        log.debug(u'ContainerSubHandler.delete(%r)', index)
         if not isinstance(self._attr(), dict):
             index = int(index) # TODO validation
         try:
             item = self._vattr()[index]
             if hasattr(item, '_delete'):
+                log.debug(u'ContainerSubHandler.delete: _delete found, '
+                            u'setting to True')
                 item._delete = True
             else:
                 del self._attr()[index]
             return item
         except LookupError:
+            log.debug(u'ContainerSubHandler.delete: item not found')
             raise ItemNotFoundError(index)
 
     @handler(u'Remove all items (use with care).')
     def clear(self):
         r"clear() -> None :: Delete all items of the container."
+        log.debug(u'ContainerSubHandler.clear()')
+        # FIXME broken really, no _delete attribute is setted :S
         if isinstance(self._attr(), dict):
             self._attr.clear()
         else:
@@ -842,16 +923,19 @@ class ContainerSubHandler(SubHandler):
     @handler(u'Get information about an item')
     def get(self, index):
         r"get(index) -> item :: List all the information of an item."
+        log.debug(u'ContainerSubHandler.get(%r)', index)
         if not isinstance(self._attr(), dict):
             index = int(index) # TODO validation
         try:
             return self._vattr()[index]
         except LookupError:
+            log.debug(u'ContainerSubHandler.get: item not found')
             raise ItemNotFoundError(index)
 
     @handler(u'Get information about all items')
     def show(self):
         r"show() -> list of items :: List all the complete items information."
+        log.debug(u'ContainerSubHandler.show()')
         if isinstance(self._attr(), dict):
             return self._attr().values()
         return self._vattr()
@@ -866,6 +950,7 @@ class ListSubHandler(ContainerSubHandler):
     @handler(u'Get how many items are in the list')
     def len(self):
         r"len() -> int :: Get how many items are in the list."
+        log.debug(u'ListContainerSubHandler.len()')
         return len(self._vattr())
 
 class DictSubHandler(ContainerSubHandler):
@@ -878,6 +963,7 @@ class DictSubHandler(ContainerSubHandler):
     @handler(u'List all the items by key')
     def list(self):
         r"list() -> tuple :: List all the item keys."
+        log.debug(u'DictContainerSubHandler.list()')
         return self._attr().keys()
 
 class ComposedSubHandler(SubHandler):
@@ -921,6 +1007,8 @@ class ComposedSubHandler(SubHandler):
 
     def __init__(self, parent, cont=None, attr=None, cls=None):
         r"Initialize the object, see the class documentation for details."
+        log.debug(u'ComposedSubHandler(%r, %r, %r, %r)',
+                    parent, cont, attr, cls)
         self.parent = parent
         if cont is not None:
             self._comp_subhandler_cont = cont
@@ -947,19 +1035,24 @@ class ComposedSubHandler(SubHandler):
     @handler(u'Add a new item')
     def add(self, cont, *args, **kwargs):
         r"add(cont, ...) -> None :: Add an item to the list."
+        log.debug(u'ComposedSubHandler.add(%r, %r, %r)', cont, args, kwargs)
         if not cont in self._cont():
+            log.debug(u'ComposedSubHandler.add: container not found')
             raise ContainerNotFoundError(cont)
         item = self._comp_subhandler_class(*args, **kwargs)
         if hasattr(item, '_add'):
+            log.debug(u'ComposedSubHandler.add: _add found, setting to True')
             item._add = True
         key = item
         if isinstance(self._attr(cont), dict):
             key = item.as_tuple()[0]
         # do we have the same item? then raise an error
         if key in self._vattr(cont):
+            log.debug(u'ComposedSubHandler.add: allready exists')
             raise ItemAlreadyExistsError(item)
         # do we have the same item, but logically deleted? then update flags
         if key in self._attr(cont):
+            log.debug(u'ComposedSubHandler.add: was deleted, undeleting it')
             index = key
             if not isinstance(self._attr(cont), dict):
                 index = self._attr(cont).index(item)
@@ -973,6 +1066,8 @@ class ComposedSubHandler(SubHandler):
             else:
                 self._attr(cont).append(item)
         if hasattr(self._cont()[cont], '_update'):
+            log.debug(u"ComposedSubHandler.add: container's _update found, "
+                        u'setting to True')
             self._cont()[cont]._update = True
 
     @handler(u'Update an item')
@@ -980,46 +1075,66 @@ class ComposedSubHandler(SubHandler):
         r"update(cont, index, ...) -> None :: Update an item of the container."
         # TODO make it right with metaclasses, so the method is not created
         # unless the update() method really exists.
-        # TODO check if the modified item is the same of an existing one
+        log.debug(u'ComposedSubHandler.update(%r, %r, %r, %r)',
+                    cont, index, args, kwargs)
         if not cont in self._cont():
+            log.debug(u'ComposedSubHandler.add: container not found')
             raise ContainerNotFoundError(cont)
         if not isinstance(self._attr(cont), dict):
             index = int(index) # TODO validation
         if not hasattr(self._comp_subhandler_class, 'update'):
+            log.debug(u'ComposedSubHandler.update: update() not found, '
+                        u"can't really update, raising command not found")
             raise CommandNotFoundError(('update',))
         try:
             item = self._vattr(cont)[index]
             item.update(*args, **kwargs)
             if hasattr(item, '_update'):
+                log.debug(u'ComposedSubHandler.update: _update found, '
+                            u'setting to True')
                 item._update = True
             if hasattr(self._cont()[cont], '_update'):
+                log.debug(u"ComposedSubHandler.add: container's _update found, "
+                            u'setting to True')
                 self._cont()[cont]._update = True
         except LookupError:
+            log.debug(u'ComposedSubHandler.update: item not found')
             raise ItemNotFoundError(index)
 
     @handler(u'Delete an item')
     def delete(self, cont, index):
         r"delete(cont, index) -> None :: Delete an item of the container."
+        log.debug(u'ComposedSubHandler.delete(%r, %r)', cont, index)
         if not cont in self._cont():
+            log.debug(u'ComposedSubHandler.add: container not found')
             raise ContainerNotFoundError(cont)
         if not isinstance(self._attr(cont), dict):
             index = int(index) # TODO validation
         try:
             item = self._vattr(cont)[index]
             if hasattr(item, '_delete'):
+                log.debug(u'ComposedSubHandler.delete: _delete found, '
+                            u'setting to True')
                 item._delete = True
             else:
                 del self._attr(cont)[index]
             if hasattr(self._cont()[cont], '_update'):
+                log.debug(u"ComposedSubHandler.add: container's _update found, "
+                            u'setting to True')
                 self._cont()[cont]._update = True
             return item
         except LookupError:
+            log.debug(u'ComposedSubHandler.delete: item not found')
             raise ItemNotFoundError(index)
 
     @handler(u'Remove all items (use with care).')
     def clear(self, cont):
         r"clear(cont) -> None :: Delete all items of the container."
+        # FIXME broken really, no item or container _delete attribute is
+        #       setted :S
+        log.debug(u'ComposedSubHandler.clear(%r)', cont)
         if not cont in self._cont():
+            log.debug(u'ComposedSubHandler.add: container not found')
             raise ContainerNotFoundError(cont)
         if isinstance(self._attr(cont), dict):
             self._attr(cont).clear()
@@ -1029,19 +1144,24 @@ class ComposedSubHandler(SubHandler):
     @handler(u'Get information about an item')
     def get(self, cont, index):
         r"get(cont, index) -> item :: List all the information of an item."
+        log.debug(u'ComposedSubHandler.get(%r, %r)', cont, index)
         if not cont in self._cont():
+            log.debug(u'ComposedSubHandler.add: container not found')
             raise ContainerNotFoundError(cont)
         if not isinstance(self._attr(cont), dict):
             index = int(index) # TODO validation
         try:
             return self._vattr(cont)[index]
         except LookupError:
+            log.debug(u'ComposedSubHandler.get: item not found')
             raise ItemNotFoundError(index)
 
     @handler(u'Get information about all items')
     def show(self, cont):
         r"show(cont) -> list of items :: List all the complete items information."
+        log.debug(u'ComposedSubHandler.show(%r)', cont)
         if not cont in self._cont():
+            log.debug(u'ComposedSubHandler.add: container not found')
             raise ContainerNotFoundError(cont)
         if isinstance(self._attr(cont), dict):
             return self._attr(cont).values()
@@ -1057,6 +1177,7 @@ class ListComposedSubHandler(ComposedSubHandler):
     @handler(u'Get how many items are in the list')
     def len(self, cont):
         r"len(cont) -> int :: Get how many items are in the list."
+        log.debug(u'ListComposedSubHandler.len(%r)', cont)
         if not cont in self._cont():
             raise ContainerNotFoundError(cont)
         return len(self._vattr(cont))
@@ -1071,6 +1192,7 @@ class DictComposedSubHandler(ComposedSubHandler):
     @handler(u'List all the items by key')
     def list(self, cont):
         r"list(cont) -> tuple :: List all the item keys."
+        log.debug(u'DictComposedSubHandler.list(%r)', cont)
         if not cont in self._cont():
             raise ContainerNotFoundError(cont)
         return self._attr(cont).keys()
@@ -1078,6 +1200,12 @@ class DictComposedSubHandler(ComposedSubHandler):
 
 if __name__ == '__main__':
 
+    logging.basicConfig(
+        level   = logging.DEBUG,
+        format  = '%(asctime)s %(levelname)-8s %(message)s',
+        datefmt = '%H:%M:%S',
+    )
+
     import sys
 
     # Execution tests
diff --git a/pymin/services/vpn/__init__.py b/pymin/services/vpn/__init__.py
index d251640..3b5046e 100644
--- a/pymin/services/vpn/__init__.py
+++ b/pymin/services/vpn/__init__.py
@@ -3,6 +3,7 @@
 import os
 import signal
 from os import path
+import logging ; log = logging.getLogger('pymin.services.vpn')
 
 
 from pymin.seqtools import Sequence
@@ -79,7 +80,8 @@ class VpnHandler(Restorable, ConfigWriter,
     _config_writer_tpl_dir = path.join(path.dirname(__file__), 'templates')
 
     def __init__(self,  pickle_dir='.', config_dir='/etc/tinc'):
-        DictSubHandler.__init__(self,self)
+        log.debug(u'VpnHandler(%r, %r)', pickle_dir, config_dir)
+        DictSubHandler.__init__(self, self)
         self._config_writer_cfg_dir = config_dir
         self._persistent_dir = pickle_dir
         self._config_build_templates()
@@ -88,75 +90,108 @@ class VpnHandler(Restorable, ConfigWriter,
 
     @handler('usage : add <vpn_name> <vpn_dst> <vpn_src_ip> <vpn_src_mask>')
     def add(self, vpn_src, vpn_dst, vpn_src_ip, vpn_src_mask):
-        if not vpn_src in self.vpns:
-            DictSubHandler.add(self,  vpn_src, vpn_dst, vpn_src_ip, vpn_src_mask, None, None)
-        elif vpn_src in self.vpns:
-            if self.vpns[vpn_src].dele :
+        log.debug(u'VpnHandler.add(%r, %r, %r, %r)', vpn_src, vpn_dst,
+                    vpn_src_ip, vpn_src_mask)
+        if vpn_src in self.vpns:
+            if self.vpns[vpn_src].dele:
+                log.debug(u'VpnHandler.add: deleted, undeleting')
                 self.vpns[vpn_src] = False
+        else:
+            DictSubHandler.add(self, vpn_src, vpn_dst, vpn_src_ip,
+                                vpn_src_mask, None, None)
 
     @handler('usage : delete <vpn_name>')
     def delete(self, vpn_src):
+        log.debug(u'VpnHandler.delete(%r)', vpn_src)
         if vpn_src in self.vpns:
             self.vpns[vpn_src].dele = True;
 
 
     @handler('usage: start <vpn_name>')
     def start(self, vpn_src):
+        log.debug(u'VpnHandler.start(%r)', vpn_src)
         if vpn_src in self.vpns:
             call(('tincd','--net='+ vpn_src))
 
     @handler('usage: stop <vpn_name>')
     def stop(self, vpn_src):
+        log.debug(u'VpnHandler.stop(%r)', vpn_src)
         if vpn_src in self.vpns:
-            if path.exists('/var/run/tinc.' + vpn_src + '.pid'):
-                pid = file('/var/run/tinc.' + vpn_src + '.pid').readline()
+            pid_file = '/var/run/tinc.' + vpn_src + '.pid'
+            log.debug(u'VpnHandler.stop: getting pid from %r', pid_file)
+            if path.exists(pid_file):
+                pid = file(pid_file).readline()
+                pid = int(pid.strip())
                 try:
-                    os.kill(int(pid.strip()), signal.SIGTERM)
+                    log.debug(u'VpnHandler.stop: killing pid %r', pid)
+                    os.kill(pid, signal.SIGTERM)
                 except OSError:
-                    pass # XXX report error?
+                    log.debug(u'VpnHandler.stop: error killing: %r', e)
+            else:
+                log.debug(u'VpnHandler.stop: pid file not found')
 
     def _write_config(self):
+        log.debug(u'VpnHandler._write_config()')
         for v in self.vpns.values():
+            log.debug(u'VpnHandler._write_config: processing %r', v)
             #chek whether it's been created or not.
             if not v.dele:
-                if v.pub_key is None :
+                if v.pub_key is None:
+                    log.debug(u'VpnHandler._write_config: new VPN, generating '
+                                'key...')
                     try:
-                        print 'douugh'
+                        log.debug(u'VpnHandler._write_config: creating dir %r',
+                                    path.join(self._config_writer_cfg_dir,
+                                                v.vpn_src ,'hosts'))
                         #first create the directory for the vpn
-                        call(('mkdir','-p', path.join(self._config_writer_cfg_dir, v.vpn_src ,'hosts')))
+                        call(('mkdir', '-p', path.join(
+                                            self._config_writer_cfg_dir,
+                                            v.vpn_src, 'hosts')))
                         #this command should generate 2 files inside the vpn
                         #dir, one rsa_key.priv and one rsa_key.pub
                         #for some reason debian does not work like this
-                        call(('tincd','-n', v.vpn_src,'-K','<','/dev/null'))
+                        # FIXME if the < /dev/null works, is magic!
+                        log.debug(u'VpnHandler._write_config: creating key...')
+                        call(('tincd', '-n', v.vpn_src, '-K', '<', '/dev/null'))
                         #open the created files and load the keys
-                        f = file(path.join(self._config_writer_cfg_dir, v.vpn_src , 'rsa_key.priv'), 'r')
+                        f = file(path.join(self._config_writer_cfg_dir,
+                                            v.vpn_src, 'rsa_key.priv'), 'r')
                         priv = f.read()
                         f.close()
-                        f = file(path.join(self._config_writer_cfg_dir, v.vpn_src ,'rsa_key.pub'), 'r')
+                        f = file(path.join(self._config_writer_cfg_dir,
+                                            v.vpn_src, 'rsa_key.pub'), 'r')
                         pub = f.read()
                         f.close()
                         v.pub_key = pub
                         v.priv_key = priv
                     except ExecutionError, e:
-                        print e
+                        log.debug(u'VpnHandler._write_config: error executing '
+                                    'the command: %r', e)
 
                 vars = dict(
                     vpn = v,
                 )
-                self._write_single_config('tinc.conf',path.join(v.vpn_src,'tinc.conf'),vars)
-                self._write_single_config('tinc-up',path.join(v.vpn_src,'tinc-up'),vars)
+                self._write_single_config('tinc.conf',
+                                path.join(v.vpn_src, 'tinc.conf'), vars)
+                self._write_single_config('tinc-up',
+                                path.join(v.vpn_src, 'tinc-up'), vars)
                 for h in v.hosts.values():
                     if not h.dele:
                         vars = dict(
                             host = h,
                         )
-                        self._write_single_config('host',path.join(v.vpn_src,'hosts',h.name),vars)
+                        self._write_single_config('host',
+                                path.join(v.vpn_src, 'hosts', h.name), vars)
                     else:
+                        log.debug(u'VpnHandler._write_config: removing...')
                         try:
-                            call(('rm','-f', path.join(v.vpn_src,'hosts',h.name)))
+                            # FIXME use os.unlink()
+                            call(('rm','-f',
+                                    path.join(v.vpn_src, 'hosts', h.name)))
                             del v.hosts[h.name]
                         except ExecutionError, e:
-                            print e
+                            log.debug(u'VpnHandler._write_config: error '
+                                    'removing files: %r', e)
             else:
                 #delete the vpn root at tinc dir
                 if path.exists('/etc/tinc/' + v.vpn_src):
@@ -166,7 +201,16 @@ class VpnHandler(Restorable, ConfigWriter,
 
 
 if __name__ == '__main__':
+
+    logging.basicConfig(
+        level   = logging.DEBUG,
+        format  = '%(asctime)s %(levelname)-8s %(message)s',
+        datefmt = '%H:%M:%S',
+    )
+
     v = VpnHandler()
     v.add('prueba','sarasa','192.168.0.188','255.255.255.0')
-    v.host.add('prueba', 'azazel' ,'192.168.0.77', '192.168.0.0','kjdhfkbdskljvkjblkbjeslkjbvkljbselvslberjhbvslbevlhb')
+    v.host.add('prueba', 'azazel' ,'192.168.0.77', '192.168.0.0',
+                'kjdhfkbdskljvkjblkbjeslkjbvkljbselvslberjhbvslbevlhb')
     v.commit()
+
diff --git a/pymin/services/vrrp/__init__.py b/pymin/services/vrrp/__init__.py
index 403cd36..4739c52 100644
--- a/pymin/services/vrrp/__init__.py
+++ b/pymin/services/vrrp/__init__.py
@@ -4,6 +4,7 @@ import os
 from os import path
 from signal import SIGTERM
 from subprocess import Popen, PIPE
+import logging ; log = logging.getLogger('pymin.services.vrrp')
 
 from pymin.seqtools import Sequence
 from pymin.dispatcher import Handler, handler, HandlerError
@@ -29,6 +30,7 @@ class VrrpHandler(Restorable, ParametersHandler, ReloadHandler, RestartHandler,
                             )
 
     def _service_start(self):
+        log.debug(u'VrrpHandler._service_start()')
         if self.params['prio'] != '':
             call(('vrrp', '-i', self.params['dev'], '-v', self.params['id'],
                     '-p', self.params['prio'], self.params['ipaddress']))
@@ -37,22 +39,34 @@ class VrrpHandler(Restorable, ParametersHandler, ReloadHandler, RestartHandler,
                     self.params['ipaddress']))
 
     def _service_stop(self):
+        log.debug(u'VrrpHandler._service_stop()')
         try:
             pid_filename = 'vrrpd_%(dev)s_%(id)s.pid' % self.params
-            pid = file(path.join(self._pid_dir, pid_filename )).read().strip()
-            os.kill(int(pid), SIGTERM)
-        except (IOError, OSError):
-            # TODO log
-            pass
+            log.debug(u'VrrpHandler._service_stop: getting pid from %r',
+                        pid_filename)
+            pid = file(path.join(self._pid_dir, pid_filename )).read()
+            pid = int(pid.strip())
+            log.debug(u'VrrpHandler._service_stop: killing pid %r', pid)
+            os.kill(pid, SIGTERM)
+        except (IOError, OSError), e:
+            log.debug(u'VrrpHandler._service_stop: error %r', e)
 
     def __init__(self, pickle_dir='.', config_dir='.', pid_dir='.'):
+        log.debug(u'VrrpHandler(%r, %r, $r)', pickle_dir, config_dir, pid_dir)
         self._persistent_dir = pickle_dir
         self._pid_dir = pid_dir
         ServiceHandler.__init__(self)
 
 
 if __name__ == '__main__':
+
+    logging.basicConfig(
+        level   = logging.DEBUG,
+        format  = '%(asctime)s %(levelname)-8s %(message)s',
+        datefmt = '%H:%M:%S',
+    )
+
     v = VrrpHandler()
-    v.set('prio','10')
+    v.set('prio', '10')
     v.commit()