From f3ffd929ed8ec9e4546bb83282b26b94304364b7 Mon Sep 17 00:00:00 2001 From: Tom Turney Date: Tue, 20 Jun 2017 19:32:38 +0000 Subject: Revert "Re-organize logs for easy bug reporting." This reverts commit 2b46d89a6ed1b8afd5183e2ec8450f125b166570. Change-Id: I711170939d44c5f57bb34dff9cf82a1b58c5393c (cherry picked from commit 07efec1a7e61ea5ff340da0aa1c322ef2d5452d0) --- acts/framework/acts/base_test.py | 33 ++++++------ acts/framework/acts/controllers/android_device.py | 61 ++++++++++++++--------- acts/framework/acts/logger.py | 32 +++++------- acts/framework/tests/acts_android_device_test.py | 46 ++++++++++++----- 4 files changed, 100 insertions(+), 72 deletions(-) diff --git a/acts/framework/acts/base_test.py b/acts/framework/acts/base_test.py index 0817516445..3d424c9b5e 100755 --- a/acts/framework/acts/base_test.py +++ b/acts/framework/acts/base_test.py @@ -28,7 +28,7 @@ from acts import utils # Macro strings for test result reporting TEST_CASE_TOKEN = "[Test Case]" -RESULT_LINE_TEMPLATE = "[TEST CASE %s:%s] %s" +RESULT_LINE_TEMPLATE = TEST_CASE_TOKEN + " %s %s" class Error(Exception): @@ -227,7 +227,7 @@ class BaseTestClass(object): if record.details: self.log.error(record.details) begin_time = logger.epoch_to_log_line_timestamp(record.begin_time) - self.log.info(RESULT_LINE_TEMPLATE, self.TAG, test_name, record.result) + self.log.info(RESULT_LINE_TEMPLATE, test_name, record.result) self.on_fail(test_name, begin_time) def on_fail(self, test_name, begin_time): @@ -253,7 +253,7 @@ class BaseTestClass(object): msg = record.details if msg: self.log.info(msg) - self.log.info(RESULT_LINE_TEMPLATE, self.TAG, test_name, record.result) + self.log.info(RESULT_LINE_TEMPLATE, test_name, record.result) self.on_pass(test_name, begin_time) def on_pass(self, test_name, begin_time): @@ -276,7 +276,7 @@ class BaseTestClass(object): """ test_name = record.test_name begin_time = logger.epoch_to_log_line_timestamp(record.begin_time) - self.log.info(RESULT_LINE_TEMPLATE, self.TAG, test_name, record.result) + self.log.info(RESULT_LINE_TEMPLATE, test_name, record.result) self.log.info("Reason to skip: %s", record.details) self.on_skip(test_name, begin_time) @@ -300,7 +300,7 @@ class BaseTestClass(object): """ test_name = record.test_name begin_time = logger.epoch_to_log_line_timestamp(record.begin_time) - self.log.info(RESULT_LINE_TEMPLATE, self.TAG, test_name, record.result) + self.log.info(RESULT_LINE_TEMPLATE, test_name, record.result) self.log.info("Reason to block: %s", record.details) self.on_blocked(test_name, begin_time) @@ -375,16 +375,16 @@ class BaseTestClass(object): is_generate_trigger = False tr_record = records.TestResultRecord(test_name, self.TAG) tr_record.test_begin() - self.test_case_log_path = os.path.join(self.log_path, - "%s:%s" % (self.TAG, test_name)) - logger.create_test_case_logger(self.test_case_log_path) - self.log.info("%s %s", self.TAG, test_name) - for ad in getattr(self, "android_devices", []): - ad.log_path = os.path.join(self.test_case_log_path, ad.serial) - ad.start_adb_logcat(cont_logcat_file=True) + self.log.info("%s %s", TEST_CASE_TOKEN, test_name) + th = logger.create_test_case_logger(self.log_path, + "%s:%s" % (self.TAG, test_name)) verdict = None try: try: + if hasattr(self, 'android_devices'): + for ad in self.android_devices: + if not ad.is_adb_logcat_on: + ad.start_adb_logcat(cont_logcat_file=True) ret = self._setup_test(test_name) asserts.assert_true(ret is not False, "Setup for %s failed." % test_name) @@ -443,7 +443,7 @@ class BaseTestClass(object): tr_record.test_fail() self._exec_procedure_func(self._on_fail, tr_record) finally: - logger.remove_test_case_logger() + logger.remove_test_case_logger(th) if not is_generate_trigger: self.results.add_record(tr_record) @@ -696,12 +696,13 @@ class BaseTestClass(object): try: ad.adb.wait_for_device() ad.take_bug_report(test_name, begin_time) - ad.check_crash_report(log_crash_report=True) + bugreport_path = os.path.join(ad.log_path, test_name) + utils.create_dir(bugreport_path) + ad.check_crash_report(True, test_name) if getattr(ad, "qxdm_always_on", False): ad.log.info("Pull QXDM Logs") - qxdm_path = os.path.join(ad.log_path, "qxdm") ad.pull_files(["/data/vendor/radio/diag_logs/logs/"], - qxdm_path) + bugreport_path) except Exception as e: ad.log.error( "Failed to take a bug report for %s with error %s", diff --git a/acts/framework/acts/controllers/android_device.py b/acts/framework/acts/controllers/android_device.py index 4f9db7221f..114b956b93 100755 --- a/acts/framework/acts/controllers/android_device.py +++ b/acts/framework/acts/controllers/android_device.py @@ -539,7 +539,7 @@ class AndroidDevice: @property def is_adb_logcat_on(self): - """Whether the adb logcat process is active. + """Whether there is an ongoing adb logcat collection. """ if self.adb_logcat_process: try: @@ -552,8 +552,9 @@ class AndroidDevice: if ret is None: return True else: - self.log.error( - 'Logcat process %s died' % self.adb_logcat_process) + if self.droid: + self.droid.logI('Logcat died') + self.log.error('Logcat died on %s' % self.adb_logcat_file_path) return False return False @@ -719,7 +720,7 @@ class AndroidDevice: if in_range: break - def start_adb_logcat(self, cont_logcat_file=False, logcat_file_path=None): + def start_adb_logcat(self, cont_logcat_file=False): """Starts a standing adb logcat collection in separate subprocesses and save the logcat in a file. @@ -728,32 +729,41 @@ class AndroidDevice: file. This allows for start_adb_logcat to act as a restart logcat function if it is noticed logcat is no longer running. - log_cat_file_path: the file path to collect logcat. """ + if self.is_adb_logcat_on: + raise AndroidDeviceError(("Android device {} already has an adb " + "logcat thread going on. Cannot start " + "another one.").format(self.serial)) # Disable adb log spam filter. Have to stop and clear settings first # because 'start' doesn't support --clear option before Android N. - if self.adb_logcat_process and self.is_adb_logcat_on: - self.stop_adb_logcat() self.adb.shell("logpersist.stop --clear") self.adb.shell("logpersist.start") - if not logcat_file_path: - logcat_file_path = self.log_path - utils.create_dir(logcat_file_path) - logcat_output_file = os.path.join( - logcat_file_path, "adblog_%s_%s.txt" % (self.model, self.serial)) - extra_params = getattr(self, "adb_logcat_param", "-b all") - cmd = "adb -s %s logcat -v threadtime %s" % (self.serial, extra_params) - redirect = ">>" if cont_logcat_file else ">" - cmd = " ".join([cmd, redirect, logcat_output_file]) + if cont_logcat_file: + if self.droid: + self.droid.logI('Restarting logcat') + self.log.warning( + 'Restarting logcat on file %s' % self.adb_logcat_file_path) + logcat_file_path = self.adb_logcat_file_path + else: + f_name = "adblog,{},{}.txt".format(self.model, self.serial) + utils.create_dir(self.log_path) + logcat_file_path = os.path.join(self.log_path, f_name) + try: + extra_params = self.adb_logcat_param + except AttributeError: + extra_params = "-b all" + cmd = "adb -s {} logcat -v threadtime {} >> {}".format( + self.serial, extra_params, logcat_file_path) self.adb_logcat_process = utils.start_standing_subprocess(cmd) - self.adb_logcat_file_path = logcat_output_file + self.adb_logcat_file_path = logcat_file_path def stop_adb_logcat(self): """Stops the adb logcat collection subprocess. """ - if not self.adb_logcat_process: - self.log.info( - "Device does not have an ongoing adb logcat collector.") + if not self.is_adb_logcat_on: + raise AndroidDeviceError( + "Android device %s does not have an ongoing adb logcat collection." + % self.serial) utils.stop_standing_subprocess(self.adb_logcat_process) self.adb_logcat_process = None @@ -847,7 +857,7 @@ class AndroidDevice: new_br = False except adb.AdbError: new_br = False - br_path = self.log_path + br_path = os.path.join(self.log_path, test_name) utils.create_dir(br_path) out_name = "AndroidDevice%s_%s" % (self.serial, begin_time.replace( " ", "_").replace(":", "-")) @@ -882,12 +892,11 @@ class AndroidDevice: """Pull files from devies.""" if not remote_path: remote_path = self.log_path - utils.create_dir(remote_path) for file_name in files: self.adb.pull( "%s %s" % (file_name, remote_path), timeout=PULL_TIMEOUT) - def check_crash_report(self, log_crash_report=False): + def check_crash_report(self, log_crash_report=False, test_name=None): """check crash report on the device.""" crash_reports = [] for crash_path in CRASH_REPORT_PATHS: @@ -896,7 +905,11 @@ class AndroidDevice: continue crash_reports.append(os.path.join(crash_path, report)) if log_crash_report: - crash_log_path = os.path.join(self.log_path, "crashes") + if not test_name: + test_name = time.strftime("%m-%d-%Y-%H-%M-%S") + crash_log_path = os.path.join(self.log_path, test_name, + "CrashReports") + utils.create_dir(crash_log_path) self.pull_files(crash_reports, crash_log_path) return crash_reports diff --git a/acts/framework/acts/logger.py b/acts/framework/acts/logger.py index 2692d575ee..370409ff10 100755 --- a/acts/framework/acts/logger.py +++ b/acts/framework/acts/logger.py @@ -235,25 +235,17 @@ def normalize_log_line_timestamp(log_line_timestamp): return norm_tp -def create_test_case_logger(test_case_log_path): - create_dir(test_case_log_path) +def create_test_case_logger(log_path, test_case_name): log = logging.getLogger() - for log_level, file_name, log_handle in zip( - [logging.INFO, - logging.DEBUG], ["test_run_info.txt", "test_run_details.txt"], - ["test_case_info_handle", "test_case_debug_handle"]): - th = logging.FileHandler(os.path.join(test_case_log_path, file_name)) - th.setFormatter( - logging.Formatter(log_line_format, log_line_time_format)) - th.setLevel(log_level) - log.addHandler(th) - setattr(log, log_handle, th) - - -def remove_test_case_logger(): + th = logging.FileHandler(os.path.join(log_path, '%s.txt' % test_case_name)) + th.setFormatter(logging.Formatter(log_line_format, log_line_time_format)) + th.setLevel(logging.INFO) + log.addHandler(th) + return th + + +def remove_test_case_logger(th): log = logging.getLogger() - for handle_name in ("test_case_info_handle", "test_case_debug_handle"): - th = getattr(log, handle_name) - log.removeHandler(th) - if isinstance(th, logging.FileHandler): - th.close() + log.removeHandler(th) + if isinstance(th, logging.FileHandler): + th.close() diff --git a/acts/framework/tests/acts_android_device_test.py b/acts/framework/tests/acts_android_device_test.py index 0c2d63c753..d5b7908b37 100755 --- a/acts/framework/tests/acts_android_device_test.py +++ b/acts/framework/tests/acts_android_device_test.py @@ -99,8 +99,9 @@ class MockAdbProxy(): return "\t".join([str(self.serial), "device"]) def bugreport(self, params, timeout=android_device.BUG_REPORT_TIMEOUT): - expected = os.path.join(logging.log_path, - "AndroidDevice%s" % self.serial) + expected = os.path.join( + logging.log_path, "AndroidDevice%s" % self.serial, + "test_something", "AndroidDevice%s_sometime" % self.serial) assert expected in params, "Expected '%s', got '%s'." % (expected, params) @@ -275,7 +276,8 @@ class ActsAndroidDeviceTest(unittest.TestCase): mock_serial = 1 ad = android_device.AndroidDevice(serial=mock_serial) ad.take_bug_report("test_something", "sometime") - expected_path = os.path.join(ad.log_path) + expected_path = os.path.join( + logging.log_path, "AndroidDevice%s" % ad.serial, "test_something") create_dir_mock.assert_called_with(expected_path) @mock.patch( @@ -314,8 +316,8 @@ class ActsAndroidDeviceTest(unittest.TestCase): mock_serial = 1 ad = android_device.AndroidDevice(serial=mock_serial) ad.take_bug_report("test_something", "sometime") - expected_path = os.path.join(logging.log_path, - "AndroidDevice%s" % ad.serial) + expected_path = os.path.join( + logging.log_path, "AndroidDevice%s" % ad.serial, "test_something") create_dir_mock.assert_called_with(expected_path) @mock.patch('acts.controllers.adb.AdbProxy', return_value=MockAdbProxy(1)) @@ -337,17 +339,26 @@ class ActsAndroidDeviceTest(unittest.TestCase): expected_msg = ("Android device .* does not have an ongoing adb logcat" " collection.") # Expect error if stop is called before start. + with self.assertRaisesRegex(android_device.AndroidDeviceError, + expected_msg): + ad.stop_adb_logcat() ad.start_adb_logcat() # Verify start did the correct operations. self.assertTrue(ad.adb_logcat_process) expected_log_path = os.path.join(logging.log_path, "AndroidDevice%s" % ad.serial, - "adblog_fakemodel_%s.txt" % ad.serial) + "adblog,fakemodel,%s.txt" % ad.serial) creat_dir_mock.assert_called_with(os.path.dirname(expected_log_path)) - adb_cmd = 'adb -s %s logcat -v threadtime -b all > %s' + adb_cmd = 'adb -s %s logcat -v threadtime -b all >> %s' start_proc_mock.assert_called_with(adb_cmd % (ad.serial, expected_log_path)) self.assertEqual(ad.adb_logcat_file_path, expected_log_path) + expected_msg = ("Android device .* already has an adb logcat thread " + "going on. Cannot start another one.") + # Expect error if start is called back to back. + with self.assertRaisesRegex(android_device.AndroidDeviceError, + expected_msg): + ad.start_adb_logcat() # Verify stop did the correct operations. ad.stop_adb_logcat() stop_proc_mock.assert_called_with("process") @@ -371,14 +382,20 @@ class ActsAndroidDeviceTest(unittest.TestCase): mock_serial = 1 ad = android_device.AndroidDevice(serial=mock_serial) ad.adb_logcat_param = "-b radio" + expected_msg = ("Android device .* does not have an ongoing adb logcat" + " collection.") + # Expect error if stop is called before start. + with self.assertRaisesRegex(android_device.AndroidDeviceError, + expected_msg): + ad.stop_adb_logcat() ad.start_adb_logcat() # Verify start did the correct operations. self.assertTrue(ad.adb_logcat_process) expected_log_path = os.path.join(logging.log_path, "AndroidDevice%s" % ad.serial, - "adblog_fakemodel_%s.txt" % ad.serial) + "adblog,fakemodel,%s.txt" % ad.serial) creat_dir_mock.assert_called_with(os.path.dirname(expected_log_path)) - adb_cmd = 'adb -s %s logcat -v threadtime -b radio > %s' + adb_cmd = 'adb -s %s logcat -v threadtime -b radio >> %s' start_proc_mock.assert_called_with(adb_cmd % (ad.serial, expected_log_path)) self.assertEqual(ad.adb_logcat_file_path, expected_log_path) @@ -402,17 +419,22 @@ class ActsAndroidDeviceTest(unittest.TestCase): mock_serial = 1 ad = android_device.AndroidDevice(serial=mock_serial) # Expect error if attempted to cat adb log before starting adb logcat. + expected_msg = ("Attempting to cat adb log when none has been " + "collected on Android device .*") + with self.assertRaisesRegex(android_device.AndroidDeviceError, + expected_msg): + ad.cat_adb_log("some_test", MOCK_ADB_LOGCAT_BEGIN_TIME) ad.start_adb_logcat() # Direct the log path of the ad to a temp dir to avoid racing. - mock_adb_log_path = os.path.join(ad.log_path, "adblog_%s_%s.txt" % + ad.log_path = os.path.join(self.tmp_dir, ad.log_path) + mock_adb_log_path = os.path.join(ad.log_path, "adblog,%s,%s.txt" % (ad.model, ad.serial)) with open(mock_adb_log_path, 'w') as f: f.write(MOCK_ADB_LOGCAT) ad.cat_adb_log("some_test", MOCK_ADB_LOGCAT_BEGIN_TIME) cat_file_path = os.path.join( ad.log_path, "AdbLogExcerpts", - ("some_test,02-29 14:02:20.123,adblog_%s_%s.txt") % (ad.model, - ad.serial)) + ("some_test,02-29 14:02:20.123,%s,%s.txt") % (ad.model, ad.serial)) with open(cat_file_path, 'r') as f: actual_cat = f.read() self.assertEqual(actual_cat, ''.join(MOCK_ADB_LOGCAT_CAT_RESULT)) -- cgit v1.2.3