fix(logging): removed args/kwargs from logging messages

This commit is contained in:
2026-05-26 10:00:37 +02:00
committed by Jan Wyzula
parent c8275fcfd5
commit 2fb7fb2ff4
7 changed files with 16 additions and 59 deletions
+3 -8
View File
@@ -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"])
+3 -6
View File
@@ -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)}"
)
-12
View File
@@ -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"<unrepresentable {type(value).__name__}: {exc}>"
if len(text) <= limit:
return text
return f"{text[:limit]}...<truncated {len(text) - limit} chars>"
def elapsed_seconds(start: float | int | None, stop: float) -> float | None:
if start is None:
+6 -12
View File
@@ -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()
+4 -11
View File
@@ -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()
-4
View File
@@ -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
-6
View File
@@ -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):