From 2fb7fb2ff487863c3bc931498496da74b25e52d8 Mon Sep 17 00:00:00 2001 From: wyzula-jan Date: Tue, 26 May 2026 10:00:37 +0200 Subject: [PATCH] fix(logging): removed args/kwargs from logging messages --- bec_widgets/cli/rpc/rpc_base.py | 11 +++-------- bec_widgets/utils/bec_dispatcher.py | 9 +++------ bec_widgets/utils/rpc_logging.py | 12 ------------ bec_widgets/utils/rpc_server.py | 18 ++++++------------ tests/unit_tests/test_bec_dispatcher.py | 15 ++++----------- tests/unit_tests/test_rpc_base.py | 4 ---- tests/unit_tests/test_rpc_server.py | 6 ------ 7 files changed, 16 insertions(+), 59 deletions(-) diff --git a/bec_widgets/cli/rpc/rpc_base.py b/bec_widgets/cli/rpc/rpc_base.py index 15091c8b..a5061ae4 100644 --- a/bec_widgets/cli/rpc/rpc_base.py +++ b/bec_widgets/cli/rpc/rpc_base.py @@ -13,8 +13,6 @@ from bec_lib.endpoints import MessageEndpoints from bec_lib.logger import bec_logger from bec_lib.utils.import_utils import lazy_import, lazy_import_from -from bec_widgets.utils.rpc_logging import format_rpc_payload - if TYPE_CHECKING: # pragma: no cover from bec_lib import messages from bec_lib.connector import MessageObject @@ -267,8 +265,6 @@ class RPCBase: ) target_gui_id = gui_id or self._gui_id - args_log = format_rpc_payload(args) - kwargs_log = format_rpc_payload(kwargs) sent_at = time.time() deadline = sent_at + timeout if timeout is not None else None rpc_msg.metadata.update( @@ -287,8 +283,7 @@ class RPCBase: "Sending GUI RPC request " f"request_id={request_id} method={method} receiver={receiver} " f"target_gui_id={target_gui_id} object_name={self.object_name} " - f"wait_for_response={wait_for_rpc_response} timeout={timeout} " - f"args={args_log} kwargs={kwargs_log}" + f"wait_for_response={wait_for_rpc_response} timeout={timeout}" ) self._client.connector.set_and_publish(MessageEndpoints.gui_instructions(receiver), rpc_msg) @@ -300,7 +295,7 @@ class RPCBase: "GUI RPC response timeout " f"request_id={request_id} method={method} receiver={receiver} " f"target_gui_id={target_gui_id} object_name={self.object_name} " - f"timeout={timeout} args={args_log} kwargs={kwargs_log}" + f"timeout={timeout}" ) raise RPCResponseTimeoutError(request_id, timeout) finally: @@ -317,7 +312,7 @@ class RPCBase: "Received GUI RPC response " f"request_id={request_id} method={method} receiver={receiver} " f"target_gui_id={target_gui_id} object_name={self.object_name} " - f"accepted={self._rpc_response.accepted} args={args_log} kwargs={kwargs_log}" + f"accepted={self._rpc_response.accepted}" ) if not self._rpc_response.accepted: raise ValueError(self._rpc_response.message["error"]) diff --git a/bec_widgets/utils/bec_dispatcher.py b/bec_widgets/utils/bec_dispatcher.py index 28b3e139..6f145315 100644 --- a/bec_widgets/utils/bec_dispatcher.py +++ b/bec_widgets/utils/bec_dispatcher.py @@ -16,7 +16,7 @@ from bec_lib.service_config import ServiceConfig from qtpy.QtCore import QObject from qtpy.QtCore import Signal as pyqtSignal -from bec_widgets.utils.rpc_logging import elapsed_seconds, format_elapsed, format_rpc_payload +from bec_widgets.utils.rpc_logging import elapsed_seconds, format_elapsed from bec_widgets.utils.serialization import register_serializer_extension logger = bec_logger.logger @@ -43,23 +43,20 @@ def _log_rpc_dispatcher_receive(msg_content: Any, metadata: Any) -> None: dispatch_latency = elapsed_seconds(sent_at, dispatch_received_at) stale_on_dispatch = deadline is not None and dispatch_received_at > deadline target_gui_id = parameter.get("gui_id") or metadata.get("target_gui_id") - args_log = format_rpc_payload(parameter.get("args", [])) - kwargs_log = format_rpc_payload(parameter.get("kwargs", {})) logger.info( "GUI RPC dispatcher received request before Qt callback emit " f"request_id={request_id} method={method} receiver={metadata.get('receiver')} " f"target_gui_id={target_gui_id} object_name={metadata.get('object_name')} " f"timeout={timeout} dispatch_latency_s={format_elapsed(dispatch_latency)} " - f"stale_on_dispatch={stale_on_dispatch} args={args_log} kwargs={kwargs_log}" + f"stale_on_dispatch={stale_on_dispatch}" ) if stale_on_dispatch: logger.warning( "GUI RPC dispatcher received request after client timeout deadline " f"request_id={request_id} method={method} receiver={metadata.get('receiver')} " f"target_gui_id={target_gui_id} object_name={metadata.get('object_name')} " - f"timeout={timeout} dispatch_latency_s={format_elapsed(dispatch_latency)} " - f"args={args_log} kwargs={kwargs_log}" + f"timeout={timeout} dispatch_latency_s={format_elapsed(dispatch_latency)}" ) diff --git a/bec_widgets/utils/rpc_logging.py b/bec_widgets/utils/rpc_logging.py index 90a21f4f..9ef28b2d 100644 --- a/bec_widgets/utils/rpc_logging.py +++ b/bec_widgets/utils/rpc_logging.py @@ -1,17 +1,5 @@ from __future__ import annotations -from typing import Any - - -def format_rpc_payload(value: Any, limit: int = 500) -> str: - try: - text = repr(value) - except Exception as exc: # pragma: no cover - defensive logging helper - text = f"" - if len(text) <= limit: - return text - return f"{text[:limit]}..." - def elapsed_seconds(start: float | int | None, stop: float) -> float | None: if start is None: diff --git a/bec_widgets/utils/rpc_server.py b/bec_widgets/utils/rpc_server.py index 0163e141..af27e4ca 100644 --- a/bec_widgets/utils/rpc_server.py +++ b/bec_widgets/utils/rpc_server.py @@ -19,7 +19,7 @@ from bec_widgets.utils.bec_connector import BECConnector from bec_widgets.utils.bec_dispatcher import BECDispatcher from bec_widgets.utils.container_utils import WidgetContainerUtils from bec_widgets.utils.error_popups import ErrorPopupUtility -from bec_widgets.utils.rpc_logging import elapsed_seconds, format_elapsed, format_rpc_payload +from bec_widgets.utils.rpc_logging import elapsed_seconds, format_elapsed from bec_widgets.utils.rpc_register import RPCRegister from bec_widgets.utils.screen_utils import apply_window_geometry from bec_widgets.widgets.containers.dock_area.dock_area import BECDockArea @@ -121,8 +121,6 @@ class RPCServer: parameter = msg.get("parameter", {}) args = parameter.get("args", []) kwargs = parameter.get("kwargs", {}) - args_log = format_rpc_payload(args) - kwargs_log = format_rpc_payload(kwargs) target_gui_id = parameter.get("gui_id") sent_at = metadata.get("sent_at") deadline = metadata.get("deadline") @@ -135,15 +133,14 @@ class RPCServer: f"request_id={request_id} method={method} gui_id={self.gui_id} " f"target_gui_id={target_gui_id} timeout={timeout} " f"receive_latency_s={format_elapsed(receive_latency)} " - f"stale_on_receive={stale_on_receive} args={args_log} kwargs={kwargs_log}" + f"stale_on_receive={stale_on_receive}" ) if stale_on_receive: logger.warning( "GUI RPC server received request after client timeout deadline " f"request_id={request_id} method={method} gui_id={self.gui_id} " f"target_gui_id={target_gui_id} timeout={timeout} " - f"receive_latency_s={format_elapsed(receive_latency)} " - f"args={args_log} kwargs={kwargs_log}" + f"receive_latency_s={format_elapsed(receive_latency)}" ) logger.debug(f"Received RPC instruction: {msg}, metadata: {metadata}") execution_start = time.perf_counter() @@ -160,8 +157,7 @@ class RPCServer: logger.error( "GUI RPC server execution failed " f"request_id={request_id} method={method} gui_id={self.gui_id} " - f"target_gui_id={target_gui_id} execution_duration_s={execution_duration:.3f} " - f"args={args_log} kwargs={kwargs_log}\n" + f"target_gui_id={target_gui_id} execution_duration_s={execution_duration:.3f}\n" f"{content}" ) self.send_response(request_id, False, {"error": content}) @@ -172,16 +168,14 @@ class RPCServer: "GUI RPC server executed request " f"request_id={request_id} method={method} gui_id={self.gui_id} " f"target_gui_id={target_gui_id} execution_duration_s={execution_duration:.3f} " - f"response_after_client_deadline={response_stale} " - f"args={args_log} kwargs={kwargs_log}" + f"response_after_client_deadline={response_stale}" ) if response_stale: logger.warning( "GUI RPC server response is late for client timeout " f"request_id={request_id} method={method} gui_id={self.gui_id} " f"target_gui_id={target_gui_id} timeout={timeout} " - f"execution_duration_s={execution_duration:.3f} " - f"args={args_log} kwargs={kwargs_log}" + f"execution_duration_s={execution_duration:.3f}" ) logger.debug(f"RPC instruction executed successfully: {res}") self._rpc_singleshot_repeats[request_id] = SingleshotRPCRepeat() diff --git a/tests/unit_tests/test_bec_dispatcher.py b/tests/unit_tests/test_bec_dispatcher.py index 48bbd8ec..b433e885 100644 --- a/tests/unit_tests/test_bec_dispatcher.py +++ b/tests/unit_tests/test_bec_dispatcher.py @@ -1,12 +1,11 @@ # pylint: disable = no-name-in-module,missing-class-docstring, missing-module-docstring import threading import time -from types import SimpleNamespace from unittest import mock import pytest from bec_lib import service_config -from bec_lib.messages import ScanMessage +from bec_lib.messages import GUIInstructionMessage, ScanMessage from bec_lib.serialization import MsgpackSerialization from bec_widgets.utils.bec_dispatcher import BECDispatcher, QtRedisConnector, QtThreadSafeCallback @@ -227,11 +226,9 @@ def test_qt_redis_connector_logs_rpc_before_qt_callback(monkeypatch): cb = QtThreadSafeCallback(callback) connector = QtRedisConnector("localhost:1", mock.MagicMock()) - rpc_msg = SimpleNamespace( - content={ - "action": "set_value", - "parameter": {"args": [1], "kwargs": {"source": "test"}, "gui_id": "ring"}, - }, + rpc_msg = GUIInstructionMessage( + action="set_value", + parameter={"args": [1], "kwargs": {"source": "test"}, "gui_id": "ring"}, metadata={ "request_id": "dispatcher-request", "receiver": "gui", @@ -255,14 +252,10 @@ def test_qt_redis_connector_logs_rpc_before_qt_callback(monkeypatch): assert "object_name=progressbar" in info_message assert "timeout=0.1" in info_message assert "stale_on_dispatch=True" in info_message - assert "args=[1]" in info_message - assert "kwargs={'source': 'test'}" in info_message warning_mock.assert_called_once() warning_message = warning_mock.call_args.args[0] assert "received request after client timeout deadline" in warning_message assert "request_id=dispatcher-request" in warning_message - assert "args=[1]" in warning_message - assert "kwargs={'source': 'test'}" in warning_message finally: connector.shutdown() diff --git a/tests/unit_tests/test_rpc_base.py b/tests/unit_tests/test_rpc_base.py index 7fc44cf4..ac668654 100644 --- a/tests/unit_tests/test_rpc_base.py +++ b/tests/unit_tests/test_rpc_base.py @@ -76,8 +76,6 @@ def test_run_rpc_logs_response_timeout(monkeypatch): assert publish_msg.metadata["deadline"] == publish_msg.metadata["sent_at"] assert info_mock.call_count == 1 info_message = info_mock.call_args.args[0] - assert "args=(42,)" in info_message - assert "kwargs={'precision': 2}" in info_message error_mock.assert_called_once() error_message = error_mock.call_args.args[0] assert "GUI RPC response timeout" in error_message @@ -85,5 +83,3 @@ def test_run_rpc_logs_response_timeout(monkeypatch): assert "target_gui_id=progress_widget" in error_message assert "object_name=progressbar" in error_message assert "timeout=0" in error_message - assert "args=(42,)" in error_message - assert "kwargs={'precision': 2}" in error_message diff --git a/tests/unit_tests/test_rpc_server.py b/tests/unit_tests/test_rpc_server.py index 03cfd8c1..6ef01531 100644 --- a/tests/unit_tests/test_rpc_server.py +++ b/tests/unit_tests/test_rpc_server.py @@ -198,15 +198,9 @@ def test_on_rpc_update_logs_late_client_deadline(rpc_server, monkeypatch): assert "target_gui_id=ring" in received_log assert "timeout=0.1" in received_log assert "stale_on_receive=True" in received_log - assert "args=[1]" in received_log - assert "kwargs={'source': 'test'}" in received_log assert "response_after_client_deadline=True" in executed_log - assert "args=[1]" in executed_log - assert "kwargs={'source': 'test'}" in executed_log assert "received request after client timeout deadline" in warning_logs assert "response is late for client timeout" in warning_logs - assert "args=[1]" in warning_logs - assert "kwargs={'source': 'test'}" in warning_logs def test_run_rpc_delegates_to_rpc_content_class(rpc_server):