Fix #2513: Update logging effect in automation (#3437)

1. Print the executed commands and exit code when a test is failed.
2. Print the failed commands' output.
3. Hide msrest, vcr, or any other logger.
This commit is contained in:
Troy Dai 2017-05-24 09:00:14 -07:00 коммит произвёл Travis Prescott
Родитель f3f7f515c7
Коммит 2e672ea875
4 изменённых файлов: 23 добавлений и 27 удалений

2
nose.cfg Normal file
Просмотреть файл

@ -0,0 +1,2 @@
[nosetests]
logging-filter=azure.cli.testsdk,vcr_test_base

Просмотреть файл

@ -5,6 +5,10 @@
from __future__ import print_function
import os.path
from ..utilities.path import get_repo_root
def get_nose_runner(report_folder, parallel=True, process_timeout=600, process_restart=True,
xunit_report=False, exclude_integration=True):
"""Create a nose execution method"""
@ -24,7 +28,7 @@ def get_nose_runner(report_folder, parallel=True, process_timeout=600, process_r
or not os.path.isdir(report_folder):
raise ValueError('Report folder {} does not exist'.format(report_folder))
arguments = [__file__, '-v', '--nologcapture']
arguments = [__file__, '-v', '-c', os.path.join(get_repo_root(), 'nose.cfg')]
if parallel:
arguments += ['--processes=-1', '--process-timeout={}'.format(process_timeout)]
if process_restart:
@ -36,12 +40,8 @@ def get_nose_runner(report_folder, parallel=True, process_timeout=600, process_r
else:
test_report = ''
if exclude_integration:
arguments += ['--ignore-files=integration*']
debug_file = os.path.join(report_folder, 'test-debug.log')
arguments += ['--debug-log={}'.format(debug_file)]
arguments += ['--nologcapture']
arguments.extend(test_folders)
result = nose.run(argv=arguments)

Просмотреть файл

@ -3,8 +3,6 @@
# Licensed under the MIT License. See License.txt in the project root for license information.
# --------------------------------------------------------------------------------------------
from __future__ import print_function
import datetime
import unittest
import os
import inspect
@ -29,7 +27,7 @@ from .recording_processors import (SubscriptionRecordingProcessor, OAuthRequestR
from .utilities import create_random_name
from .decorators import live_only
logger = logging.getLogger('azuer.cli.testsdk')
logger = logging.getLogger('azure.cli.testsdk')
class IntegrationTestBase(unittest.TestCase):
@ -37,19 +35,9 @@ class IntegrationTestBase(unittest.TestCase):
super(IntegrationTestBase, self).__init__(method_name)
self.diagnose = os.environ.get(ENV_TEST_DIAGNOSE, None) == 'True'
def cmd(self, command, checks=None, expect_failure=False):
if self.diagnose:
begin = datetime.datetime.now()
print('\nExecuting command: {}'.format(command))
result = execute(command, expect_failure=expect_failure)
if self.diagnose:
duration = datetime.datetime.now() - begin
print('\nCommand accomplished in {} s. Exit code {}.\n{}'.format(
duration.total_seconds(), result.exit_code, result.output))
return result.assert_with_checks(checks)
@classmethod
def cmd(cls, command, checks=None, expect_failure=False):
return execute(command, expect_failure=expect_failure).assert_with_checks(checks)
def create_random_name(self, prefix, length): # pylint: disable=no-self-use
return create_random_name(prefix=prefix, length=length)
@ -238,17 +226,21 @@ class ScenarioTest(IntegrationTestBase): # pylint: disable=too-many-instance-at
class ExecutionResult(object): # pylint: disable=too-few-public-methods
def __init__(self, command, expect_failure=False, in_process=True):
logger.info('Execute command %s', command)
if in_process:
self._in_process_execute(command)
else:
self._out_of_process_execute(command)
if expect_failure and self.exit_code == 0:
raise AssertionError('The command is expected to fail but it doesn\'.')
logger.error('Command "%s" => %d. (It did not fail as expected) Output: %s', command,
self.exit_code, self.output)
raise AssertionError('The command did not fail as it was expected.')
elif not expect_failure and self.exit_code != 0:
logger.error('Command "%s" => %d. Output: %s', command, self.exit_code, self.output)
raise AssertionError('The command failed. Exit code: {}'.format(self.exit_code))
logger.info('Command "%s" => %d.', command, self.exit_code)
self.json_value = None
self.skip_assert = os.environ.get(ENV_SKIP_ASSERT, None) == 'True'
@ -260,8 +252,6 @@ class ExecutionResult(object): # pylint: disable=too-few-public-methods
elif callable(each):
checks.append(each)
logger.info('Checkers to be executed %s', len(checks))
if not self.skip_assert:
for c in checks:
c(self)

Просмотреть файл

@ -15,6 +15,7 @@ import shlex
import sys
import tempfile
import traceback
import logging
from random import choice
from string import digits, ascii_lowercase
@ -45,6 +46,7 @@ MOCKED_SUBSCRIPTION_ID = '00000000-0000-0000-0000-000000000000'
MOCKED_TENANT_ID = '00000000-0000-0000-0000-000000000000'
MOCKED_STORAGE_ACCOUNT = 'dummystorage'
logger = logging.getLogger('vcr_test_base')
# MOCK METHODS
@ -109,7 +111,7 @@ def _mock_subscriptions(self): # pylint: disable=unused-argument
def _mock_user_access_token(_, _1, _2, _3): # pylint: disable=unused-argument
return ('Bearer', 'top-secret-token-for-you', None)
return 'Bearer', 'top-secret-token-for-you', None
def _mock_operation_delay(_):
@ -284,7 +286,6 @@ class VCRTestBase(unittest.TestCase): # pylint: disable=too-many-instance-attri
self.exception = CLIError('No recorded result provided for {}.'.format(self.test_name))
if debug_vcr:
import logging
logging.basicConfig()
vcr_log = logging.getLogger('vcr')
vcr_log.setLevel(logging.INFO)
@ -427,8 +428,11 @@ class VCRTestBase(unittest.TestCase): # pylint: disable=too-many-instance-attri
cli_main(command_list, file=output)
except Exception as ex: # pylint: disable=broad-except
ex_msg = str(ex)
logger.error('Command "%s" => %s. Output: %s', command, ex_msg, output.getvalue())
if not next((x for x in allowed_exceptions if x in ex_msg), None):
raise ex
logger.info('Command "%s" => %s.', command, 'success')
self._track_executed_commands(command_list)
result = output.getvalue().strip()
output.close()