From 98ce3600888844d4b8f6c59d6960ce6a09a0a4a1 Mon Sep 17 00:00:00 2001 From: Xuwznln <18435084+Xuwznln@users.noreply.github.com> Date: Mon, 4 Aug 2025 20:27:02 +0800 Subject: [PATCH] feat: add trace log level --- unilabos/app/mq.py | 2 +- .../virtual/virtual_solid_dispenser.py | 2 +- unilabos/devices/virtual/virtual_stirrer.py | 2 +- unilabos/registry/registry.py | 10 ++--- unilabos/ros/nodes/base_device_node.py | 23 +++++++---- unilabos/ros/nodes/presets/host_node.py | 33 ++++++++++----- unilabos/ros/nodes/presets/protocol_node.py | 4 +- unilabos/utils/log.py | 41 ++++++++++++++++--- 8 files changed, 81 insertions(+), 36 deletions(-) diff --git a/unilabos/app/mq.py b/unilabos/app/mq.py index 1b721902..1d3f9695 100644 --- a/unilabos/app/mq.py +++ b/unilabos/app/mq.py @@ -166,7 +166,7 @@ class MQTTClient: status = {"data": device_status.get(device_id, {}), "device_id": device_id, "timestamp": time.time()} address = f"labs/{MQConfig.lab_id}/devices/" self.client.publish(address, json.dumps(status), qos=2) - logger.info(f"Device {device_id} status published: address: {address}, {status}") + # logger.info(f"Device {device_id} status published: address: {address}, {status}") def publish_job_status(self, feedback_data: dict, job_id: str, status: str, return_info: Optional[str] = None): if self.mqtt_disable: diff --git a/unilabos/devices/virtual/virtual_solid_dispenser.py b/unilabos/devices/virtual/virtual_solid_dispenser.py index 439c3483..54a93ec3 100644 --- a/unilabos/devices/virtual/virtual_solid_dispenser.py +++ b/unilabos/devices/virtual/virtual_solid_dispenser.py @@ -331,7 +331,7 @@ class VirtualSolidDispenser: "precision": self.precision } - self.logger.debug(f"📊 设备信息: 状态={self._status}, 试剂={self._current_reagent}, 加样量={self._dispensed_amount:.6f}g") + # self.logger.debug(f"📊 设备信息: 状态={self._status}, 试剂={self._current_reagent}, 加样量={self._dispensed_amount:.6f}g") return info def __str__(self): diff --git a/unilabos/devices/virtual/virtual_stirrer.py b/unilabos/devices/virtual/virtual_stirrer.py index 2b9058be..cccf61ea 100644 --- a/unilabos/devices/virtual/virtual_stirrer.py +++ b/unilabos/devices/virtual/virtual_stirrer.py @@ -321,7 +321,7 @@ class VirtualStirrer: "min_speed": self._min_speed } - self.logger.debug(f"📊 设备信息: 模式={self.operation_mode}, 速度={self.current_speed} RPM, 搅拌={self.is_stirring}") + # self.logger.debug(f"📊 设备信息: 模式={self.operation_mode}, 速度={self.current_speed} RPM, 搅拌={self.is_stirring}") return info def __str__(self): diff --git a/unilabos/registry/registry.py b/unilabos/registry/registry.py index e1736524..1e789488 100644 --- a/unilabos/registry/registry.py +++ b/unilabos/registry/registry.py @@ -152,11 +152,11 @@ class Registry: } } ) - logger.debug(f"[UniLab Registry] ----------Setup----------") + logger.trace(f"[UniLab Registry] ----------Setup----------") self.registry_paths = [Path(path).absolute() for path in self.registry_paths] for i, path in enumerate(self.registry_paths): sys_path = path.parent - logger.debug(f"[UniLab Registry] Path {i+1}/{len(self.registry_paths)}: {sys_path}") + logger.trace(f"[UniLab Registry] Path {i+1}/{len(self.registry_paths)}: {sys_path}") sys.path.append(str(sys_path)) self.load_device_types(path, complete_registry) if BasicConfig.enable_resource_load: @@ -215,7 +215,7 @@ class Registry: yaml.dump(complete_data, f, allow_unicode=True, default_flow_style=False, Dumper=NoAliasDumper) self.resource_type_registry.update(data) - logger.debug( + logger.trace( f"[UniLab Registry] Resource-{current_resource_number} File-{i+1}/{len(files)} " + f"Add {list(data.keys())}" ) @@ -402,7 +402,7 @@ class Registry: devices_path = abs_path / "devices" device_comms_path = abs_path / "device_comms" files = list(devices_path.glob("*.yaml")) + list(device_comms_path.glob("*.yaml")) - logger.debug( + logger.trace( f"[UniLab Registry] devices: {devices_path.exists()}, device_comms: {device_comms_path.exists()}, " + f"total: {len(files)}" ) @@ -565,7 +565,7 @@ class Registry: } device_config["file_path"] = str(file.absolute()).replace("\\", "/") device_config["registry_type"] = "device" - logger.debug( + logger.trace( f"[UniLab Registry] Device-{current_device_number} File-{i+1}/{len(files)} Add {device_id} " + f"[{data[device_id].get('name', '未命名设备')}]" ) diff --git a/unilabos/ros/nodes/base_device_node.py b/unilabos/ros/nodes/base_device_node.py index 82e59f65..70bb2ece 100644 --- a/unilabos/ros/nodes/base_device_node.py +++ b/unilabos/ros/nodes/base_device_node.py @@ -51,7 +51,7 @@ from unilabos.ros.nodes.resource_tracker import DeviceNodeResourceTracker from unilabos.ros.x.rclpyx import get_event_loop from unilabos.ros.utils.driver_creator import ProtocolNodeCreator, PyLabRobotCreator, DeviceClassCreator from unilabos.utils.async_util import run_async_func -from unilabos.utils.log import info, debug, warning, error, critical, logger +from unilabos.utils.log import info, debug, warning, error, critical, logger, trace from unilabos.utils.type_check import get_type_class, TypeEncoder, serialize_result_info T = TypeVar("T") @@ -82,6 +82,7 @@ class ROSLoggerAdapter: self.level_2_logger_func = { "info": info, "debug": debug, + "trace": trace, "warning": warning, "error": error, "critical": critical, @@ -96,6 +97,10 @@ class ROSLoggerAdapter: ros_log_func(msg) self.level_2_logger_func[level](msg, *args, stack_level=1, **kwargs) + def trace(self, msg, *args, **kwargs): + """记录TRACE级别日志""" + self._log("trace", msg, *args, **kwargs) + def debug(self, msg, *args, **kwargs): """记录DEBUG级别日志""" self._log("debug", msg, *args, **kwargs) @@ -175,12 +180,12 @@ class PropertyPublisher: self.timer = node.create_timer(self.timer_period, self.publish_property) self.__loop = get_event_loop() str_msg_type = str(msg_type)[8:-2] - self.node.lab_logger().debug(f"发布属性: {name}, 类型: {str_msg_type}, 周期: {initial_period}秒") + self.node.lab_logger().trace(f"发布属性: {name}, 类型: {str_msg_type}, 周期: {initial_period}秒") def get_property(self): if asyncio.iscoroutinefunction(self.get_method): # 如果是异步函数，运行事件循环并等待结果 - self.node.lab_logger().debug(f"【PropertyPublisher.get_property】获取异步属性: {self.name}") + self.node.lab_logger().trace(f"【PropertyPublisher.get_property】获取异步属性: {self.name}") loop = self.__loop if loop: future = asyncio.run_coroutine_threadsafe(self.get_method(), loop) @@ -191,28 +196,28 @@ class PropertyPublisher: return None else: # 如果是同步函数，直接调用并返回结果 - self.node.lab_logger().debug(f"【PropertyPublisher.get_property】获取同步属性: {self.name}") + self.node.lab_logger().trace(f"【PropertyPublisher.get_property】获取同步属性: {self.name}") self._value = self.get_method() return self._value async def get_property_async(self): try: # 获取异步属性值 - self.node.lab_logger().debug(f"【PropertyPublisher.get_property_async】异步获取属性: {self.name}") + self.node.lab_logger().trace(f"【PropertyPublisher.get_property_async】异步获取属性: {self.name}") self._value = await self.get_method() except Exception as e: self.node.lab_logger().error(f"【PropertyPublisher.get_property_async】获取异步属性出错: {str(e)}") def publish_property(self): try: - self.node.lab_logger().debug(f"【PropertyPublisher.publish_property】开始发布属性: {self.name}") + self.node.lab_logger().trace(f"【PropertyPublisher.publish_property】开始发布属性: {self.name}") value = self.get_property() if self.print_publish: - self.node.lab_logger().info(f"【PropertyPublisher.publish_property】发布 {self.msg_type}: {value}") + self.node.lab_logger().trace(f"【PropertyPublisher.publish_property】发布 {self.msg_type}: {value}") if value is not None: msg = convert_to_ros_msg(self.msg_type, value) self.publisher_.publish(msg) - self.node.lab_logger().debug(f"【PropertyPublisher.publish_property】属性 {self.name} 发布成功") + self.node.lab_logger().trace(f"【PropertyPublisher.publish_property】属性 {self.name} 发布成功") except Exception as e: self.node.lab_logger().error(f"【PropertyPublisher.publish_property】发布属性 {self.publisher_.topic} 出错: {str(e)}\n{traceback.format_exc()}") @@ -606,7 +611,7 @@ class BaseROS2DeviceNode(Node, Generic[T]): callback_group=ReentrantCallbackGroup(), ) - self.lab_logger().debug(f"发布动作: {action_name}, 类型: {str_action_type}") + self.lab_logger().trace(f"发布动作: {action_name}, 类型: {str_action_type}") def get_real_function(self, instance, attr_name): if hasattr(instance.__class__, attr_name): diff --git a/unilabos/ros/nodes/presets/host_node.py b/unilabos/ros/nodes/presets/host_node.py index 9b598ddf..2b11e452 100644 --- a/unilabos/ros/nodes/presets/host_node.py +++ b/unilabos/ros/nodes/presets/host_node.py @@ -1,3 +1,4 @@ +import collections import copy import json import threading @@ -254,7 +255,7 @@ class HostNode(BaseROS2DeviceNode): 检测ROS2网络中的所有设备节点，并为它们创建ActionClient 同时检测设备离线情况 """ - self.lab_logger().debug("[Host Node] Discovering devices in the network...") + self.lab_logger().trace("[Host Node] Discovering devices in the network...") # 获取当前所有设备 nodes_and_names = self.get_node_names_and_namespaces() @@ -303,7 +304,7 @@ class HostNode(BaseROS2DeviceNode): # 更新在线设备列表 self._online_devices = current_devices - self.lab_logger().debug(f"[Host Node] Total online devices: {len(self._online_devices)}") + self.lab_logger().trace(f"[Host Node] Total online devices: {len(self._online_devices)}") def _discovery_devices_callback(self) -> None: """ @@ -335,7 +336,7 @@ class HostNode(BaseROS2DeviceNode): self._action_clients[action_id] = ActionClient( self, action_type, action_id, callback_group=self.callback_group ) - self.lab_logger().debug(f"[Host Node] Created ActionClient (Discovery): {action_id}") + self.lab_logger().trace(f"[Host Node] Created ActionClient (Discovery): {action_id}") action_name = action_id[len(namespace) + 1 :] edge_device_id = namespace[9:] # from unilabos.app.mq import mqtt_client @@ -476,7 +477,7 @@ class HostNode(BaseROS2DeviceNode): if action_id not in self._action_clients: action_type = action_value_mapping["type"] self._action_clients[action_id] = ActionClient(self, action_type, action_id) - self.lab_logger().debug( + self.lab_logger().trace( f"[Host Node] Created ActionClient (Local): {action_id}" ) # 子设备再创建用的是Discover发现的 # from unilabos.app.mq import mqtt_client @@ -521,7 +522,7 @@ class HostNode(BaseROS2DeviceNode): self.device_status_timestamps[device_id] = {} # 默认初始化属性值为 None - self.device_status[device_id][property_name] = None + self.device_status[device_id] = collections.defaultdict() self.device_status_timestamps[device_id][property_name] = 0 # 初始化时间戳 # 动态创建订阅 @@ -539,7 +540,7 @@ class HostNode(BaseROS2DeviceNode): ) # 标记为已订阅 self._subscribed_topics.add(topic) - self.lab_logger().debug(f"[Host Node] Subscribed to new topic: {topic}") + self.lab_logger().trace(f"[Host Node] Subscribed to new topic: {topic}") except (NameError, SyntaxError) as e: self.lab_logger().error(f"[Host Node] Failed to create subscription for topic {topic}: {e}") @@ -557,10 +558,15 @@ class HostNode(BaseROS2DeviceNode): # 更新设备状态字典 if hasattr(msg, "data"): bChange = False + bCreate = False if isinstance(msg.data, (float, int, str)): - if self.device_status[device_id][property_name] != msg.data: + if property_name not in self.device_status[device_id]: + bCreate = True bChange = True - self.device_status[device_id][property_name] = msg.data + self.device_status[device_id][property_name] = msg.data + elif self.device_status[device_id][property_name] != msg.data: + bChange = True + self.device_status[device_id][property_name] = msg.data # 更新时间戳 self.device_status_timestamps[device_id][property_name] = time.time() else: @@ -573,9 +579,14 @@ class HostNode(BaseROS2DeviceNode): for bridge in self.bridges: if hasattr(bridge, "publish_device_status"): bridge.publish_device_status(self.device_status, device_id, property_name) - self.lab_logger().debug( - f"[Host Node] Status updated: {device_id}.{property_name} = {msg.data}" - ) + if bCreate: + self.lab_logger().trace( + f"Status created: {device_id}.{property_name} = {msg.data}" + ) + else: + self.lab_logger().debug( + f"Status updated: {device_id}.{property_name} = {msg.data}" + ) def send_goal( self, diff --git a/unilabos/ros/nodes/presets/protocol_node.py b/unilabos/ros/nodes/presets/protocol_node.py index 6f491c72..833e1892 100644 --- a/unilabos/ros/nodes/presets/protocol_node.py +++ b/unilabos/ros/nodes/presets/protocol_node.py @@ -151,7 +151,7 @@ class ROS2ProtocolNode(BaseROS2DeviceNode): except Exception as ex: self.lab_logger().error(f"创建动作客户端失败: {action_id}, 错误: {ex}") continue - self.lab_logger().debug(f"为子设备 {device_id} 创建动作客户端: {action_name}") + self.lab_logger().trace(f"为子设备 {device_id} 创建动作客户端: {action_name}") return d def create_ros_action_server(self, action_name, action_value_mapping): @@ -171,7 +171,7 @@ class ROS2ProtocolNode(BaseROS2DeviceNode): callback_group=ReentrantCallbackGroup(), ) - self.lab_logger().debug(f"发布动作: {action_name}, 类型: {str_action_type}") + self.lab_logger().trace(f"发布动作: {action_name}, 类型: {str_action_type}") def _create_protocol_execute_callback(self, protocol_name, protocol_steps_generator): async def execute_protocol(goal_handle: ServerGoalHandle): diff --git a/unilabos/utils/log.py b/unilabos/utils/log.py index a6801018..74442a62 100644 --- a/unilabos/utils/log.py +++ b/unilabos/utils/log.py @@ -7,6 +7,10 @@ import atexit import inspect from typing import Tuple, cast +# 添加TRACE级别到logging模块 +TRACE_LEVEL = 5 +logging.addLevelName(TRACE_LEVEL, "TRACE") + class CustomRecord: custom_stack_info: Tuple[str, int, str, str] @@ -44,11 +48,13 @@ class ColoredFormatter(logging.Formatter): "GRAY": "\033[37m", # 灰色 "WHITE": "\033[97m", # 白色 "BLACK": "\033[30m", # 黑色 + "TRACE_LEVEL": "\033[1;90m", # 加粗深灰色 "DEBUG_LEVEL": "\033[1;36m", # 加粗青色 "INFO_LEVEL": "\033[1;32m", # 加粗绿色 "WARNING_LEVEL": "\033[1;33m", # 加粗黄色 "ERROR_LEVEL": "\033[1;31m", # 加粗红色 "CRITICAL_LEVEL": "\033[1;35m", # 加粗紫色 + "TRACE_TEXT": "\033[90m", # 深灰色 "DEBUG_TEXT": "\033[37m", # 灰色 "INFO_TEXT": "\033[97m", # 白色 "WARNING_TEXT": "\033[33m", # 黄色 @@ -148,8 +154,8 @@ def configure_logger(loglevel=None): """配置日志记录器 Args: - loglevel: 日志级别，可以是字符串（'DEBUG', 'INFO', 'WARNING', 'ERROR', 'CRITICAL'） - 或logging模块的常量（如logging.DEBUG） + loglevel: 日志级别，可以是字符串（'TRACE', 'DEBUG', 'INFO', 'WARNING', 'ERROR', 'CRITICAL'） + 或logging模块的常量（如logging.DEBUG）或TRACE_LEVEL """ # 获取根日志记录器 root_logger = logging.getLogger() @@ -158,10 +164,13 @@ def configure_logger(loglevel=None): if loglevel is not None: if isinstance(loglevel, str): # 将字符串转换为logging级别 - numeric_level = getattr(logging, loglevel.upper(), None) - if not isinstance(numeric_level, int): - print(f"警告: 无效的日志级别 '{loglevel}'，使用默认级别 DEBUG") - numeric_level = logging.DEBUG + if loglevel.upper() == "TRACE": + numeric_level = TRACE_LEVEL + else: + numeric_level = getattr(logging, loglevel.upper(), None) + if not isinstance(numeric_level, int): + print(f"警告: 无效的日志级别 '{loglevel}'，使用默认级别 DEBUG") + numeric_level = logging.DEBUG else: numeric_level = loglevel root_logger.setLevel(numeric_level) @@ -318,9 +327,29 @@ def critical(msg, *args, stack_level=0, **kwargs): logger.critical(msg, *args, **kwargs) +def trace(msg, *args, stack_level=0, **kwargs): + """ + 记录TRACE级别日志（比DEBUG级别更低） + + Args: + msg: 日志消息 + stack_level: 堆栈回溯级别，用于定位日志的实际调用位置 + *args, **kwargs: 传递给logger.log的其他参数 + """ + if stack_level > 0: + caller_info = _get_caller_info(stack_level) + extra = kwargs.get("extra", {}) + extra["custom_stack_info"] = caller_info + kwargs["extra"] = extra + logger.log(TRACE_LEVEL, msg, *args, **kwargs) + + +logger.trace = trace + # 测试日志输出（如果直接运行此文件） if __name__ == "__main__": print("测试不同日志级别的颜色输出:") + trace("这是一条跟踪日志 (TRACE级别显示为深灰色，其他文本也为深灰色)") debug("这是一条调试日志 (DEBUG级别显示为蓝色，其他文本为灰色)") info("这是一条信息日志 (INFO级别显示为绿色，其他文本为白色)") warning("这是一条警告日志 (WARNING级别显示为黄色，其他文本也为黄色)")