Merge "Rework logger" into stable/mitaka

fuelweb_test/__init__.py

@@ -1,4 +1,4 @@
-#    Copyright 2014 Mirantis, Inc.
+#    Copyright 2016 Mirantis, Inc.
 #
 #    Licensed under the Apache License, Version 2.0 (the "License"); you may
 #    not use this file except in compliance with the License. You may obtain
@@ -11,66 +11,116 @@
 #    WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the
 #    License for the specific language governing permissions and limitations
 #    under the License.
+
+from __future__ import unicode_literals
+
 import functools
-import logging
-import traceback
+import logging.config
 import os
+import traceback
+import warnings
+
 from fuelweb_test.settings import LOGS_DIR
 
 if not os.path.exists(LOGS_DIR):
     os.makedirs(LOGS_DIR)
 
-logging.basicConfig(level=logging.DEBUG,
-                    format='%(asctime)s - %(levelname)s %(filename)s:'
-                    '%(lineno)d -- %(message)s',
-                    filename=os.path.join(LOGS_DIR, 'sys_test.log'),
-                    filemode='w')
-
-console = logging.StreamHandler()
-console.setLevel(logging.INFO)
-formatter = logging.Formatter('%(asctime)s - %(levelname)s %(filename)s:'
-                              '%(lineno)d -- %(message)s')
-console.setFormatter(formatter)
+_log_config = {
+    'version': 1,
+    'disable_existing_loggers': False,
+    'formatters': {
+        'default': {
+            'format': '%(asctime)s - %(levelname)s %(filename)s:'
+                      '%(lineno)d -- %(message)s',
+            'datefmt': '%Y-%m-%d %H:%M:%S'
+        },
+    },
+    'handlers': {
+        'console': {
+            'level': 'INFO',
+            'class': 'logging.StreamHandler',
+            'formatter': 'default'
+        },
+        'tests_log': {
+            'level': 'DEBUG',
+            'class': 'logging.FileHandler',
+            'formatter': 'default',
+            'filename': os.path.join(LOGS_DIR, 'sys_test.log'),
+            'mode': 'w',
+            'encoding': 'utf8',
+        },
+        'devops_log': {
+            'level': 'DEBUG',
+            'class': 'logging.FileHandler',
+            'formatter': 'default',
+            'filename': os.path.join(LOGS_DIR, 'devops.log'),
+            'mode': 'w',
+            'encoding': 'utf8',
+        },
+        'null': {
+            'level': 'CRITICAL',
+            'class': 'logging.NullHandler',
+        },
+    },
+    'loggers': {
+        # Log all to log file , but by default only warnings.
+        '': {
+            'handlers': ['tests_log'],
+            'level': 'WARNING',
+        },
+        'fuel-qa': {
+            'handlers': ['console'],
+            'level': 'DEBUG',
+            'propagate': True
+        },
+        'devops': {
+            'handlers': ['console', 'devops_log'],
+            'level': 'DEBUG',
+            'propagate': True  # Test log too
+        },
+        # py.warnings is changed by Django -> do not propagate
+        'py.warnings': {
+            'handlers': ['console', 'tests_log'],
+            'level': 'WARNING',
+            'propagate': False
+        },
+        'paramiko': {'level': 'WARNING'},
+        'iso8601': {'level': 'WARNING'},
+        'keystoneauth': {'level': 'WARNING'},
+    }
+}
 
-logger = logging.getLogger(__name__)
-logger.addHandler(console)
+logging.config.dictConfig(_log_config)
+logging.captureWarnings(True)  # Log warnings
+# Filter deprecation warnings: log only when deletion announced
+warnings.filterwarnings(
+    'default',
+    message=r'.*(drop|remove)+.*',
+    category=DeprecationWarning)
 
+logger = logging.getLogger('fuel-qa.{}'.format(__name__))
 
-# suppress iso8601 and paramiko debug logging
-class NoDebugMessageFilter(logging.Filter):
-    def filter(self, record):
-        return not record.levelno <= logging.DEBUG
 
-logging.getLogger('paramiko.transport').setLevel(logging.WARNING)
-logging.getLogger('paramiko.hostkeys').setLevel(logging.WARNING)
-logging.getLogger('iso8601.iso8601').addFilter(NoDebugMessageFilter())
-logging.getLogger('keystoneauth.session').setLevel(logging.WARNING)
-
-
-def debug(logger):
-    def wrapper(func):
-        @functools.wraps(func)
-        def wrapped(*args, **kwargs):
-            logger.debug(
-                "Calling: {} with args: {} {}".format(
-                    func.__name__, args, kwargs
-                )
+def logwrap(func):
+    @functools.wraps(func)
+    def wrapped(*args, **kwargs):
+        logger.debug(
+            "Calling: {} with args: {} {}".format(
+                func.__name__, args, kwargs
             )
-            try:
-                result = func(*args, **kwargs)
-                logger.debug(
-                    "Done: {} with result: {}".format(func.__name__, result))
-            except BaseException as e:
-                logger.error(
-                    '{func} raised: {exc!r}\n'
-                    'Traceback: {tb!s}'.format(
-                        func=func.__name__, exc=e, tb=traceback.format_exc()))
-                raise
-            return result
-        return wrapped
-    return wrapper
-
-logwrap = debug(logger)
+        )
+        try:
+            result = func(*args, **kwargs)
+            logger.debug(
+                "Done: {} with result: {}".format(func.__name__, result))
+        except BaseException as e:
+            logger.error(
+                '{func} raised: {exc!r}\n'
+                'Traceback: {tb!s}'.format(
+                    func=func.__name__, exc=e, tb=traceback.format_exc()))
+            raise
+        return result
+    return wrapped
 
 
 class QuietLogger(object):
@@ -81,8 +131,9 @@ def __init__(self, upper_log_level=logging.WARNING):
         self.storage = None
 
     def __enter__(self):
+        console = logging.StreamHandler()
         self.storage = console.level
         console.setLevel(self.log_level + 1)
 
-    def __exit__(self, exp_type, exp_value, traceback):
-        console.setLevel(self.storage)
+    def __exit__(self, exc_type, exc_value, exc_tb):
+        logging.StreamHandler().setLevel(self.storage)