Add logging to pymin.services.util module.

diff --git a/config.py b/config.py
index 295a0fca67c4b82d43a33b4bb520b2a82cf3b36b..e16262d1ee09dcfdf84ae42b162738642df6b025 100644 (file)
--- a/config.py
+++ b/config.py
@@ -4,7 +4,7 @@
 import logging
 logging.basicConfig(
         level   = logging.DEBUG,
 import logging
 logging.basicConfig(
         level   = logging.DEBUG,

-        format  = '%(asctime)s %(name)-18s %(levelname)-8s %(message)s',
+        format  = '%(asctime)s %(name)-24s %(levelname)-8s %(message)s',

         datefmt = '%a, %d %b %Y %H:%M:%S',
 )
 
         datefmt = '%a, %d %b %Y %H:%M:%S',
 )
 

diff --git a/pymin/services/util.py b/pymin/services/util.py
index a7ec0e4dd906db025ca108421002cb0fb2d908b1..21afa63a15f8cbb362bdecacca531d4b51a81071 100644 (file)
--- a/pymin/services/util.py
+++ b/pymin/services/util.py
@@ -8,6 +8,7 @@ try:
     import cPickle as pickle
 except ImportError:
     import pickle
     import cPickle as pickle
 except ImportError:
     import pickle

+import logging ; log = logging.getLogger('pymin.services.util')

 
 from pymin.dispatcher import Handler, handler, HandlerError, \
                                 CommandNotFoundError
 
 from pymin.dispatcher import Handler, handler, HandlerError, \
                                 CommandNotFoundError


@@ -209,17 +210,16 @@ def get_peers():
 def call(command, stdin=subprocess.PIPE, stdout=subprocess.PIPE,
             stderr=subprocess.PIPE, close_fds=True, universal_newlines=True,
             **kw):
 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 DEBUG:

-        if not isinstance(command, basestring):
-            command = ' '.join(command)
-        print 'Executing command:', command
+        log.debug(u'call: not really executing, DEBUG mode')

         return
     try:
         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:
                     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:
         raise ExecutionError(command, e)
 
 class Persistent:


@@ -277,14 +277,22 @@ class Persistent:
 
     def _dump_attr(self, attrname):
         r"_dump_attr() -> None :: Dump a specific variable to a pickle file."
 
     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')
         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.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):
         f.close()
 
     def _pickle_filename(self, name):


@@ -328,18 +336,27 @@ class Restorable(Persistent):
 
     def _restore(self):
         r"_restore() -> bool :: Restore persistent data or create a default."
 
     def _restore(self):
         r"_restore() -> bool :: Restore persistent data or create a default."

+        log.debug(u'Restorable._restore()')

         try:
         try:

+            log.debug(u'Restorable._restore: trying to load...')

             self._load()
             self._load()

+            log.debug(u'Restorable._restore: load OK')

             return True
         except IOError:
             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'):
             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
                 self.commit()
                 return False

+            log.debug(u'Restorable._restore: dumping new defaults...')

             self._dump()
             if hasattr(self, '_write_config'):
             self._dump()
             if hasattr(self, '_write_config'):

+                log.debug(u'Restorable._restore: _write_config() found, '
+                            u'writing new config...')

                 self._write_config()
             return False
 
                 self._write_config()
             return False
 


@@ -403,6 +420,7 @@ class ConfigWriter:
 
     def _config_build_templates(self):
         r"_config_writer_templates() -> None :: Build the template objects."
 
     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') \
         if isinstance(self._config_writer_files, basestring):
             self._config_writer_files = (self._config_writer_files,)
         if not hasattr(self, '_config_writer_templates') \


@@ -427,6 +445,8 @@ class ConfigWriter:
                 vars = dict()
         elif callable(vars):
             vars = vars(template_name)
                 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):
         return self._config_writer_templates[template_name].render(**vars)
 
     def _get_config_path(self, template_name, config_filename=None):


@@ -457,8 +477,11 @@ class ConfigWriter:
                 vars = dict()
         elif callable(vars):
             vars = vars(template_name)
                 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)
         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()
 
         self._config_writer_templates[template_name].render_context(ctx)
         f.close()
 


@@ -495,23 +518,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."
 
     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:
         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
         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:
         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."
             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:
         if not self._service_running:

+            log.debug(u'ServiceHandler.start: not running, starting it...')

             if callable(self._service_start):
                 self._service_start()
             else:
             if callable(self._service_start):
                 self._service_start()
             else:


@@ -521,8 +552,10 @@ class ServiceHandler(Handler, Restorable):
 
     @handler(u'Stop the service.')
     def stop(self):
 
     @handler(u'Stop the service.')
     def stop(self):

+        log.debug(u'ServiceHandler.stop()')

         r"stop() -> None :: Stop the service."
         if self._service_running:
         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:
             if callable(self._service_stop):
                 self._service_stop()
             else:


@@ -533,6 +566,7 @@ class ServiceHandler(Handler, Restorable):
     @handler(u'Restart the service.')
     def restart(self):
         r"restart() -> None :: Restart the service."
     @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:
         if callable(self._service_restart):
             self._service_restart()
         else:


@@ -543,7 +577,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."
     @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:
         if self._service_running:

+            log.debug(u'ServiceHandler.reload: running, reloading...')

             if callable(self._service_reload):
                 self._service_reload()
             else:
             if callable(self._service_reload):
                 self._service_reload()
             else:


@@ -552,6 +588,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."
     @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:
         if self._service_running:
             return 1
         else:


@@ -568,6 +605,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()."
     @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()
 
         self.stop()
         self.start()
 


@@ -581,7 +619,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."
     @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:
         if hasattr(self, '_service_running') and self._service_running:

