Revert "Re-organize logs for easy bug reporting."

This reverts commit 2b46d89a6ed1b8afd5183e2ec8450f125b166570.

Change-Id: I711170939d44c5f57bb34dff9cf82a1b58c5393c
(cherry picked from commit 07efec1a7e61ea5ff340da0aa1c322ef2d5452d0)

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))