From: Leandro Lucarella <llucax@gmail.com>
Date: Thu, 27 Dec 2007 15:53:10 +0000 (-0300)
Subject: Merge branch 'procman'
X-Git-Url: https://git.llucax.com/software/pymin.git/commitdiff_plain/55efba31a241826ed31597b14f2b5eb9efe808f1?hp=45d91d1b75b9aed9abbbae97ff962ab08f215177

Merge branch 'procman'

* procman:
  Bugfix: set the catched signal to None *after* calling the signal handler.
  Improve vrrp restorable defaults readability.
  Use procman.restart() to restart vrrp service.
  Add ProcessManager.restart() method to block until the restart is done.
  Use procman to manage vrrp service.
  Bugfix: raise a KeyError, don't return it.
  Bugfix: call ProcessInfo.stop() in the right way (without parameters).
  Bugfix: use self instead of an unbinded pi object when killing a process.
  Remove unused ProcessInfo.last_return attribute.
  Bugfix: use correct module for simbol ECHILD.
  Handle SIGCHLD in PyminDaemon.
  Add a global ProcessManager instance and functions to procman module.
  Implement timer in PyminDaemon using EventLoop signal handling.
  Support general signals handling in EventLoop.
  Replace time.sleep() for signal.pause() in the ProcessManager test.
  Improve ProcessManager to manage registerable named services.
  Add a ProcessManager class to manage processes.
  Improve ProcessManager to manage registerable named services.
  Add a ProcessManager class to manage processes.

Conflicts:

	pymin/eventloop.py
	pymin/pymindaemon.py
	pymin/services/vrrp/__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 fe3c4ec..0f72012 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')
 
@@ -95,6 +96,7 @@ class EventLoop:
 
         See EventLoop class documentation for more info.
         """
+        log.debug(u'EventLoop(%r, %r, %r)', file, handler, signals)
         self.poll = select.poll()
         self._stop = False
         self.__register(file)
@@ -156,6 +158,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):
@@ -164,10 +167,12 @@ 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)
         # List of pending signals
         global signals
         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 a signal, then raise
@@ -176,13 +181,16 @@ class EventLoop:
             # If we have signals to process, we just do it
             have_signals = bool(signals)
             while signals:
-                self.handle_signal(signals.pop(0))
+                signum = signals.pop(0)
+                log.debug(u'EventLoop.loop: processing signal %d...', signum)
+                self.handle_signal(signum)
             # No signals to process, execute the regular handler
             if not have_signals:
+                log.debug(u'EventLoop.loop: processing event...')
                 self.handle()
-            import os
             # Look if we have to stop
             if self._stop or once:
+                log.debug(u'EventLoop.loop: stopped')
                 self._stop = False
                 break
 
@@ -196,6 +204,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
 
@@ -205,7 +219,7 @@ if __name__ == '__main__':
 
     p = EventLoop(0, handle)
 
-    os.write(1, 'Say something once: ')
+    os.write(1, 'Say something once:\n')
     p.loop(once=True)
     os.write(1, 'Great!\n')
 
diff --git a/pymin/pymindaemon.py b/pymin/pymindaemon.py
index 3881857..067a727 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
@@ -43,6 +44,7 @@ class PyminDaemon(eventloop.EventLoop):
 
         See PyminDaemon class documentation for more info.
         """
+        log.debug(u'PyminDaemon(%r, %r, %r)', root, bind_addr, timer)
         # Timer timeout time
         self.timer = timer
         # Create and bind socket
@@ -51,10 +53,12 @@ class PyminDaemon(eventloop.EventLoop):
         sock.bind(bind_addr)
         # Signal handling
         def quit(loop, signum):
-            print "Shuting down ..."
+            log.debug(u'PyminDaemon quit() handler: signal %r', signum)
+            log.info(u'Shutting down...')
             loop.stop() # tell main event loop to stop
         def reload_config(loop, signum):
-            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
         def timer(loop, signum):
             loop.handle_timer()
@@ -76,6 +80,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:
@@ -87,12 +92,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):
@@ -101,6 +107,7 @@ class PyminDaemon(eventloop.EventLoop):
 
     def run(self):
         r"run() -> None :: Run the event loop (shortcut to loop())"
+        log.debug(u'PyminDaemon.loop()')
         # Start the timer
         self.handle_timer()
         signal.alarm(self.timer)
@@ -108,10 +115,17 @@ class PyminDaemon(eventloop.EventLoop):
         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 9fdfd1a..f13db3e 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 import procman
 from pymin.seqtools import Sequence
@@ -42,12 +43,14 @@ class VrrpHandler(Restorable, ParametersHandler, ReloadHandler, RestartHandler,
         return command
 
     def _service_start(self):
+        log.debug(u'VrrpHandler._service_start()')
         procinfo = procman.get('vrrp')
         procinfo.command = self._command
         procinfo.persist = self.params['persist']
         procman.start('vrrp')
 
     def _service_stop(self):
+        log.debug(u'VrrpHandler._service_stop()')
         procman.stop('vrrp')
 
     def _service_restart(self):
@@ -57,6 +60,7 @@ class VrrpHandler(Restorable, ParametersHandler, ReloadHandler, RestartHandler,
         procman.restart('vrrp')
 
     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
         procman.register('vrrp', None)
@@ -64,7 +68,14 @@ class VrrpHandler(Restorable, ParametersHandler, ReloadHandler, RestartHandler,
 
 
 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()