[debug] add DBG_TRANSACTIONS flag and hide transactions debug by default

CW debug output log is very verbose and most information is not always useful in all situation. This new flag is an attempt to make logs more useful by default while not preventing from adding this additional information when needed.

authorLaurent Peuch <cortex@worlddomination.be>
changeset1ff4fd41b2a5
branchdefault
phasedraft
hiddenno
parent revision#c5dcb7911dc7 fix: skip a wdoc test when doctuils is not available
child revision<not specified>
files modified by this revision
cubicweb/cwctl.py
cubicweb/server/__init__.py
cubicweb/server/session.py
cubicweb/test/unittest_cwctl.py
doc/book/annexes/rql/debugging.rst
doc/changes/3.30.rst
# HG changeset patch
# User Laurent Peuch <cortex@worlddomination.be>
# Date 1563975648 -7200
# Wed Jul 24 15:40:48 2019 +0200
# Node ID 1ff4fd41b2a5cf4432a58add6ac1fdd5fece372b
# Parent c5dcb7911dc7f2a333594045306c0fd498d182dd
[debug] add DBG_TRANSACTIONS flag and hide transactions debug by default

CW debug output log is very verbose and most information is not always useful
in all situation. This new flag is an attempt to make logs more useful by
default while not preventing from adding this additional information when
needed.

