!173 修改hilog日志抓取逻辑

Merge pull request !173 from liguangjie/master

plugins/ohos/src/ohos/drivers/drivers.py

@@ -59,6 +59,7 @@ from xdevice import reset_junit_para
 from xdevice import disable_keyguard
 from xdevice import unlock_screen
 from xdevice import unlock_device
+from xdevice import get_cst_time
 
 from ohos.environment.dmlib import process_command_ret
 from ohos.environment.dmlib import DisplayOutputReceiver
@@ -945,8 +946,7 @@ class JUnitTestDriver(IDriver):
         else:
             test_list = [ele.strip() for ele in self.config.include_tests]
         if test_list:
-            import datetime
-            prefix = datetime.datetime.now().strftime('%Y%m%d%H%M%S%f')
+            prefix = get_cst_time().strftime('%Y%m%d%H%M%S%f')
 
             save_file = \
                 os.path.join(self.config.report_path, "temp_%s.txt" % prefix)
@@ -2487,10 +2487,11 @@ class JSUnitTestDriver(IDriver):
             raise exception
         finally:
             serial = "{}_{}".format(str(self.config.device.__get_serial__()), time.time_ns())
-            log_tar_file_name = "{}_{}".format(str(serial).replace(
-                ":", "_"), request.get_module_name())
+            log_tar_file_name = "{}_{}".format(request.get_module_name(),
+                                               str(serial).replace(":", "_"))
             self.config.device.start_get_crash_log(log_tar_file_name)
             self.config.device.stop_catch_device_log()
+            self.config.device.stop_hilog_task(log_tar_file_name)
             self.result = check_result_report(
                 request.config.report_path, self.result, self.error_message)
 
@@ -2526,6 +2527,7 @@ class JSUnitTestDriver(IDriver):
                     hilog_file_pipe=hilog_file_pipe)
 
             # execute test case
+            self.config.device.start_hilog_task()
             command = "shell aa start -d 123 -a %s -b %s" \
                       % (ability_name, package)
             result_value = self.config.device.connector_command(command)

plugins/ohos/src/ohos/drivers/openharmony.py

@@ -241,20 +241,9 @@ class OHJSUnitTestDriver(IDriver):
                     request.root.source.source_string, error_no="00110")
             LOG.debug("Test case file path: %s" % suite_file)
             self.config.device.set_device_report_path(request.config.report_path)
-
-            hilog = get_device_log_file(request.config.report_path,
-                                        request.config.device.__get_serial__() + "_" + request.
-                                        get_module_name(),
-                                        "device_hilog")
-
-            hilog_open = os.open(hilog, os.O_WRONLY | os.O_CREAT | os.O_APPEND,
-                                 0o755)
-            self.config.device.execute_shell_command(command="hilog -r")
-            with os.fdopen(hilog_open, "a") as hilog_file_pipe:
-                if hasattr(self.config.device, "clear_crash_log"):
-                    self.config.device.clear_crash_log()
-                self.config.device.start_catch_device_log(hilog_file_pipe=hilog_file_pipe)
-                self._run_oh_jsunit(config_file, request)
+            if hasattr(self.config.device, "start_hilog_task"):
+                self.config.device.start_hilog_task()
+            self._run_oh_jsunit(config_file, request)
         except Exception as exception:
             self.error_message = exception
             if not getattr(exception, "error_no", ""):
@@ -263,11 +252,12 @@ class OHJSUnitTestDriver(IDriver):
             raise exception
         finally:
             serial = "{}_{}".format(str(self.config.device.__get_serial__()), time.time_ns())
-            log_tar_file_name = "{}_{}".format(str(serial).replace(
-                ":", "_"), request.get_module_name())
+            log_tar_file_name = "{}_{}".format(request.get_module_name(),
+                                               str(serial).replace(":", "_"))
             if hasattr(self.config.device, "start_get_crash_log"):
                 self.config.device.start_get_crash_log(log_tar_file_name)
-            self.config.device.stop_catch_device_log()
+            if hasattr(self.config.device, "stop_hilog_task"):
+                self.config.device.stop_hilog_task(log_tar_file_name)
             self.result = check_result_report(
                 request.config.report_path, self.result, self.error_message)
 

plugins/ohos/src/ohos/environment/device.py

@@ -19,9 +19,6 @@
 import time
 import os
 import threading