+            log.debug(u'ReloadHandler.reload: running, reloading...')

             self.restart()
 
 class InitdHandler(ServiceHandler):
             self.restart()
 
 class InitdHandler(ServiceHandler):


@@ -610,6 +650,7 @@ class InitdHandler(ServiceHandler):
 
     def __init__(self, initd_name=None, initd_dir=None):
         r"Initialize the object, see the class documentation for details."
 
     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:
         if initd_name is not None:
             self._initd_name = initd_name
         if initd_dir is not None:


@@ -621,12 +662,16 @@ class InitdHandler(ServiceHandler):
         ServiceHandler.__init__(self, **actions)
 
     def handle_timer(self):
         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:
         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:
             self._service_running = True
         else:

+            log.debug(u'InitdHandler.handle_timer: pid absent, NOT running')

             self._service_running = False
 
 class TransactionalHandler(Handler):
             self._service_running = False
 
 class TransactionalHandler(Handler):


@@ -648,18 +693,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."
     @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'):
         if hasattr(self, '_dump'):

+            log.debug(u'TransactionalHandler.commit: _dump() present, '
+                        u'dumping...')

             self._dump()
         unchanged = False
         if hasattr(self, '_write_config'):
             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'):
             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."
             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'):
         if hasattr(self, '_load'):

+            log.debug(u'TransactionalHandler.reload: _load() present, loading'
+                        u'pickled values...')

             self._load()
 
 class ParametersHandler(Handler):
             self._load()
 
 class ParametersHandler(Handler):


@@ -683,33 +738,41 @@ class ParametersHandler(Handler):
 
     def __init__(self, attr=None):
         r"Initialize the object, see the class documentation for details."
 
     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."
         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:
         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'):
             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."
             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:
         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."
             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."
         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):
         return self.params.items()
 
 class SubHandler(Handler):


@@ -723,6 +786,7 @@ class SubHandler(Handler):
 
     def __init__(self, parent):
         r"Initialize the object, see the class documentation for details."
 
     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):
         self.parent = parent
 
 class ContainerSubHandler(SubHandler):


@@ -752,6 +816,7 @@ class ContainerSubHandler(SubHandler):
 
     def __init__(self, parent, attr=None, cls=None):
         r"Initialize the object, see the class documentation for details."
 
     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
         self.parent = parent
         if attr is not None:
             self._cont_subhandler_attr = attr


@@ -773,17 +838,21 @@ class ContainerSubHandler(SubHandler):
     @handler(u'Add a new item')
     def add(self, *args, **kwargs):
         r"add(...) -> None :: Add an item to the list."
     @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'):
         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():
             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():
             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)
             index = key
             if not isinstance(self._attr(), dict):
                 index = self._attr().index(item)


@@ -800,39 +869,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."
     @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 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'):
         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'):
             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:
                 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."
             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'):
         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:
                 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."
             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:
         if isinstance(self._attr(), dict):
             self._attr.clear()
         else:


@@ -841,16 +922,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."
     @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:
         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."
             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()
         if isinstance(self._attr(), dict):
             return self._attr().values()
         return self._vattr()


@@ -865,6 +949,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."
     @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):
         return len(self._vattr())
 
 class DictSubHandler(ContainerSubHandler):


@@ -877,6 +962,7 @@ class DictSubHandler(ContainerSubHandler):
     @handler(u'List all the items by key')
     def list(self):
         r"list() -> tuple :: List all the item keys."
     @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):
         return self._attr().keys()
 
 class ComposedSubHandler(SubHandler):


@@ -920,6 +1006,8 @@ class ComposedSubHandler(SubHandler):
 
     def __init__(self, parent, cont=None, attr=None, cls=None):
         r"Initialize the object, see the class documentation for details."
 
     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
         self.parent = parent
         if cont is not None:
             self._comp_subhandler_cont = cont


@@ -946,19 +1034,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."
     @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():
         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'):
             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):
             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):
             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)
             index = key
             if not isinstance(self._attr(cont), dict):
                 index = self._attr(cont).index(item)


@@ -972,6 +1065,8 @@ class ComposedSubHandler(SubHandler):
             else:
                 self._attr(cont).append(item)
         if hasattr(self._cont()[cont], '_update'):
             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')
             self._cont()[cont]._update = True
 
     @handler(u'Update an item')


@@ -979,46 +1074,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.
         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():
         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'):
             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'):
             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'):
                 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:
                 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."
             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():
         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'):
             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'):
                 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:
                 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."
             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():
         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()
             raise ContainerNotFoundError(cont)
         if isinstance(self._attr(cont), dict):
             self._attr(cont).clear()


@@ -1028,19 +1143,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."
     @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():
         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:
             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."
             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():
         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()
             raise ContainerNotFoundError(cont)
         if isinstance(self._attr(cont), dict):
             return self._attr(cont).values()


@@ -1056,6 +1176,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."
     @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))
         if not cont in self._cont():
             raise ContainerNotFoundError(cont)
         return len(self._vattr(cont))


@@ -1070,6 +1191,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."
     @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()
         if not cont in self._cont():
             raise ContainerNotFoundError(cont)
         return self._attr(cont).keys()


@@ -1077,6 +1199,12 @@ class DictComposedSubHandler(ComposedSubHandler):
 
 if __name__ == '__main__':
 
 
 if __name__ == '__main__':
 

+    logging.basicConfig(
+        level   = logging.DEBUG,
+        format  = '%(asctime)s %(levelname)-8s %(message)s',
+        datefmt = '%H:%M:%S',
+    )
+

     import sys
 
     # Execution tests
     import sys
 
     # Execution tests