diff --git a/cubicweb/cwctl.py b/cubicweb/cwctl.py
@@ -46,11 +46,11 @@
1  from cubicweb.server import set_debug
2  from cubicweb.toolsutils import Command, rm, create_dir, underline_title
3  from cubicweb.__pkginfo__ import version as cw_version
4 
5  LOG_LEVELS = ('debug', 'info', 'warning', 'error')
6 -DBG_FLAGS = ('RQL', 'SQL', 'REPO', 'HOOKS', 'OPS', 'SEC', 'MORE', 'ALL')
7 +DBG_FLAGS = ('RQL', 'SQL', 'REPO', 'TRANSACTIONS', 'HOOKS', 'OPS', 'SEC', 'MORE', 'ALL')
8 
9  # don't check duplicated commands, it occurs when reloading site_cubicweb
10  CWCTL = CommandLine('cubicweb-ctl', 'The CubicWeb swiss-knife.',
11                      version=cw_version, check_duplicated_command=False)
12 
diff --git a/cubicweb/server/__init__.py b/cubicweb/server/__init__.py
@@ -61,20 +61,22 @@
13  DBG_RQL = 1
14  #: executed sql
15  DBG_SQL = 2
16  #: repository events
17  DBG_REPO = 4
18 +#: db transactions
19 +DBG_TRANSACTIONS = 8
20  #: hooks
21  DBG_HOOKS = 16
22  #: operations
23  DBG_OPS = 32
24  #: security
25  DBG_SEC = 64
26  #: more verbosity
27  DBG_MORE = 128
28  #: all level enabled
29 -DBG_ALL = DBG_RQL + DBG_SQL + DBG_REPO + DBG_HOOKS + DBG_OPS + DBG_SEC + DBG_MORE
30 +DBG_ALL = DBG_RQL + DBG_SQL + DBG_REPO + DBG_TRANSACTIONS + DBG_HOOKS + DBG_OPS + DBG_SEC + DBG_MORE
31 
32  _SECURITY_ITEMS = []
33  _SECURITY_CAPS = ['read', 'add', 'update', 'delete', 'transition']
34 
35  #: current debug mode
diff --git a/cubicweb/server/session.py b/cubicweb/server/session.py
@@ -684,12 +684,12 @@
36                          operation.handle_event('rollback_event')
37                      except BaseException:
38                          self.critical('rollback error', exc_info=sys.exc_info())
39                          continue
40                  cnxset.rollback()
41 -                if debug:
42 -                    print('rollback for transaction %s done' % self)
43 +                if server.DEBUG & server.DBG_TRANSACTIONS:
44 +                    self.debug('rollback for transaction %s done', self)
45          finally:
46              self.clear()
47 
48      @_open_only
49      def commit(self):
@@ -725,12 +725,12 @@
50                              processed.append(operation)
51                              if debug:
52                                  print(operation)
53                              operation.handle_event('precommit_event')
54                      self.pending_operations[:] = processed
55 -                    if debug:
56 -                        print('precommit transaction %s done' % self)
57 +                    if server.DEBUG & server.DBG_TRANSACTIONS:
58 +                        self.debug('precommit transaction %s done', self)
59                  except BaseException:
60                      # if error on [pre]commit:
61                      #
62                      # * set .failed = True on the operation causing the failure
63                      # * call revert<event>_event on processed operations
@@ -772,12 +772,12 @@
64                          except BaseException:
65                              if self.repo.config.mode == 'test':
66                                  raise
67                              self.critical('error while postcommit',
68                                            exc_info=sys.exc_info())
69 -                if debug:
70 -                    print('postcommit transaction %s done' % self)
71 +                if server.DEBUG & server.DBG_TRANSACTIONS:
72 +                    self.debug('postcommit transaction %s done', self)
73                  return self.transaction_uuid(set=False)
74          finally:
75              self.clear()
76 
77      # resource accessors ######################################################
diff --git a/cubicweb/test/unittest_cwctl.py b/cubicweb/test/unittest_cwctl.py
@@ -194,7 +194,33 @@
78 
79              total_value += getattr(server, "DBG_%s" % dbg_flag)
80              self.assertEqual(total_value, server.DEBUG)
81 
82 
83 +    def test_set_loglevel(self):
84 +        LOG_LEVELS = ('debug', 'info', 'warning', 'error')
85 +
86 +        for log_level in LOG_LEVELS:
87 +            with self.assertRaises(SystemExit) as cm:
88 +                self.CWCTL.run(["test", "some_instance", "--loglevel", log_level])
89 +            self.assertEqual(cm.exception.code, 0)
90 +
91 +            self.fake_config.global_set_option.assert_called_with('log-threshold',
92 +                                                                  log_level.upper())
93 +
94 +    @patch.object(server, "DEBUG", 0)
95 +    def test_set_dblevel(self):
96 +        DBG_FLAGS = ('RQL', 'SQL', 'REPO', 'TRANSACTIONS', 'HOOKS', 'OPS', 'SEC', 'MORE')
97 +
98 +        total_value = 0
99 +
100 +        for dbg_flag in DBG_FLAGS:
101 +            with self.assertRaises(SystemExit) as cm:
102 +                self.CWCTL.run(["test", "some_instance", "--dbglevel", dbg_flag])
103 +            self.assertEqual(cm.exception.code, 0)
104 +
105 +            total_value += getattr(server, "DBG_%s" % dbg_flag)
106 +            self.assertEqual(total_value, server.DEBUG)
107 +
108 +
109  if __name__ == '__main__':
110      unittest.main()
diff --git a/doc/book/annexes/rql/debugging.rst b/doc/book/annexes/rql/debugging.rst
@@ -12,10 +12,11 @@
111 
112  .. autodata:: cubicweb.server.DBG_NONE
113  .. autodata:: cubicweb.server.DBG_RQL
114  .. autodata:: cubicweb.server.DBG_SQL
115  .. autodata:: cubicweb.server.DBG_REPO
116 +.. autodata:: cubicweb.server.DBG_TRANSACTIONS
117  .. autodata:: cubicweb.server.DBG_HOOKS
118  .. autodata:: cubicweb.server.DBG_OPS
119  .. autodata:: cubicweb.server.DBG_MORE
120  .. autodata:: cubicweb.server.DBG_ALL
121 
diff --git a/doc/changes/3.30.rst b/doc/changes/3.30.rst
@@ -0,0 +1,10 @@
122 +3.30 (unreleased 2021)
123 +======================
124 +
125 +New features
126 +------------
127 +
128 +* hide "precommit/postcommit/rollback for transaction" logs by default, to
129 +  re-enable them use the "TRANSACTIONS" flag either with --dbglevel CLI
130 +  argument or following this documentation
131 +  https://cubicweb.readthedocs.io/en/default/book/annexes/rql/debugging/