# HG changeset patch
# User Aurelien Campeas <aurelien.campeas@logilab.fr>
# Date 1355246400 -3600
# Node ID e2ba137b2bf9f51367cb8a74979831d45e2613ad
# Parent  7ee0752178e5548c09792ba0573512ec01072631
[server] add debugging for Hooks & Operations (closes #2470048)

diff -r 7ee0752178e5 -r e2ba137b2bf9 doc/book/en/annexes/rql/debugging.rst
--- a/doc/book/en/annexes/rql/debugging.rst	Fri Dec 14 14:08:14 2012 +0100
+++ b/doc/book/en/annexes/rql/debugging.rst	Tue Dec 11 18:20:00 2012 +0100
@@ -15,6 +15,8 @@
 .. autodata:: cubicweb.server.DBG_SQL
 .. autodata:: cubicweb.server.DBG_REPO
 .. autodata:: cubicweb.server.DBG_MS
+.. autodata:: cubicweb.server.DBG_HOOKS
+.. autodata:: cubicweb.server.DBG_OPS
 .. autodata:: cubicweb.server.DBG_MORE
 .. autodata:: cubicweb.server.DBG_ALL
 
@@ -31,6 +33,14 @@
 
 .. autofunction:: cubicweb.server.set_debug
 
+Another example showing how to debug hooks at a specific code site:
+
+.. sourcecode:: python
+
+    from cubicweb.server import debuged, DBG_HOOKS
+    with debugged(DBG_HOOKS):
+        person.cw_set(works_for=company)
+
 
 Detect largest RQL queries
 ~~~~~~~~~~~~~~~~~~~~~~~~~~~
diff -r 7ee0752178e5 -r e2ba137b2bf9 server/__init__.py
--- a/server/__init__.py	Fri Dec 14 14:08:14 2012 +0100
+++ b/server/__init__.py	Tue Dec 11 18:20:00 2012 +0100
@@ -77,10 +77,14 @@
 DBG_REPO = 4
 #: multi-sources
 DBG_MS   = 8
+#: hooks
+DBG_HOOKS = 16
+#: operations
+DBG_OPS = 32
 #: more verbosity
-DBG_MORE = 16
+DBG_MORE = 64
 #: all level enabled
-DBG_ALL  = DBG_RQL + DBG_SQL + DBG_REPO + DBG_MS + DBG_MORE
+DBG_ALL  = DBG_RQL + DBG_SQL + DBG_REPO + DBG_MS + DBG_HOOKS + DBG_OPS + DBG_MORE
 
 #: current debug mode
 DEBUG = 0
diff -r 7ee0752178e5 -r e2ba137b2bf9 server/hook.py
--- a/server/hook.py	Fri Dec 14 14:08:14 2012 +0100
+++ b/server/hook.py	Tue Dec 11 18:20:00 2012 +0100
@@ -260,7 +260,7 @@
 from logilab.common.registry import (Predicate, NotPredicate, OrPredicate,
                                      classid, objectify_predicate, yes)
 
-from cubicweb import RegistryNotFound
+from cubicweb import RegistryNotFound, server
 from cubicweb.cwvreg import CWRegistry, CWRegistryStore
 from cubicweb.predicates import ExpectedValuePredicate, is_instance
 from cubicweb.appobject import AppObject
@@ -325,8 +325,11 @@
                 for _kwargs in _iter_kwargs(entities, eids_from_to, kwargs):
                     hooks = sorted(self.filtered_possible_objects(pruned, session, **_kwargs),
                                    key=lambda x: x.order)
+                    debug = server.DEBUG & server.DBG_HOOKS
                     with session.security_enabled(write=False):
                         for hook in hooks:
+                            if debug:
+                                print event, _kwargs, hook
                             hook()
 
     def get_pruned_hooks(self, session, event, entities, eids_from_to, kwargs):
diff -r 7ee0752178e5 -r e2ba137b2bf9 server/session.py
--- a/server/session.py	Fri Dec 14 14:08:14 2012 +0100
+++ b/server/session.py	Tue Dec 11 18:20:00 2012 +0100
@@ -31,7 +31,7 @@
 from logilab.common.textutils import unormalize
 from logilab.common.registry import objectify_predicate
 
-from cubicweb import UnknownEid, QueryError, schema
+from cubicweb import UnknownEid, QueryError, schema, server
 from cubicweb.req import RequestSessionBase
 from cubicweb.dbapi import ConnectionProperties
 from cubicweb.utils import make_uid
@@ -939,16 +939,21 @@
         # information:
         # - processed by the precommit/commit event or not
         # - if processed, is it the failed operation
+        debug = server.DEBUG & server.DBG_OPS
         try:
             # by default, operations are executed with security turned off
             with security_enabled(self, False, False):
                 processed = []
                 self.commit_state = 'precommit'
+                if debug:
+                    print self.commit_state, '*' * 20
                 try:
                     while self.pending_operations:
                         operation = self.pending_operations.pop(0)
                         operation.processed = 'precommit'
                         processed.append(operation)
+                        if debug:
+                            print operation
                         operation.handle_event('precommit_event')
                     self.pending_operations[:] = processed
                     self.debug('precommit session %s done', self.id)
@@ -964,7 +969,11 @@
                     # instead of having to implements rollback, revertprecommit
                     # and revertcommit, that will be enough in mont case.
                     operation.failed = True
+                    if debug:
+                        print self.commit_state, '*' * 20
                     for operation in reversed(processed):
+                        if debug:
+                            print operation
                         try:
                             operation.handle_event('revertprecommit_event')
                         except BaseException:
@@ -977,8 +986,12 @@
                     raise
                 self.cnxset.commit()
                 self.commit_state = 'postcommit'
+                if debug:
+                    print self.commit_state, '*' * 20
                 while self.pending_operations:
                     operation = self.pending_operations.pop(0)
+                    if debug:
+                        print operation
                     operation.processed = 'postcommit'
                     try:
                         operation.handle_event('postcommit_event')