def setUp(self):
super(TestMetricsUnitTests, self).setUp()
# Save the original state of the collector.
self.original_collector_instance = MetricsCollector.GetCollector()
# Set dummy attributes for the collector.
MetricsCollector.StartTestCollector('https://example.com', 'user-agent-007',
{'a': 'b', 'c': 'd'})
self.collector = MetricsCollector.GetCollector()
self.log_handler = MockLoggingHandler()
# Use metrics logger to avoid impacting the root logger which may
# interfere with other tests.
logging.getLogger('metrics').setLevel(logging.DEBUG)
logging.getLogger('metrics').addHandler(self.log_handler)
def testMultithreadingDoesNotLogMacOSWarning(self):
logger = CreateOrGetGsutilLogger('FakeCommand')
mock_log_handler = MockLoggingHandler()
logger.addHandler(mock_log_handler)
self._TestRecursiveDepthThreeDifferentFunctions(1, 3)
macos_message = 'If you experience problems with multiprocessing on MacOS'
contains_message = [
message.startswith(macos_message)
for message in mock_log_handler.messages['info']
]
self.assertFalse(any(contains_message))
logger.removeHandler(mock_log_handler)
def setUp(self):
super(TestMetricsUnitTests, self).setUp()
# Save the original state of the collector.
self.original_collector_instance = MetricsCollector.GetCollector()
# Set dummy attributes for the collector.
MetricsCollector.StartTestCollector('https://example.com', 'user-agent-007',
{'a': 'b', 'c': 'd'})
self.collector = MetricsCollector.GetCollector()
self.log_handler = MockLoggingHandler()
# Use metrics logger to avoid impacting the root logger which may
# interfere with other tests.
logging.getLogger('metrics').setLevel(logging.DEBUG)
logging.getLogger('metrics').addHandler(self.log_handler)
def testSequentialApplyDoesNotRecommendParallelismAtEndIfLastSuggestionInView(
self, mock_get_term_lines):
logger = CreateOrGetGsutilLogger('FakeCommand')
mock_log_handler = MockLoggingHandler()
logger.addHandler(mock_log_handler)
self._RunApply(_ReturnOneValue,
range(22),
process_count=1,
thread_count=1)
contains_message = [
message == PARALLEL_PROCESSING_MESSAGE
for message in mock_log_handler.messages['info']
]
self.assertEqual(sum(contains_message), 2)
logger.removeHandler(mock_log_handler)
def testSequentialApplyRecommendsParallelismAfterThreshold(
self, mock_get_term_lines):
mock_get_term_lines.return_value = 100
logger = CreateOrGetGsutilLogger('FakeCommand')
mock_log_handler = MockLoggingHandler()
logger.addHandler(mock_log_handler)
self._RunApply(_ReturnOneValue,
range(2),
process_count=1,
thread_count=1)
contains_message = [
message == PARALLEL_PROCESSING_MESSAGE
for message in mock_log_handler.messages['info']
]
self.assertTrue(any(contains_message))
logger.removeHandler(mock_log_handler)
def RunCommand(self,
command_name,
args=None,
headers=None,
debug=0,
return_stdout=False,
return_stderr=False,
return_log_handler=False,
cwd=None):
"""Method for calling gslib.command_runner.CommandRunner.
Passes parallel_operations=False for all tests, optionally saving/returning
stdout output. We run all tests multi-threaded, to exercise those more
complicated code paths.
TODO: Change to run with parallel_operations=True for all tests. At
present when you do this it causes many test failures.
Args:
command_name: The name of the command being run.
args: Command-line args (arg0 = actual arg, not command name ala bash).
headers: Dictionary containing optional HTTP headers to pass to boto.
debug: Debug level to pass in to boto connection (range 0..3).
return_stdout: If True, will save and return stdout produced by command.
return_stderr: If True, will save and return stderr produced by command.
return_log_handler: If True, will return a MockLoggingHandler instance
that was attached to the command's logger while running.
cwd: The working directory that should be switched to before running the
command. The working directory will be reset back to its original
value after running the command. If not specified, the working
directory is left unchanged.
Returns:
One or a tuple of requested return values, depending on whether
return_stdout, return_stderr, and/or return_log_handler were specified.
Return Types:
stdout - str (binary in Py2, text in Py3)
stderr - str (binary in Py2, text in Py3)
log_handler - MockLoggingHandler
"""
args = args or []
command_line = six.ensure_text(' '.join([command_name] + args))
if self.is_debugging:
print_to_fd('\nRunCommand of {}\n'.format(command_line),
file=self.stderr_save)
# Save and truncate stdout and stderr for the lifetime of RunCommand. This
# way, we can return just the stdout and stderr that was output during the
# RunNamedCommand call below.
sys.stdout.seek(0)
sys.stderr.seek(0)
stdout = sys.stdout.read()
stderr = sys.stderr.read()
if stdout:
self.accumulated_stdout.append(stdout)
if stderr:
self.accumulated_stderr.append(stderr)
sys.stdout.seek(0)
sys.stderr.seek(0)
sys.stdout.truncate()
sys.stderr.truncate()
mock_log_handler = MockLoggingHandler()
logging.getLogger(command_name).addHandler(mock_log_handler)
if debug:
logging.getLogger(command_name).setLevel(logging.DEBUG)
try:
with WorkingDirectory(cwd):
self.command_runner.RunNamedCommand(command_name,
args=args,
headers=headers,
debug=debug,
parallel_operations=False,
do_shutdown=False)
finally:
sys.stdout.seek(0)
sys.stderr.seek(0)
if six.PY2:
stdout = sys.stdout.read()
stderr = sys.stderr.read()
else:
try:
stdout = sys.stdout.read()
stderr = sys.stderr.read()
except UnicodeDecodeError:
sys.stdout.seek(0)
sys.stderr.seek(0)
stdout = sys.stdout.buffer.read()
stderr = sys.stderr.buffer.read()
logging.getLogger(command_name).removeHandler(mock_log_handler)
mock_log_handler.close()
log_output = '\n'.join(
'%s:\n ' % level + '\n '.join(records)
for level, records in six.iteritems(mock_log_handler.messages)
if records)
_id = six.ensure_text(self.id())
if self.is_debugging and log_output:
print_to_fd('==== logging RunCommand {} {} ====\n'.format(
_id, command_line),
file=self.stderr_save)
print_to_fd(log_output, file=self.stderr_save)
print_to_fd('\n==== end logging ====\n', file=self.stderr_save)
if self.is_debugging and stdout:
print_to_fd('==== stdout RunCommand {} {} ====\n'.format(
_id, command_line),
file=self.stderr_save)
print_to_fd(stdout, file=self.stderr_save)
print_to_fd('==== end stdout ====\n', file=self.stderr_save)
if self.is_debugging and stderr:
print_to_fd('==== stderr RunCommand {} {} ====\n'.format(
_id, command_line),
file=self.stderr_save)
print_to_fd(stderr, file=self.stderr_save)
print_to_fd('==== end stderr ====\n', file=self.stderr_save)
# Reset stdout and stderr files, so that we won't print them out again
# in tearDown if debugging is enabled.
sys.stdout.seek(0)
sys.stderr.seek(0)
sys.stdout.truncate()
sys.stderr.truncate()
to_return = []
if return_stdout:
to_return.append(stdout)
if return_stderr:
to_return.append(stderr)
if return_log_handler:
to_return.append(mock_log_handler)
if len(to_return) == 1:
return to_return[0]
return tuple(to_return)
def setUp(self): super(TestCredsConfig, self).setUp() self.log_handler = MockLoggingHandler() self.logger.addHandler(self.log_handler)
def RunCommand(self,
command_name,
args=None,
headers=None,
debug=0,
return_stdout=False,
return_stderr=False,
return_log_handler=False,
cwd=None):
"""Method for calling gslib.command_runner.CommandRunner.
Passes parallel_operations=False for all tests, optionally saving/returning
stdout output. We run all tests multi-threaded, to exercise those more
complicated code paths.
TODO: Change to run with parallel_operations=True for all tests. At
present when you do this it causes many test failures.
Args:
command_name: The name of the command being run.
args: Command-line args (arg0 = actual arg, not command name ala bash).
headers: Dictionary containing optional HTTP headers to pass to boto.
debug: Debug level to pass in to boto connection (range 0..3).
return_stdout: If True, will save and return stdout produced by command.
return_stderr: If True, will save and return stderr produced by command.
return_log_handler: If True, will return a MockLoggingHandler instance
that was attached to the command's logger while running.
cwd: The working directory that should be switched to before running the
command. The working directory will be reset back to its original
value after running the command. If not specified, the working
directory is left unchanged.
Returns:
One or a tuple of requested return values, depending on whether
return_stdout, return_stderr, and/or return_log_handler were specified.
Return Types:
stdout - binary
stderr - str (binary in Py2, text in Py3)
log_handler - MockLoggingHandler
"""
args = args or []
command_line = ' '.join([command_name] + args)
if self.is_debugging:
self.stderr_save.write('\nRunCommand of {}\n'.format(command_line))
# Save and truncate stdout and stderr for the lifetime of RunCommand. This
# way, we can return just the stdout and stderr that was output during the
# RunNamedCommand call below.
sys.stdout.seek(0)
sys.stderr.seek(0)
stdout = sys.stdout.read()
stderr = sys.stderr.read()
if stdout:
self.accumulated_stdout.append(stdout)
if stderr:
self.accumulated_stderr.append(stderr)
sys.stdout.seek(0)
sys.stderr.seek(0)
sys.stdout.truncate()
sys.stderr.truncate()
mock_log_handler = MockLoggingHandler()
logging.getLogger(command_name).addHandler(mock_log_handler)
if debug:
logging.getLogger(command_name).setLevel(logging.DEBUG)
try:
with WorkingDirectory(cwd):
self.command_runner.RunNamedCommand(command_name,
args=args,
headers=headers,
debug=debug,
parallel_operations=False,
do_shutdown=False)
finally:
sys.stdout.seek(0)
sys.stderr.seek(0)
if six.PY2:
stdout = sys.stdout.read()
stderr = sys.stderr.read()
else:
try:
stdout = sys.stdout.read()
stderr = sys.stderr.read()
except UnicodeDecodeError:
sys.stdout.seek(0)
sys.stderr.seek(0)
stdout = sys.stdout.buffer.read().decode(UTF8)
stderr = sys.stderr.buffer.read().decode(UTF8)
logging.getLogger(command_name).removeHandler(mock_log_handler)
mock_log_handler.close()
log_output = '\n'.join(
'%s:\n ' % level + '\n '.join(records)
for level, records in six.iteritems(mock_log_handler.messages)
if records)
_id = six.ensure_text(self.id())
if self.is_debugging and log_output:
self.stderr_save.write('==== logging RunCommand {} {} ====\n'.format(
_id, command_line))
self.stderr_save.write(log_output)
self.stderr_save.write('\n==== end logging ====\n')
if self.is_debugging and stdout:
self.stderr_save.write('==== stdout RunCommand {} {} ====\n'.format(
_id, command_line))
self.stderr_save.write(stdout)
self.stderr_save.write('==== end stdout ====\n')
if self.is_debugging and stderr:
self.stderr_save.write('==== stderr RunCommand {} {} ====\n'.format(
_id, command_line))
self.stderr_save.write(stderr)
self.stderr_save.write('==== end stderr ====\n')
# Reset stdout and stderr files, so that we won't print them out again
# in tearDown if debugging is enabled.
sys.stdout.seek(0)
sys.stderr.seek(0)
sys.stdout.truncate()
sys.stderr.truncate()
to_return = []
if return_stdout:
to_return.append(stdout)
if return_stderr:
to_return.append(stderr)
if return_log_handler:
to_return.append(mock_log_handler)
if len(to_return) == 1:
return to_return[0]
return tuple(to_return)
class TestMetricsUnitTests(testcase.GsUtilUnitTestCase):
"""Unit tests for analytics data collection."""
def setUp(self):
super(TestMetricsUnitTests, self).setUp()
# Save the original state of the collector.
self.original_collector_instance = MetricsCollector.GetCollector()
# Set dummy attributes for the collector.
MetricsCollector.StartTestCollector('https://example.com', 'user-agent-007',
{'a': 'b', 'c': 'd'})
self.collector = MetricsCollector.GetCollector()
self.log_handler = MockLoggingHandler()
# Use metrics logger to avoid impacting the root logger which may
# interfere with other tests.
logging.getLogger('metrics').setLevel(logging.DEBUG)
logging.getLogger('metrics').addHandler(self.log_handler)
def tearDown(self):
super(TestMetricsUnitTests, self).tearDown()
# Reset to default collection settings.
MetricsCollector.StopTestCollector(
original_instance=self.original_collector_instance)
def testDisabling(self):
"""Tests enabling/disabling of metrics collection."""
self.assertEqual(self.collector, MetricsCollector.GetCollector())
# Test when gsutil is part of the Cloud SDK and the user opted in there.
with mock.patch.dict(os.environ,
values={'CLOUDSDK_WRAPPER': '1',
'GA_CID': '555'}):
MetricsCollector._CheckAndSetDisabledCache()
self.assertFalse(MetricsCollector._disabled_cache)
self.assertEqual(self.collector, MetricsCollector.GetCollector())
# Test when gsutil is part of the Cloud SDK and the user did not opt in
# there.
with mock.patch.dict(os.environ,
values={'CLOUDSDK_WRAPPER': '1',
'GA_CID': ''}):
MetricsCollector._CheckAndSetDisabledCache()
self.assertTrue(MetricsCollector._disabled_cache)
self.assertEqual(None, MetricsCollector.GetCollector())
# Test when gsutil is not part of the Cloud SDK and there is no UUID file.
with mock.patch.dict(os.environ, values={'CLOUDSDK_WRAPPER': ''}):
with mock.patch('os.path.exists', return_value=False):
MetricsCollector._CheckAndSetDisabledCache()
self.assertTrue(MetricsCollector._disabled_cache)
self.assertEqual(None, MetricsCollector.GetCollector())
# Test when gsutil is not part of the Cloud SDK and there is a UUID file.
with mock.patch.dict(os.environ, values={'CLOUDSDK_WRAPPER': ''}):
with mock.patch('os.path.exists', return_value=True):
# Mock the contents of the file.
with mock.patch('__builtin__.open') as mock_open:
mock_open.return_value.__enter__ = lambda s: s
# Set the file.read() method to return the disabled text.
mock_open.return_value.read.return_value = metrics._DISABLED_TEXT
MetricsCollector._CheckAndSetDisabledCache()
self.assertTrue(MetricsCollector._disabled_cache)
self.assertEqual(None, MetricsCollector.GetCollector())
# Set the file.read() method to return a mock cid (analytics enabled).
mock_open.return_value.read.return_value = 'mock_cid'
MetricsCollector._CheckAndSetDisabledCache()
self.assertFalse(MetricsCollector._disabled_cache)
self.assertEqual(self.collector, MetricsCollector.GetCollector())
# Check that open/read was called twice.
self.assertEqual(2, len(mock_open.call_args_list))
self.assertEqual(2, len(mock_open.return_value.read.call_args_list))
def testConfigValueValidation(self):
"""Tests the validation of potentially PII config values."""
string_and_bool_categories = ['check_hashes', 'content_language',
'disable_analytics_prompt',
'https_validate_certificates',
'json_api_version',
'parallel_composite_upload_component_size',
'parallel_composite_upload_threshold',
'prefer_api',
'sliced_object_download_component_size',
'sliced_object_download_threshold',
'tab_completion_time_logs', 'token_cache',
'use_magicfile']
int_categories = ['debug', 'default_api_version', 'http_socket_timeout',
'max_retry_delay', 'num_retries',
'oauth2_refresh_retries', 'parallel_process_count',
'parallel_thread_count', 'resumable_threshold',
'rsync_buffer_lines',
'sliced_object_download_max_components',
'software_update_check_period', 'tab_completion_timeout',
'task_estimation_threshold']
all_categories = sorted(string_and_bool_categories + int_categories)
# Test general invalid values.
with mock.patch('boto.config.get_value', return_value=None):
self.assertEqual('', self.collector._ValidateAndGetConfigValues())
with mock.patch('boto.config.get_value', return_value='invalid string'):
self.assertEqual(','.join([
category + ':INVALID' for category in all_categories
]), self.collector._ValidateAndGetConfigValues())
# Test that non-ASCII characters are invalid.
with mock.patch('boto.config.get_value', return_value='£'):
self.assertEqual(','.join([
category + ':INVALID' for category in all_categories
]), self.collector._ValidateAndGetConfigValues())
# Mock valid return values for specific string validations.
def MockValidStrings(section, category):
if section == 'GSUtil':
if category == 'check_hashes':
return 'if_fast_else_skip'
if category == 'content_language':
return 'chi'
if category == 'json_api_version':
return 'v3'
if category == 'prefer_api':
return 'xml'
if category in ('disable_analytics_prompt', 'use_magicfile',
'tab_completion_time_logs'):
return 'True'
if section == 'OAuth2' and category == 'token_cache':
return 'file_system'
if section == 'Boto' and category == 'https_validate_certificates':
return 'True'
return ''
with mock.patch('boto.config.get_value', side_effect=MockValidStrings):
self.assertEqual(
'check_hashes:if_fast_else_skip,content_language:chi,'
'disable_analytics_prompt:True,https_validate_certificates:True,'
'json_api_version:v3,prefer_api:xml,tab_completion_time_logs:True,'
'token_cache:file_system,use_magicfile:True',
self.collector._ValidateAndGetConfigValues())
# Test that "small" and "large" integers are appropriately validated.
def MockValidSmallInts(_, category):
if category in int_categories:
return '1999'
return ''
with mock.patch('boto.config.get_value', side_effect=MockValidSmallInts):
self.assertEqual(
'debug:1999,default_api_version:1999,http_socket_timeout:1999,'
'max_retry_delay:1999,num_retries:1999,oauth2_refresh_retries:1999,'
'parallel_process_count:1999,parallel_thread_count:1999,'
'resumable_threshold:1999,rsync_buffer_lines:1999,'
'sliced_object_download_max_components:1999,'
'software_update_check_period:1999,tab_completion_timeout:1999,'
'task_estimation_threshold:1999',
self.collector._ValidateAndGetConfigValues())
def MockValidLargeInts(_, category):
if category in int_categories:
return '2001'
return ''
with mock.patch('boto.config.get_value', side_effect=MockValidLargeInts):
self.assertEqual(
'debug:INVALID,default_api_version:INVALID,'
'http_socket_timeout:INVALID,max_retry_delay:INVALID,'
'num_retries:INVALID,oauth2_refresh_retries:INVALID,'
'parallel_process_count:INVALID,parallel_thread_count:INVALID,'
'resumable_threshold:2001,rsync_buffer_lines:2001,'
'sliced_object_download_max_components:INVALID,'
'software_update_check_period:INVALID,'
'tab_completion_timeout:INVALID,task_estimation_threshold:2001',
self.collector._ValidateAndGetConfigValues())
# Test that a non-integer return value is invalid.
def MockNonIntegerValue(_, category):
if category in int_categories:
return '10.28'
return ''
with mock.patch('boto.config.get_value', side_effect=MockNonIntegerValue):
self.assertEqual(
','.join([category + ':INVALID' for category in int_categories]),
self.collector._ValidateAndGetConfigValues())
# Test data size validation.
def MockDataSizeValue(_, category):
if category in ('parallel_composite_upload_component_size',
'parallel_composite_upload_threshold',
'sliced_object_download_component_size',
'sliced_object_download_threshold'):
return '10MiB'
return ''
with mock.patch('boto.config.get_value', side_effect=MockDataSizeValue):
self.assertEqual('parallel_composite_upload_component_size:10485760,'
'parallel_composite_upload_threshold:10485760,'
'sliced_object_download_component_size:10485760,'
'sliced_object_download_threshold:10485760',
self.collector._ValidateAndGetConfigValues())
def testCommandAndErrorEventsCollection(self):
"""Tests the collection of command and error GA events."""
self.assertEqual([], self.collector._metrics)
_LogAllTestMetrics()
# Only the first command should be logged.
metrics.LogCommandParams(command_name='cmd2')
# Commands and errors should not be collected until we explicitly collect
# them.
self.assertEqual([], self.collector._metrics)
self.collector._CollectCommandAndErrorMetrics()
self.assertEqual(COMMAND_AND_ERROR_TEST_METRICS,
set(self.collector._metrics))
def testPerformanceSummaryEventCollection(self):
"""Test the collection of PerformanceSummary GA events."""
# PerformanceSummaries are only collected for cp and rsync.
self.collector.ga_params[metrics._GA_LABEL_MAP['Command Name']] = 'cp'
# GetDiskCounters is called at initialization of _PerformanceSummaryParams,
# which occurs during the first call to LogPerformanceSummaryParams.
with mock.patch('gslib.metrics.GetDiskCounters',
return_value={'fake-disk': (0, 0, 0, 0, 0, 0)}):
metrics.LogPerformanceSummaryParams(
uses_fan=True, uses_slice=True, avg_throughput=10,
is_daisy_chain=True, has_file_dst=False, has_cloud_dst=True,
has_file_src=False, has_cloud_src=True, total_bytes_transferred=100,
total_elapsed_time=10, thread_idle_time=40, thread_execution_time=10,
num_processes=2, num_threads=3, num_objects_transferred=3,
provider_types=['gs'])
# Log a retryable service error and two retryable network errors.
service_retry_msg = RetryableErrorMessage(
apitools_exceptions.CommunicationError(), 0)
network_retry_msg = RetryableErrorMessage(socket.error(), 0)
metrics.LogRetryableError(service_retry_msg)
metrics.LogRetryableError(network_retry_msg)
metrics.LogRetryableError(network_retry_msg)
# Log some thread throughput.
start_file_msg = FileMessage('src', 'dst', 0, size=100)
end_file_msg = FileMessage('src', 'dst', 10, finished=True)
start_file_msg.thread_id = end_file_msg.thread_id = 1
start_file_msg.process_id = end_file_msg.process_id = 1
metrics.LogPerformanceSummaryParams(file_message=start_file_msg)
metrics.LogPerformanceSummaryParams(file_message=end_file_msg)
self.assertEqual(self.collector.perf_sum_params.thread_throughputs[
(1, 1)].GetThroughput(), 10)
# GetDiskCounters is called a second time during collection.
with mock.patch('gslib.metrics.GetDiskCounters',
return_value={'fake-disk': (0, 0, 0, 0, 10, 10)}):
self.collector._CollectPerformanceSummaryMetric()
# Check for all the expected parameters.
metric_body = self.collector._metrics[0].body
label_and_value_pairs = [
('Event Category', metrics._GA_PERFSUM_CATEGORY),
('Event Action', 'CloudToCloud%2CDaisyChain'), ('Execution Time', '10'),
('Parallelism Strategy', 'both'), ('Source URL Type', 'cloud'),
('Provider Types', 'gs'), ('Num Processes', '2'), ('Num Threads', '3'),
('Number of Files/Objects Transferred', '3'),
('Size of Files/Objects Transferred', '100'),
('Average Overall Throughput', '10'),
('Num Retryable Service Errors', '1'),
('Num Retryable Network Errors', '2'),
('Thread Idle Time Percent', '0.8'),
('Slowest Thread Throughput', '10'),
('Fastest Thread Throughput', '10'),
]
if IS_LINUX: # Disk I/O time is only available on Linux.
label_and_value_pairs.append(('Disk I/O Time', '20'))
for label, exp_value in label_and_value_pairs:
self.assertIn('{0}={1}'.format(metrics._GA_LABEL_MAP[label], exp_value),
metric_body)
def testCommandCollection(self):
"""Tests the collection of command parameters."""
_TryExceptAndPass(self.command_runner.RunNamedCommand,
'acl', ['set', '-a'], collect_analytics=True)
self.assertEqual(
'acl set',
self.collector.ga_params.get(metrics._GA_LABEL_MAP['Command Name']))
self.assertEqual('a', self.collector.ga_params.get(metrics._GA_LABEL_MAP[
'Command-Level Options']))
# Reset the ga_params, which store the command info.
self.collector.ga_params.clear()
self.command_runner.RunNamedCommand('list', collect_analytics=True)
self.assertEqual(
'ls',
self.collector.ga_params.get(metrics._GA_LABEL_MAP['Command Name']))
self.assertEqual(
'list',
self.collector.ga_params.get(metrics._GA_LABEL_MAP['Command Alias']))
self.collector.ga_params.clear()
_TryExceptAndPass(
self.command_runner.RunNamedCommand,
'iam', ['get', 'dummy_bucket'], collect_analytics=True)
self.assertEqual(
'iam get',
self.collector.ga_params.get(metrics._GA_LABEL_MAP['Command Name']))
# We only care about the error logging, not the actual exceptions handling.
@mock.patch.object(http_wrapper, 'HandleExceptionsAndRebuildHttpConnections')
def testRetryableErrorCollection(self, mock_default_retry):
"""Tests the collection of a retryable error in the retry function."""
# A DiscardMessagesQueue has the same retryable error-logging code as the
# UIThread and the MainThreadUIQueue.
mock_queue = RetryableErrorsQueue()
value_error_retry_args = http_wrapper.ExceptionRetryArgs(None, None,
ValueError(), None,
None, None)
socket_error_retry_args = http_wrapper.ExceptionRetryArgs(None, None,
socket.error(),
None, None, None)
metadata_retry_func = LogAndHandleRetries(is_data_transfer=False,
status_queue=mock_queue)
media_retry_func = LogAndHandleRetries(is_data_transfer=True,
status_queue=mock_queue)
metadata_retry_func(value_error_retry_args)
self.assertEqual(self.collector.retryable_errors['ValueError'], 1)
metadata_retry_func(value_error_retry_args)
self.assertEqual(self.collector.retryable_errors['ValueError'], 2)
metadata_retry_func(socket_error_retry_args)
self.assertEqual(self.collector.retryable_errors['SocketError'], 1)
# The media retry function raises an exception after logging because
# the GcsJsonApi handles retryable errors for media transfers itself.
_TryExceptAndPass(media_retry_func, value_error_retry_args)
_TryExceptAndPass(media_retry_func, socket_error_retry_args)
self.assertEqual(self.collector.retryable_errors['ValueError'], 3)
self.assertEqual(self.collector.retryable_errors['SocketError'], 2)
def testExceptionCatchingDecorator(self):
"""Tests the exception catching decorator CaptureAndLogException."""
# A wrapped function with an exception should not stop the process.
mock_exc_fn = mock.MagicMock(__name__='mock_exc_fn',
side_effect=Exception())
wrapped_fn = metrics.CaptureAndLogException(mock_exc_fn)
wrapped_fn()
debug_messages = self.log_handler.messages['debug']
self.assertIn('Exception captured in mock_exc_fn during metrics collection',
debug_messages[0])
self.log_handler.reset()
self.assertEqual(1, mock_exc_fn.call_count)
mock_err_fn = mock.MagicMock(__name__='mock_err_fn',
side_effect=TypeError())
wrapped_fn = metrics.CaptureAndLogException(mock_err_fn)
wrapped_fn()
self.assertEqual(1, mock_err_fn.call_count)
debug_messages = self.log_handler.messages['debug']
self.assertIn('Exception captured in mock_err_fn during metrics collection',
debug_messages[0])
self.log_handler.reset()
# Test that exceptions in the unprotected metrics functions are caught.
with mock.patch.object(MetricsCollector, 'GetCollector',
return_value='not a collector'):
# These calls should all fail, but the exceptions shouldn't propagate up.
metrics.Shutdown()
metrics.LogCommandParams()
metrics.LogRetryableError()
metrics.LogFatalError()
metrics.LogPerformanceSummaryParams()
metrics.CheckAndMaybePromptForAnalyticsEnabling('invalid argument')
debug_messages = self.log_handler.messages['debug']
message_index = 0
for func_name in ('Shutdown', 'LogCommandParams', 'LogRetryableError',
'LogFatalError', 'LogPerformanceSummaryParams',
'CheckAndMaybePromptForAnalyticsEnabling'):
self.assertIn(
'Exception captured in %s during metrics collection' % func_name,
debug_messages[message_index])
message_index += 1
self.log_handler.reset()
class TestMetricsUnitTests(testcase.GsUtilUnitTestCase):
"""Unit tests for analytics data collection."""
def setUp(self):
super(TestMetricsUnitTests, self).setUp()
# Save the original state of the collector.
self.original_collector_instance = MetricsCollector.GetCollector()
# Set dummy attributes for the collector.
MetricsCollector.StartTestCollector('https://example.com', 'user-agent-007',
{'a': 'b', 'c': 'd'})
self.collector = MetricsCollector.GetCollector()
self.log_handler = MockLoggingHandler()
# Use metrics logger to avoid impacting the root logger which may
# interfere with other tests.
logging.getLogger('metrics').setLevel(logging.DEBUG)
logging.getLogger('metrics').addHandler(self.log_handler)
def tearDown(self):
super(TestMetricsUnitTests, self).tearDown()
# Reset to default collection settings.
MetricsCollector.StopTestCollector(
original_instance=self.original_collector_instance)
def testDisabling(self):
"""Tests enabling/disabling of metrics collection."""
self.assertEqual(self.collector, MetricsCollector.GetCollector())
# Test when gsutil is part of the Cloud SDK and the user opted in there.
with mock.patch.dict(os.environ,
values={'CLOUDSDK_WRAPPER': '1',
'GA_CID': '555'}):
MetricsCollector._CheckAndSetDisabledCache()
self.assertFalse(MetricsCollector._disabled_cache)
self.assertEqual(self.collector, MetricsCollector.GetCollector())
# Test when gsutil is part of the Cloud SDK and the user did not opt in
# there.
with mock.patch.dict(os.environ,
values={'CLOUDSDK_WRAPPER': '1',
'GA_CID': ''}):
MetricsCollector._CheckAndSetDisabledCache()
self.assertTrue(MetricsCollector._disabled_cache)
self.assertEqual(None, MetricsCollector.GetCollector())
# Test when gsutil is not part of the Cloud SDK and there is no UUID file.
with mock.patch.dict(os.environ, values={'CLOUDSDK_WRAPPER': ''}):
with mock.patch('os.path.exists', return_value=False):
MetricsCollector._CheckAndSetDisabledCache()
self.assertTrue(MetricsCollector._disabled_cache)
self.assertEqual(None, MetricsCollector.GetCollector())
# Test when gsutil is not part of the Cloud SDK and there is a UUID file.
with mock.patch.dict(os.environ, values={'CLOUDSDK_WRAPPER': ''}):
with mock.patch('os.path.exists', return_value=True):
# Mock the contents of the file.
with mock.patch('__builtin__.open') as mock_open:
mock_open.return_value.__enter__ = lambda s: s
# Set the file.read() method to return the disabled text.
mock_open.return_value.read.return_value = metrics._DISABLED_TEXT
MetricsCollector._CheckAndSetDisabledCache()
self.assertTrue(MetricsCollector._disabled_cache)
self.assertEqual(None, MetricsCollector.GetCollector())
# Set the file.read() method to return a mock cid (analytics enabled).
mock_open.return_value.read.return_value = 'mock_cid'
MetricsCollector._CheckAndSetDisabledCache()
self.assertFalse(MetricsCollector._disabled_cache)
self.assertEqual(self.collector, MetricsCollector.GetCollector())
# Check that open/read was called twice.
self.assertEqual(2, len(mock_open.call_args_list))
self.assertEqual(2, len(mock_open.return_value.read.call_args_list))
def testConfigValueValidation(self):
"""Tests the validation of potentially PII config values."""
string_and_bool_categories = ['check_hashes', 'content_language',
'disable_analytics_prompt',
'https_validate_certificates',
'json_api_version',
'parallel_composite_upload_component_size',
'parallel_composite_upload_threshold',
'prefer_api',
'sliced_object_download_component_size',
'sliced_object_download_threshold',
'tab_completion_time_logs', 'token_cache',
'use_magicfile']
int_categories = ['debug', 'default_api_version', 'http_socket_timeout',
'max_retry_delay', 'num_retries',
'oauth2_refresh_retries', 'parallel_process_count',
'parallel_thread_count', 'resumable_threshold',
'rsync_buffer_lines',
'sliced_object_download_max_components',
'software_update_check_period', 'tab_completion_timeout',
'task_estimation_threshold']
all_categories = sorted(string_and_bool_categories + int_categories)
# Test general invalid values.
with mock.patch('boto.config.get_value', return_value=None):
self.assertEqual('', self.collector._ValidateAndGetConfigValues())
with mock.patch('boto.config.get_value', return_value='invalid string'):
self.assertEqual(','.join([
category + ':INVALID' for category in all_categories
]), self.collector._ValidateAndGetConfigValues())
# Test that non-ASCII characters are invalid.
with mock.patch('boto.config.get_value', return_value='£'):
self.assertEqual(','.join([
category + ':INVALID' for category in all_categories
]), self.collector._ValidateAndGetConfigValues())
# Mock valid return values for specific string validations.
def MockValidStrings(section, category):
if section == 'GSUtil':
if category == 'check_hashes':
return 'if_fast_else_skip'
if category == 'content_language':
return 'chi'
if category == 'json_api_version':
return 'v3'
if category == 'prefer_api':
return 'xml'
if category in ('disable_analytics_prompt', 'use_magicfile',
'tab_completion_time_logs'):
return 'True'
if section == 'OAuth2' and category == 'token_cache':
return 'file_system'
if section == 'Boto' and category == 'https_validate_certificates':
return 'True'
return ''
with mock.patch('boto.config.get_value', side_effect=MockValidStrings):
self.assertEqual(
'check_hashes:if_fast_else_skip,content_language:chi,'
'disable_analytics_prompt:True,https_validate_certificates:True,'
'json_api_version:v3,prefer_api:xml,tab_completion_time_logs:True,'
'token_cache:file_system,use_magicfile:True',
self.collector._ValidateAndGetConfigValues())
# Test that "small" and "large" integers are appropriately validated.
def MockValidSmallInts(_, category):
if category in int_categories:
return '1999'
return ''
with mock.patch('boto.config.get_value', side_effect=MockValidSmallInts):
self.assertEqual(
'debug:1999,default_api_version:1999,http_socket_timeout:1999,'
'max_retry_delay:1999,num_retries:1999,oauth2_refresh_retries:1999,'
'parallel_process_count:1999,parallel_thread_count:1999,'
'resumable_threshold:1999,rsync_buffer_lines:1999,'
'sliced_object_download_max_components:1999,'
'software_update_check_period:1999,tab_completion_timeout:1999,'
'task_estimation_threshold:1999',
self.collector._ValidateAndGetConfigValues())
def MockValidLargeInts(_, category):
if category in int_categories:
return '2001'
return ''
with mock.patch('boto.config.get_value', side_effect=MockValidLargeInts):
self.assertEqual(
'debug:INVALID,default_api_version:INVALID,'
'http_socket_timeout:INVALID,max_retry_delay:INVALID,'
'num_retries:INVALID,oauth2_refresh_retries:INVALID,'
'parallel_process_count:INVALID,parallel_thread_count:INVALID,'
'resumable_threshold:2001,rsync_buffer_lines:2001,'
'sliced_object_download_max_components:INVALID,'
'software_update_check_period:INVALID,'
'tab_completion_timeout:INVALID,task_estimation_threshold:2001',
self.collector._ValidateAndGetConfigValues())
# Test that a non-integer return value is invalid.
def MockNonIntegerValue(_, category):
if category in int_categories:
return '10.28'
return ''
with mock.patch('boto.config.get_value', side_effect=MockNonIntegerValue):
self.assertEqual(
','.join([category + ':INVALID' for category in int_categories]),
self.collector._ValidateAndGetConfigValues())
# Test data size validation.
def MockDataSizeValue(_, category):
if category in ('parallel_composite_upload_component_size',
'parallel_composite_upload_threshold',
'sliced_object_download_component_size',
'sliced_object_download_threshold'):
return '10MiB'
return ''
with mock.patch('boto.config.get_value', side_effect=MockDataSizeValue):
self.assertEqual('parallel_composite_upload_component_size:10485760,'
'parallel_composite_upload_threshold:10485760,'
'sliced_object_download_component_size:10485760,'
'sliced_object_download_threshold:10485760',
self.collector._ValidateAndGetConfigValues())
def testCommandAndErrorEventsCollection(self):
"""Tests the collection of command and error GA events."""
self.assertEqual([], self.collector._metrics)
_LogAllTestMetrics()
# Only the first command should be logged.
metrics.LogCommandParams(command_name='cmd2')
# Commands and errors should not be collected until we explicitly collect
# them.
self.assertEqual([], self.collector._metrics)
self.collector._CollectCommandAndErrorMetrics()
self.assertEqual(COMMAND_AND_ERROR_TEST_METRICS,
set(self.collector._metrics))
def testPerformanceSummaryEventCollection(self):
"""Test the collection of PerformanceSummary GA events."""
# PerformanceSummaries are only collected for cp and rsync.
self.collector.ga_params[metrics._GA_LABEL_MAP['Command Name']] = 'cp'
# GetDiskCounters is called at initialization of _PerformanceSummaryParams,
# which occurs during the first call to LogPerformanceSummaryParams.
with mock.patch('gslib.metrics.GetDiskCounters',
return_value={'fake-disk': (0, 0, 0, 0, 0, 0)}):
metrics.LogPerformanceSummaryParams(
uses_fan=True, uses_slice=True, avg_throughput=10,
is_daisy_chain=True, has_file_dst=False, has_cloud_dst=True,
has_file_src=False, has_cloud_src=True, total_bytes_transferred=100,
total_elapsed_time=10, thread_idle_time=40, thread_execution_time=10,
num_processes=2, num_threads=3, num_objects_transferred=3,
provider_types=['gs'])
# Log a retryable service error and two retryable network errors.
service_retry_msg = RetryableErrorMessage(
apitools_exceptions.CommunicationError(), 0)
network_retry_msg = RetryableErrorMessage(socket.error(), 0)
metrics.LogRetryableError(service_retry_msg)
metrics.LogRetryableError(network_retry_msg)
metrics.LogRetryableError(network_retry_msg)
# Log some thread throughput.
start_file_msg = FileMessage('src', 'dst', 0, size=100)
end_file_msg = FileMessage('src', 'dst', 10, finished=True)
start_file_msg.thread_id = end_file_msg.thread_id = 1
start_file_msg.process_id = end_file_msg.process_id = 1
metrics.LogPerformanceSummaryParams(file_message=start_file_msg)
metrics.LogPerformanceSummaryParams(file_message=end_file_msg)
self.assertEqual(self.collector.perf_sum_params.thread_throughputs[
(1, 1)].GetThroughput(), 10)
# GetDiskCounters is called a second time during collection.
with mock.patch('gslib.metrics.GetDiskCounters',
return_value={'fake-disk': (0, 0, 0, 0, 10, 10)}):
self.collector._CollectPerformanceSummaryMetric()
# Check for all the expected parameters.
metric_body = self.collector._metrics[0].body
label_and_value_pairs = [
('Event Category', metrics._GA_PERFSUM_CATEGORY),
('Event Action', 'CloudToCloud%2CDaisyChain'), ('Execution Time', '10'),
('Parallelism Strategy', 'both'), ('Source URL Type', 'cloud'),
('Provider Types', 'gs'), ('Num Processes', '2'), ('Num Threads', '3'),
('Number of Files/Objects Transferred', '3'),
('Size of Files/Objects Transferred', '100'),
('Average Overall Throughput', '10'),
('Num Retryable Service Errors', '1'),
('Num Retryable Network Errors', '2'),
('Thread Idle Time Percent', '0.8'),
('Slowest Thread Throughput', '10'),
('Fastest Thread Throughput', '10'),
]
if IS_LINUX: # Disk I/O time is only available on Linux.
label_and_value_pairs.append(('Disk I/O Time', '20'))
for label, exp_value in label_and_value_pairs:
self.assertIn('{0}={1}'.format(metrics._GA_LABEL_MAP[label], exp_value),
metric_body)
def testCommandCollection(self):
"""Tests the collection of command parameters."""
_TryExceptAndPass(self.command_runner.RunNamedCommand,
'acl', ['set', '-a'], collect_analytics=True)
self.assertEqual(
'acl set',
self.collector.ga_params.get(metrics._GA_LABEL_MAP['Command Name']))
self.assertEqual('a', self.collector.ga_params.get(metrics._GA_LABEL_MAP[
'Command-Level Options']))
# Reset the ga_params, which store the command info.
self.collector.ga_params.clear()
self.command_runner.RunNamedCommand('list', collect_analytics=True)
self.assertEqual(
'ls',
self.collector.ga_params.get(metrics._GA_LABEL_MAP['Command Name']))
self.assertEqual(
'list',
self.collector.ga_params.get(metrics._GA_LABEL_MAP['Command Alias']))
self.collector.ga_params.clear()
_TryExceptAndPass(
self.command_runner.RunNamedCommand,
'iam', ['get', 'dummy_bucket'], collect_analytics=True)
self.assertEqual(
'iam get',
self.collector.ga_params.get(metrics._GA_LABEL_MAP['Command Name']))
# We only care about the error logging, not the actual exceptions handling.
@mock.patch.object(http_wrapper, 'HandleExceptionsAndRebuildHttpConnections')
def testRetryableErrorCollection(self, mock_default_retry):
"""Tests the collection of a retryable error in the retry function."""
# A DiscardMessagesQueue has the same retryable error-logging code as the
# UIThread and the MainThreadUIQueue.
mock_queue = RetryableErrorsQueue()
value_error_retry_args = http_wrapper.ExceptionRetryArgs(None, None,
ValueError(), None,
None, None)
socket_error_retry_args = http_wrapper.ExceptionRetryArgs(None, None,
socket.error(),
None, None, None)
metadata_retry_func = LogAndHandleRetries(is_data_transfer=False,
status_queue=mock_queue)
media_retry_func = LogAndHandleRetries(is_data_transfer=True,
status_queue=mock_queue)
metadata_retry_func(value_error_retry_args)
self.assertEqual(self.collector.retryable_errors['ValueError'], 1)
metadata_retry_func(value_error_retry_args)
self.assertEqual(self.collector.retryable_errors['ValueError'], 2)
metadata_retry_func(socket_error_retry_args)
self.assertEqual(self.collector.retryable_errors['SocketError'], 1)
# The media retry function raises an exception after logging because
# the GcsJsonApi handles retryable errors for media transfers itself.
_TryExceptAndPass(media_retry_func, value_error_retry_args)
_TryExceptAndPass(media_retry_func, socket_error_retry_args)
self.assertEqual(self.collector.retryable_errors['ValueError'], 3)
self.assertEqual(self.collector.retryable_errors['SocketError'], 2)
def testExceptionCatchingDecorator(self):
"""Tests the exception catching decorator CaptureAndLogException."""
# A wrapped function with an exception should not stop the process.
mock_exc_fn = mock.MagicMock(__name__='mock_exc_fn',
side_effect=Exception())
wrapped_fn = metrics.CaptureAndLogException(mock_exc_fn)
wrapped_fn()
debug_messages = self.log_handler.messages['debug']
self.assertIn('Exception captured in mock_exc_fn during metrics collection',
debug_messages[0])
self.log_handler.reset()
self.assertEqual(1, mock_exc_fn.call_count)
mock_err_fn = mock.MagicMock(__name__='mock_err_fn',
side_effect=TypeError())
wrapped_fn = metrics.CaptureAndLogException(mock_err_fn)
wrapped_fn()
self.assertEqual(1, mock_err_fn.call_count)
debug_messages = self.log_handler.messages['debug']
self.assertIn('Exception captured in mock_err_fn during metrics collection',
debug_messages[0])
self.log_handler.reset()
# Test that exceptions in the unprotected metrics functions are caught.
with mock.patch.object(MetricsCollector, 'GetCollector',
return_value='not a collector'):
# These calls should all fail, but the exceptions shouldn't propagate up.
metrics.Shutdown()
metrics.LogCommandParams()
metrics.LogRetryableError()
metrics.LogFatalError()
metrics.LogPerformanceSummaryParams()
metrics.CheckAndMaybePromptForAnalyticsEnabling('invalid argument')
debug_messages = self.log_handler.messages['debug']
message_index = 0
for func_name in ('Shutdown', 'LogCommandParams', 'LogRetryableError',
'LogFatalError', 'LogPerformanceSummaryParams',
'CheckAndMaybePromptForAnalyticsEnabling'):
self.assertIn(
'Exception captured in %s during metrics collection' % func_name,
debug_messages[message_index])
message_index += 1
self.log_handler.reset()
def RunCommand(self,
command_name,
args=None,
headers=None,
debug=0,
test_method=None,
return_stdout=False,
return_stderr=False,
return_log_handler=False,
cwd=None):
"""Method for calling gslib.command_runner.CommandRunner.
Passes parallel_operations=False for all tests, optionally saving/returning
stdout output. We run all tests multi-threaded, to exercise those more
complicated code paths.
TODO: Change to run with parallel_operations=True for all tests. At
present when you do this it causes many test failures.
Args:
command_name: The name of the command being run.
args: Command-line args (arg0 = actual arg, not command name ala bash).
headers: Dictionary containing optional HTTP headers to pass to boto.
debug: Debug level to pass in to boto connection (range 0..3).
test_method: Optional general purpose method for testing purposes.
Application and semantics of this method will vary by
command and test type.
return_stdout: If True, will save and return stdout produced by command.
return_stderr: If True, will save and return stderr produced by command.
return_log_handler: If True, will return a MockLoggingHandler instance
that was attached to the command's logger while running.
cwd: The working directory that should be switched to before running the
command. The working directory will be reset back to its original
value after running the command. If not specified, the working
directory is left unchanged.
Returns:
One or a tuple of requested return values, depending on whether
return_stdout, return_stderr, and/or return_log_handler were specified.
"""
args = args or []
command_line = ' '.join([command_name] + args)
if self.is_debugging:
self.stderr_save.write('\nRunCommand of %s\n' % command_line)
# Save and truncate stdout and stderr for the lifetime of RunCommand. This
# way, we can return just the stdout and stderr that was output during the
# RunNamedCommand call below.
sys.stdout.seek(0)
sys.stderr.seek(0)
stdout = sys.stdout.read()
stderr = sys.stderr.read()
if stdout:
self.accumulated_stdout.append(stdout)
if stderr:
self.accumulated_stderr.append(stderr)
sys.stdout.seek(0)
sys.stderr.seek(0)
sys.stdout.truncate()
sys.stderr.truncate()
cwd_sav = None
try:
cwd_sav = os.getcwd()
except OSError:
# This can happen if the current working directory no longer exists.
pass
mock_log_handler = MockLoggingHandler()
logging.getLogger(command_name).addHandler(mock_log_handler)
try:
if cwd:
os.chdir(cwd)
self.command_runner.RunNamedCommand(command_name,
args=args,
headers=headers,
debug=debug,
parallel_operations=False,
test_method=test_method,
do_shutdown=False)
finally:
if cwd and cwd_sav:
os.chdir(cwd_sav)
sys.stdout.seek(0)
stdout = sys.stdout.read()
sys.stderr.seek(0)
stderr = sys.stderr.read()
logging.getLogger(command_name).removeHandler(mock_log_handler)
log_output = '\n'.join(
'%s:\n ' % level + '\n '.join(records)
for level, records in mock_log_handler.messages.iteritems()
if records)
if self.is_debugging and log_output:
self.stderr_save.write('==== logging RunCommand %s %s ====\n' %
(self.id(), command_line))
self.stderr_save.write(log_output)
self.stderr_save.write('\n==== end logging ====\n')
if self.is_debugging and stdout:
self.stderr_save.write('==== stdout RunCommand %s %s ====\n' %
(self.id(), command_line))
self.stderr_save.write(stdout)
self.stderr_save.write('==== end stdout ====\n')
if self.is_debugging and stderr:
self.stderr_save.write('==== stderr RunCommand %s %s ====\n' %
(self.id(), command_line))
self.stderr_save.write(stderr)
self.stderr_save.write('==== end stderr ====\n')
# Reset stdout and stderr files, so that we won't print them out again
# in tearDown if debugging is enabled.
sys.stdout.seek(0)
sys.stderr.seek(0)
sys.stdout.truncate()
sys.stderr.truncate()
to_return = []
if return_stdout:
to_return.append(stdout)
if return_stderr:
to_return.append(stderr)
if return_log_handler:
to_return.append(mock_log_handler)
if len(to_return) == 1:
return to_return[0]
return tuple(to_return)
def RunCommand(self, command_name, args=None, headers=None, debug=0,
test_method=None, return_stdout=False, return_stderr=False,
return_log_handler=False, cwd=None):
"""Method for calling gslib.command_runner.CommandRunner.
Passes parallel_operations=False for all tests, optionally saving/returning
stdout output. We run all tests multi-threaded, to exercise those more
complicated code paths.
TODO: Change to run with parallel_operations=True for all tests. At
present when you do this it causes many test failures.
Args:
command_name: The name of the command being run.
args: Command-line args (arg0 = actual arg, not command name ala bash).
headers: Dictionary containing optional HTTP headers to pass to boto.
debug: Debug level to pass in to boto connection (range 0..3).
test_method: Optional general purpose method for testing purposes.
Application and semantics of this method will vary by
command and test type.
return_stdout: If True, will save and return stdout produced by command.
return_stderr: If True, will save and return stderr produced by command.
return_log_handler: If True, will return a MockLoggingHandler instance
that was attached to the command's logger while running.
cwd: The working directory that should be switched to before running the
command. The working directory will be reset back to its original
value after running the command. If not specified, the working
directory is left unchanged.
Returns:
One or a tuple of requested return values, depending on whether
return_stdout, return_stderr, and/or return_log_handler were specified.
"""
args = args or []
command_line = ' '.join([command_name] + args)
if self.is_debugging:
self.stderr_save.write('\nRunCommand of %s\n' % command_line)
# Save and truncate stdout and stderr for the lifetime of RunCommand. This
# way, we can return just the stdout and stderr that was output during the
# RunNamedCommand call below.
sys.stdout.seek(0)
sys.stderr.seek(0)
stdout = sys.stdout.read()
stderr = sys.stderr.read()
if stdout:
self.accumulated_stdout.append(stdout)
if stderr:
self.accumulated_stderr.append(stderr)
sys.stdout.seek(0)
sys.stderr.seek(0)
sys.stdout.truncate()
sys.stderr.truncate()
cwd_sav = None
try:
cwd_sav = os.getcwd()
except OSError:
# This can happen if the current working directory no longer exists.
pass
mock_log_handler = MockLoggingHandler()
logging.getLogger(command_name).addHandler(mock_log_handler)
try:
if cwd:
os.chdir(cwd)
self.command_runner.RunNamedCommand(
command_name, args=args, headers=headers, debug=debug,
parallel_operations=False, test_method=test_method, do_shutdown=False)
finally:
if cwd and cwd_sav:
os.chdir(cwd_sav)
sys.stdout.seek(0)
stdout = sys.stdout.read()
sys.stderr.seek(0)
stderr = sys.stderr.read()
logging.getLogger(command_name).removeHandler(mock_log_handler)
mock_log_handler.close()
log_output = '\n'.join(
'%s:\n ' % level + '\n '.join(records)
for level, records in mock_log_handler.messages.iteritems()
if records)
if self.is_debugging and log_output:
self.stderr_save.write(
'==== logging RunCommand %s %s ====\n' % (self.id(), command_line))
self.stderr_save.write(log_output)
self.stderr_save.write('\n==== end logging ====\n')
if self.is_debugging and stdout:
self.stderr_save.write(
'==== stdout RunCommand %s %s ====\n' % (self.id(), command_line))
self.stderr_save.write(stdout)
self.stderr_save.write('==== end stdout ====\n')
if self.is_debugging and stderr:
self.stderr_save.write(
'==== stderr RunCommand %s %s ====\n' % (self.id(), command_line))
self.stderr_save.write(stderr)
self.stderr_save.write('==== end stderr ====\n')
# Reset stdout and stderr files, so that we won't print them out again
# in tearDown if debugging is enabled.
sys.stdout.seek(0)
sys.stderr.seek(0)
sys.stdout.truncate()
sys.stderr.truncate()
to_return = []
if return_stdout:
to_return.append(stdout)
if return_stderr:
to_return.append(stderr)
if return_log_handler:
to_return.append(mock_log_handler)
if len(to_return) == 1:
return to_return[0]
return tuple(to_return)