-from datetime import datetime
-from datetime import timezone
-from datetime import timedelta
 from xdevice import DeviceOsType
 from xdevice import ProductForm
 from xdevice import ReportException
@@ -36,9 +33,11 @@ from xdevice import convert_serial
 from xdevice import check_path_legal
 from xdevice import start_standing_subprocess
 from xdevice import stop_standing_subprocess
+from xdevice import get_cst_time
 
 from ohos.environment.dmlib import HdcHelper
 from ohos.environment.dmlib import CollectingOutputReceiver
+from ohos.parser.parser import _ACE_LOG_MARKER
 
 __all__ = ["Device"]
 TIMEOUT = 300 * 1000
@@ -397,9 +396,11 @@ class Device(IDevice):
         if self.hilog_file_pipe:
             command = "hilog"
             if self.host != "127.0.0.1":
-                cmd = ["hdc_std", "-s", "{}:{}".format(self.host, self.port), "shell", command]
+                cmd = ["hdc_std", "-s", "{}:{}".format(self.host, self.port),
+                       "shell", command, "|", "grep", "-i", _ACE_LOG_MARKER]
             else:
-                cmd = ['hdc_std', "-t", self.device_sn, "shell", command]
+                cmd = ['hdc_std', "-t", self.device_sn, "shell", command,
+                       "|", "grep", "-i", _ACE_LOG_MARKER]
             LOG.info("execute command: %s" % " ".join(cmd).replace(
                 self.device_sn, convert_serial(self.device_sn)))
             self.device_hilog_proc = start_standing_subprocess(
@@ -435,13 +436,21 @@ class Device(IDevice):
     def stop_hilog_task(self, log_name):
         cmd = "hilog -w stop"
         out = self.execute_shell_command(cmd)
-        # 把hilog文件夹下所有文件拉出来 由于hdc不支持整个文件夹拉出只能采用先压缩再拉取文件
-        cmd = "cd /data/log/hilog && tar -zcvf /data/log/hilog_{}.tar.gz *".format(log_name)
-        out = self.execute_shell_command(cmd)
-        LOG.info("Execute command: {}, result is {}".format(cmd, out))
-        self.pull_file("/data/log/hilog_{}.tar.gz".format(log_name), "{}/log/".format(self._device_log_path))
-        cmd = "rm -rf /data/log/hilog_{}.tar.gz".format(log_name)
-        out = self.execute_shell_command(cmd)
+        self.pull_file("/data/log/hilog/", "{}/log/".format(self._device_log_path))
+        try:
+            os.rename("{}/log/hilog".format(self._device_log_path),
+                      "{}/log/{}_hilog".format(self._device_log_path, log_name))
+        except Exception as e:
+            self.log.error("Rename hilog folder {}_hilog failed. error: {}".format(log_name, e))
+            # 把hilog文件夹下所有文件拉出来 由于hdc不支持整个文件夹拉出只能采用先压缩再拉取文件
+            cmd = "cd /data/log/hilog && tar -zcvf /data/log/hilog_{}.tar.gz *".format(log_name)
+            out = self.execute_shell_command(cmd)
+            LOG.info("Execute command: {}, result is {}".format(cmd, out))
+            if "No space left on device" not in out:
+                self.pull_file("/data/log/{}_hilog.tar.gz".format(log_name),
+                               "{}/log/".format(self._device_log_path))
+                cmd = "rm -rf /data/log/hilog_{}.tar.gz".format(log_name)
+                out = self.execute_shell_command(cmd)
         # 获取crash日志
         self.start_get_crash_log(log_name)
 
@@ -487,9 +496,9 @@ class Device(IDevice):
 
     def start_get_crash_log(self, task_name):
         log_array = list()
-        native_crash_cmd = "ls /data/log/faultlog/temp"
-        js_crash_cmd = '"ls /data/log/faultlog/faultlogger | grep jscrash"'
-        block_crash_cmd = '"ls /data/log/faultlog/"'
+        native_crash_cmd = "ls {}".format(NATIVE_CRASH_PATH)
+        js_crash_cmd = '"ls {} | grep jscrash"'.format(JS_CRASH_PATH)
+        block_crash_cmd = '"ls {}"'.format(ROOT_PATH)
         # 获取crash日志文件
         log_array.extend(self._get_log(native_crash_cmd, "cppcrash"))
         log_array.extend(self._get_log(js_crash_cmd, "jscrash"))
@@ -501,10 +510,10 @@ class Device(IDevice):
             self.get_cur_crash_log(crash_path, log_name)
 
     def clear_crash_log(self):
-        clear_block_crash_cmd = "rm -f /data/log/faultlog/*"
-        clear_native_crash_cmd = "rm -f /data/log/faultlog/temp/*"
-        clear_debug_crash_cmd = "rm -f /data/log/faultlog/debug/*"
-        clear_js_crash_cmd = "rm -f /data/log/faultlog/faultlogger/*"
+        clear_block_crash_cmd = "rm -f {}/*".format(ROOT_PATH)
+        clear_native_crash_cmd = "rm -f {}/*".format(NATIVE_CRASH_PATH)
+        clear_debug_crash_cmd = "rm -f {}/debug/*".format(ROOT_PATH)
+        clear_js_crash_cmd = "rm -f {}/*".format(JS_CRASH_PATH)
         self.execute_shell_command(clear_block_crash_cmd)
         self.execute_shell_command(clear_native_crash_cmd)
         self.execute_shell_command(clear_debug_crash_cmd)
@@ -512,13 +521,8 @@ class Device(IDevice):
 
     def _sync_device_time(self):
         # 先同步PC和设备的时间
-        sha_tz = timezone(
-            timedelta(hours=8),
-            name='Asia/Shanghai',
-        )
         iso_time_format = '%Y-%m-%d %H:%M:%S'
-        cur_time = datetime.now(tz=timezone.utc).astimezone(sha_tz)\
-            .strftime(iso_time_format)
+        cur_time = get_cst_time().strftime(iso_time_format)
         self.execute_shell_command("date '{}'".format(cur_time))
         self.execute_shell_command("hwclock --systohc")
 
@@ -552,12 +556,14 @@ class Device(IDevice):
         self.reconnecttimes = 0
 
     def reset(self):
-        self.log.debug("start stop rpc")
-        if self._proxy is not None:
-            self._proxy.close()
-        self._proxy = None
-        self.remove_ports()
-        self.stop_harmony_rpc()
+        if self.device_allocation_state != \
+                DeviceAllocationState.ignored:
+            self.log.debug("start stop rpc")
+            if self._proxy is not None:
+                self._proxy.close()
+            self._proxy = None
+            self.remove_ports()
+            self.stop_harmony_rpc()
 
     @property
     def proxy(self):

plugins/ohos/src/ohos/environment/dmlib.py

@@ -1033,6 +1033,7 @@ class HdcHelper:
         length = struct.unpack("!I", reply)[0]
         data_buf = HdcHelper.read(sock, length)
         HdcHelper.reply_to_string(data_buf)
+        LOG.debug("result is {}".format(data_buf))
 
     @staticmethod
     def is_hdc_std():

plugins/ohos/src/ohos/parser/parser.py

@@ -19,7 +19,6 @@
 import copy
 import re
 import time
-import datetime
 import json
 from enum import Enum
 
@@ -32,6 +31,7 @@ from xdevice import StateRecorder
 from xdevice import TestDescription
 from xdevice import ResultCode
 from xdevice import CommonParserType
+from xdevice import get_cst_time
 
 __all__ = ["CppTestParser", "CppTestListParser", "JunitParser", "JSUnitParser",
            "OHKernelTestParser", "OHJSUnitTestParser",
@@ -410,7 +410,7 @@ class JunitParser(IParser):
         self.listeners = []
         self.current_key = None
         self.current_value = None
-        self.start_time = datetime.datetime.now()
+        self.start_time = get_cst_time()
         self.test_time = 0
         self.test_run_finished = False
 
@@ -513,14 +513,14 @@ class JunitParser(IParser):
         test_info.is_completed = True
         self.report_test_run_started(test_info)
         if test_info.code == StatusCodes.START.value:
-            self.start_time = datetime.datetime.now()
+            self.start_time = get_cst_time()
             for listener in self.get_listeners():
                 result = copy.copy(test_info)
                 listener.__started__(LifeCycle.TestCase, result)
         elif test_info.code == StatusCodes.FAILURE.value:
             self.state_machine.running_test_index += 1
             test_info.current = self.state_machine.running_test_index
-            end_time = datetime.datetime.now()
+            end_time = get_cst_time()
             run_time = (end_time - self.start_time).total_seconds()
             test_info.run_time = int(run_time * 1000)
             for listener in self.get_listeners():
@@ -530,7 +530,7 @@ class JunitParser(IParser):
         elif test_info.code == StatusCodes.ERROR.value:
             self.state_machine.running_test_index += 1
             test_info.current = self.state_machine.running_test_index
-            end_time = datetime.datetime.now()
+            end_time = get_cst_time()
             run_time = (end_time - self.start_time).total_seconds()
             test_info.run_time = int(run_time * 1000)
             for listener in self.get_listeners():
@@ -540,7 +540,7 @@ class JunitParser(IParser):
         elif test_info.code == StatusCodes.SUCCESS.value:
             self.state_machine.running_test_index += 1
             test_info.current = self.state_machine.running_test_index
-            end_time = datetime.datetime.now()
+            end_time = get_cst_time()
             run_time = (end_time - self.start_time).total_seconds()
             test_info.run_time = int(run_time * 1000)
             for listener in self.get_listeners():
@@ -548,7 +548,7 @@ class JunitParser(IParser):
                 result.code = ResultCode.PASSED.value
                 listener.__ended__(LifeCycle.TestCase, result)
         elif test_info.code == StatusCodes.IGNORE.value:
-            end_time = datetime.datetime.now()
+            end_time = get_cst_time()
             run_time = (end_time - self.start_time).total_seconds()
             test_info.run_time = int(run_time * 1000)
             for listener in self.get_listeners():
@@ -557,7 +557,7 @@ class JunitParser(IParser):
                 listener.__skipped__(LifeCycle.TestCase, result)
         elif test_info.code == StatusCodes.BLOCKED.value:
             test_info.current = self.state_machine.running_test_index
-            end_time = datetime.datetime.now()
+            end_time = get_cst_time()
             run_time = (end_time - self.start_time).total_seconds()
             test_info.run_time = int(run_time * 1000)
             for listener in self.get_listeners():
@@ -1030,7 +1030,7 @@ class OHJSUnitTestParser(IParser):
         self.listeners = []
         self.current_key = None
         self.current_value = None
-        self.start_time = datetime.datetime.now()
+        self.start_time = get_cst_time()
         self.test_time = 0
         self.test_run_finished = False
         self.cur_sum = -1
@@ -1136,7 +1136,7 @@ class OHJSUnitTestParser(IParser):
             LOG.info("Invalid instrumentation status bundle")
             return
         if test_info.code == StatusCodes.START.value:
-            self.start_time = datetime.datetime.now()
+            self.start_time = get_cst_time()
             for listener in self.get_listeners():
                 result = copy.copy(test_info)
                 listener.__started__(LifeCycle.TestCase, result)
@@ -1144,7 +1144,7 @@ class OHJSUnitTestParser(IParser):
         if test_info.code == StatusCodes.FAILURE.value:
             self.state_machine.running_test_index += 1
             test_info.current = self.state_machine.running_test_index
-            end_time = datetime.datetime.now()
+            end_time = get_cst_time()
             run_time = (end_time - self.start_time).total_seconds()
             test_info.run_time = int(run_time * 1000)
             for listener in self.get_listeners():
@@ -1159,7 +1159,7 @@ class OHJSUnitTestParser(IParser):
         elif test_info.code == StatusCodes.ERROR.value:
             self.state_machine.running_test_index += 1
             test_info.current = self.state_machine.running_test_index
-            end_time = datetime.datetime.now()
+            end_time = get_cst_time()
             run_time = (end_time - self.start_time).total_seconds()
             test_info.run_time = int(run_time * 1000)
             for listener in self.get_listeners():
@@ -1174,7 +1174,7 @@ class OHJSUnitTestParser(IParser):
         elif test_info.code == StatusCodes.SUCCESS.value:
             self.state_machine.running_test_index += 1
             test_info.current = self.state_machine.running_test_index
-            end_time = datetime.datetime.now()
+            end_time = get_cst_time()
             run_time = (end_time - self.start_time).total_seconds()
             test_info.run_time = int(run_time * 1000)
             for listener in self.get_listeners():

plugins/ohos/src/ohos/parser/parser_lite.py

@@ -19,7 +19,6 @@
 import copy
 import re
 import time
-import datetime
 from queue import Queue
 
 from xdevice import IParser
@@ -30,6 +29,7 @@ from xdevice import LifeCycle
 from xdevice import ResultCode
 from xdevice import platform_logger
 from xdevice import check_pub_key_exist
+from xdevice import get_cst_time
 
 from ohos.constants import ParserType
 
@@ -809,7 +809,7 @@ class OpenSourceParser(IParser):
 
     def __process__(self, lines):
         if not self.start_time:
-            self.start_time = datetime.datetime.now()
+            self.start_time = get_cst_time()
         self.lines.extend(lines)
 
     def __done__(self):
@@ -832,7 +832,7 @@ class OpenSourceParser(IParser):
             if _TEST_PASSED_LOWER in line.lower():
                 test_result.code = ResultCode.PASSED.value
                 if self.start_time:
-                    end_time = datetime.datetime.now()
+                    end_time = get_cst_time()
                     run_time = (end_time - self.start_time).total_seconds()
                     test_result.run_time = int(run_time * 1000)
                 for listener in self.get_listeners():
@@ -843,7 +843,7 @@ class OpenSourceParser(IParser):
             test_result.code = ResultCode.FAILED.value
             test_result.stacktrace = "\\n".join(self.lines)
             if self.start_time:
-                end_time = datetime.datetime.now()
+                end_time = get_cst_time()
                 run_time = (end_time - self.start_time).total_seconds()
                 test_result.run_time = int(run_time * 1000)
             for listener in self.get_listeners():

src/xdevice/__init__.py

@@ -102,6 +102,7 @@ from _core.utils import check_path_legal
 from _core.utils import modify_props
 from _core.utils import get_shell_handler
 from _core.utils import get_decode
+from _core.utils import get_cst_time
 from _core.utils import start_standing_subprocess
 from _core.utils import stop_standing_subprocess
 from _core.environment.manager_env import DeviceSelectionOption
@@ -222,6 +223,7 @@ __all__ = [
     "modify_props",
     "get_shell_handler",
     "get_decode",
+    "get_cst_time",
     "start_standing_subprocess",
     "stop_standing_subprocess",
     "ExecInfo",

src/xdevice/_core/executor/request.py

@@ -29,6 +29,7 @@ from _core.plugin import Plugin
 from _core.plugin import get_plugin
 from _core.testkit.json_parser import JsonParser
 from _core.utils import get_kit_instances
+from _core.utils import get_cst_time
 
 __all__ = ["Descriptor", "Task", "Request"]
 LOG = platform_logger("Request")
@@ -71,7 +72,7 @@ class Task:
     def init(self, config):
         from xdevice import Variables
         from xdevice import Scheduler
-        start_time = datetime.datetime.now()
+        start_time = get_cst_time()
         LOG.debug("StartTime=%s" % start_time.strftime("%Y-%m-%d %H:%M:%S"))
 
         self.config.update(config.__dict__)

src/xdevice/_core/executor/scheduler.py

@@ -33,6 +33,7 @@ from _core.utils import convert_serial
 from _core.utils import get_instance_name
 from _core.utils import is_config_str
 from _core.utils import check_result_report
+from _core.utils import get_cst_time
 from _core.environment.manager_env import EnvironmentManager
 from _core.environment.manager_env import DeviceSelectionOption
 from _core.exception import ParamError
@@ -729,10 +730,10 @@ class Scheduler(object):
 
     @classmethod
     def _get_thread_id(cls, current_driver_threads):
-        thread_id = datetime.datetime.now().strftime(
+        thread_id = get_cst_time().strftime(
             '%Y-%m-%d-%H-%M-%S-%f')
         while thread_id in current_driver_threads.keys():
-            thread_id = datetime.datetime.now().strftime(
+            thread_id = get_cst_time().strftime(
                 '%Y-%m-%d-%H-%M-%S-%f')
         return thread_id
 

src/xdevice/_core/utils.py

@@ -28,6 +28,9 @@ import signal
 import uuid
 import json
 import stat
+from datetime import timezone
+from datetime import timedelta
+from datetime import datetime
 from tempfile import NamedTemporaryFile
 
 from _core.executor.listener import SuiteResult
@@ -687,4 +690,10 @@ def do_module_kit_teardown(request):
         for kit in getattr(device, ConfigConst.module_kits, []):
             if check_device_name(device, kit, step="teardown"):
                 kit.__teardown__(device)
-        setattr(device, ConfigConst.module_kits, [])
+        setattr(device, ConfigConst.module_kits, [])
+
+
+def get_cst_time():
+    cn_tz = timezone(timedelta(hours=8),
+                     name='Asia/ShangHai')
+    return datetime.now(tz=cn_tz)