Merge remote-tracking branch 'odoo/master' into master-report-translation-fix-sle

3 files changed, 26 insertions, 10 deletions

diff --git a/openerp/modules/loading.py b/openerp/modules/loading.py
index b8d52416514..d8391f4757c 100644
--- a/openerp/modules/loading.py
+++ b/openerp/modules/loading.py
@@ -29,6 +29,7 @@ import logging
 import os
 import sys
 import threading
+import time
 
 import openerp
 import openerp.modules.db
@@ -110,7 +111,7 @@ def load_module_graph(cr, graph, status=None, perform_checks=True, skip_modules=
             if kind in ('demo', 'test'):
                 threading.currentThread().testing = True
             for filename in _get_files_of_kind(kind):
-                _logger.info("module %s: loading %s", module_name, filename)
+                _logger.info("loading %s/%s", module_name, filename)
                 noupdate = False
                 if kind in ('demo', 'demo_xml') or (filename.endswith('.csv') and kind in ('init', 'init_xml')):
                     noupdate = True
@@ -137,6 +138,8 @@ def load_module_graph(cr, graph, status=None, perform_checks=True, skip_modules=
         registry.fields_by_model.setdefault(field['model'], []).append(field)
 
     # register, instantiate and initialize models for each modules
+    ta0 = time.time()
+
     for index, package in enumerate(graph):
         module_name = package.name
         module_id = package.id
@@ -144,7 +147,8 @@ def load_module_graph(cr, graph, status=None, perform_checks=True, skip_modules=
         if skip_modules and module_name in skip_modules:
             continue
 
-        _logger.debug('module %s: loading objects', package.name)
+        tm0 = time.time()
+
         migrations.migrate_module(package, 'pre')
         load_openerp_module(package.name)
 
@@ -222,9 +226,13 @@ def load_module_graph(cr, graph, status=None, perform_checks=True, skip_modules=
                 if hasattr(package, kind):
                     delattr(package, kind)
 
+            _logger.log(25, "%s loaded in %.2fs", package.name, time.time() - tm0)
+
         registry._init_modules.add(package.name)
         cr.commit()
 
+        _logger.log(25, "%s modules loaded in %.2fs", len(graph), time.time() - ta0)
+
     # The query won't be valid for models created later (i.e. custom model
     # created after the registry has been loaded), so empty its result.
     registry.fields_by_model = None
@@ -451,10 +459,13 @@ def load_modules(db, force_demo=False, status=None, update_module=False):
 
         # STEP 9: Run the post-install tests
         cr.commit()
+
+        ta0 = time.time()
         if openerp.tools.config['test_enable']:
             cr.execute("SELECT name FROM ir_module_module WHERE state='installed'")
             for module_name in cr.fetchall():
                 report.record_result(openerp.modules.module.run_unit_tests(module_name[0], cr.dbname, position=runs_post_install))
+            _logger.log(25, "All post-tested in %.2fs", time.time() - ta0)
     finally:
         cr.close()
 
diff --git a/openerp/modules/module.py b/openerp/modules/module.py
index cd21e681a8b..18a0cdbf727 100644
--- a/openerp/modules/module.py
+++ b/openerp/modules/module.py
@@ -27,6 +27,7 @@ import logging
 import os
 import re
 import sys
+import time
 import unittest
 from os.path import join as opj
 
@@ -422,14 +423,16 @@ def run_unit_tests(module_name, dbname, position=runs_at_install):
     for m in mods:
         tests = unwrap_suite(unittest2.TestLoader().loadTestsFromModule(m))
         suite = unittest2.TestSuite(itertools.ifilter(position, tests))
-        _logger.info('running %s tests.', m.__name__)
 
-        result = unittest2.TextTestRunner(verbosity=2, stream=TestStream(m.__name__)).run(suite)
+        if suite.countTestCases():
+            tm0 = time.time()
+            _logger.info('%s running tests.', m.__name__)
+            result = unittest2.TextTestRunner(verbosity=2, stream=TestStream(m.__name__)).run(suite)
+            _logger.log(25, "%s tested in %.2fs", m.__name__, time.time() - tm0)
+            if not result.wasSuccessful():
+                r = False
+                _logger.error("Module %s: %d failures, %d errors", module_name, len(result.failures), len(result.errors))
 
-        if not result.wasSuccessful():
-            r = False
-            _logger.error("Module %s: %d failures, %d errors",
-                          module_name, len(result.failures), len(result.errors))
     current_test = None
     return r
 
diff --git a/openerp/netsvc.py b/openerp/netsvc.py
index e6c05bf7298..0703c654f80 100644
--- a/openerp/netsvc.py
+++ b/openerp/netsvc.py
@@ -116,7 +116,7 @@ class DBFormatter(logging.Formatter):
 
 class ColoredFormatter(DBFormatter):
     def format(self, record):
-        fg_color, bg_color = LEVEL_COLOR_MAPPING[record.levelno]
+        fg_color, bg_color = LEVEL_COLOR_MAPPING.get(record.levelno, (GREEN, DEFAULT))
         record.levelname = COLOR_PATTERN % (30 + fg_color, 40 + bg_color, record.levelname)
         return DBFormatter.format(self, record)
 
@@ -127,6 +127,8 @@ def init_logger():
         return
     _logger_init = True
 
+    logging.addLevelName(25, "INFO")
+
     from tools.translate import resetlocale
     resetlocale()
 
@@ -180,7 +182,7 @@ def init_logger():
 
     if tools.config['log_db']:
         postgresqlHandler = PostgreSQLHandler()
-        postgresqlHandler.setLevel(logging.WARNING)
+        postgresqlHandler.setLevel(25)
         logging.getLogger().addHandler(postgresqlHandler)
 
     # Configure loggers levels