[chore] add end-to-end mouse input diagnostics

2026-10-16 17:10:20 +08:00 · 2026-09-17 00:42:41 +08:00
parent 28de4cf938
commit afe42be672
11 changed files with 245 additions and 12 deletions
@@ -35,6 +35,7 @@
 #include "platform/video_renderer.h"
 #include "rendering/slint_video_presenter.h"
 #include "runtime/privacy_control_state.h"
+#include "runtime/mouse_input_trace.h"
 #if _WIN32
 #include <windows.h>

@@ -878,6 +879,7 @@ void DragWindow(WindowHandle& component, int phase, float mouse_x,
 }  // namespace

 struct GuiApplication::SlintUi {
+  MouseTraceState unrouted_mouse_trace;
  slint::ComponentHandle<ui::MainWindow> main = ui::MainWindow::create();
  std::shared_ptr<slint::VectorModel<ui::ReleaseNoteBlock>>
      release_note_blocks_model =
@@ -1737,6 +1739,22 @@ void GuiApplication::BindStreamCallbacks() {
      CloseStreamTab(props->remote_id_);
    }
  });
+  stream->on_pointer_observed([this](slint::PointerEventButton button,
+                                     slint::PointerEventKind kind,
+                                     bool local_ui, bool dragging,
+                                     bool suppressed) {
+    auto props = SelectedSession();
+    auto& state = props ? props->mouse_ui_trace_ : ui_->unrouted_mouse_trace;
+    const auto ticket = state.Next();
+    if (ticket.sampled) {
+      LOG_INFO("Mouse UI event: peer=[{}] event={} mono_us={} button={} kind={} "
+               "local_ui={} dragging={} suppressed={} window_focus={}",
+               props ? props->remote_id_ : "none", ticket.event,
+               ticket.started_us, static_cast<int>(button),
+               static_cast<int>(kind), local_ui, dragging, suppressed,
+               focus_on_stream_window_);
+    }
+  });
  stream->on_pointer_input([this](slint::PointerEventButton button,
                                  slint::PointerEventKind kind, float x,
                                  float y) {
@@ -2448,6 +2466,7 @@ void GuiApplication::SyncStreamWindow() {
    (*ui_->stream)->set_stats_rows(ui_->stats_model);
    BindStreamCallbacks();
    (*ui_->stream)->show();
+    LOG_INFO("Mouse UI stream window shown");
    // Repeat after the next layout pass because the backend resolves the
    // initial DPI and preferred size asynchronously on some platforms.
    ui_->stream_initial_position_attempts = 2;
@@ -3141,6 +3160,9 @@ void GuiApplication::SelectStreamTab(int index) {
  }
  const std::string selected_remote_id = ui_->tab_ids[index];
  const bool selection_changed = focused_remote_id_ != selected_remote_id;
+  if (selection_changed) {
+    LOG_INFO("Mouse UI selected peer=[{}]", selected_remote_id);
+  }
  bool renderer_selection_changed = false;
  if (!controlled_remote_id_.empty() &&
      controlled_remote_id_ != selected_remote_id) {
@@ -3245,7 +3267,12 @@ GuiApplication::SelectedSession() {

 void GuiApplication::SendPointerInput(int button, int kind, float x, float y) {
  auto props = SelectedSession();
+  MouseInputTrace trace(props ? &props->mouse_send_trace_ :
+                                &ui_->unrouted_mouse_trace,
+                        props ? props->remote_id_ : "none", "pointer");
  if (!props || !props->peer_ || !props->control_mouse_ || !ui_->stream) {
+    trace.Result(!props ? "no_session" : !props->peer_ ? "no_peer" :
+                 !props->control_mouse_ ? "control_disabled" : "no_window");
    return;
  }

@@ -3279,11 +3306,13 @@ void GuiApplication::SendPointerInput(int button, int kind, float x, float y) {
  }
  if (x < offset_x || x > offset_x + render_width || y < offset_y ||
      y > offset_y + render_height) {
+    trace.Result("outside_video");
    return;
  }

  RemoteAction action{};
  action.type = ControlType::mouse;
+  trace.Result("unsupported_pointer_event");
  action.m.x = std::clamp((x - offset_x) / render_width, 0.0f, 1.0f);
  action.m.y = std::clamp((y - offset_y) / render_height, 0.0f, 1.0f);
  // Slint enum order: Cancel=0, Down=1, Up=2, Move=3 and
@@ -3314,18 +3343,30 @@ void GuiApplication::SendPointerInput(int button, int kind, float x, float y) {

  controlled_remote_id_ = props->remote_id_;
  const std::string message = action.to_json();
+  trace.Result("pending");
+  trace.Payload(message.data(), message.size());
+  trace.Stage("cursor_state");
  {
    std::lock_guard lock(props->remote_cursor_state_mutex_);
    props->cursor_presentation_.NoteInput(SDL_GetTicks());
  }
-  SendDataFrame(props->peer_, message.c_str(), message.size(),
-                props->mouse_label_.c_str());
+  trace.Stage("send_api");
+  const int ret = SendDataFrame(props->peer_, message.c_str(), message.size(),
+                                props->mouse_label_.c_str());
+  // This API may only acknowledge dispatch. The transport logs the actual
+  // ICE send result separately using the same payload tag.
+  trace.Result("send_api_returned", ret, ret != 0);
 }

 void GuiApplication::SendScrollInput(float delta_x, float delta_y, float x,
                                     float y) {
  auto props = SelectedSession();
+  MouseInputTrace trace(props ? &props->mouse_send_trace_ :
+                                &ui_->unrouted_mouse_trace,
+                        props ? props->remote_id_ : "none", "scroll");
  if (!props || !props->peer_ || !props->control_mouse_ || !ui_->stream) {
+    trace.Result(!props ? "no_session" : !props->peer_ ? "no_peer" :
+                 !props->control_mouse_ ? "control_disabled" : "no_window");
    return;
  }
  const auto size = (*ui_->stream)->window().size();
@@ -3340,6 +3381,7 @@ void GuiApplication::SendScrollInput(float delta_x, float delta_y, float x,
      (fullscreen_button_pressed_ ? 0.0f
                                  : (ui_->tab_ids.size() > 1 ? 30.0f : 0.0f));
  if (width <= 0 || height <= 0) {
+    trace.Result("invalid_geometry");
    return;
  }
  RemoteAction action{};
@@ -3354,6 +3396,7 @@ void GuiApplication::SendScrollInput(float delta_x, float delta_y, float x,
    action.m.s = delta_x > 0 ? 1 : delta_x < 0 ? -1 : 0;
  }
  if (action.m.s == 0) {
+    trace.Result("zero_scroll");
    return;
  }
  {
@@ -3362,8 +3405,11 @@ void GuiApplication::SendScrollInput(float delta_x, float delta_y, float x,
  }
  controlled_remote_id_ = props->remote_id_;
  const std::string message = action.to_json();
-  SendDataFrame(props->peer_, message.c_str(), message.size(),
-                props->mouse_label_.c_str());
+  trace.Payload(message.data(), message.size());
+  trace.Stage("send_api");
+  const int ret = SendDataFrame(props->peer_, message.c_str(), message.size(),
+                                props->mouse_label_.c_str());
+  trace.Result("send_api_returned", ret, ret != 0);
 }

 void GuiApplication::SendKeyInput(const std::string& text, bool pressed,
@@ -370,6 +370,8 @@ int SessionDeviceManager::StartMouseController() {
  }

  const int init_ret = mouse_controller_->Init(display_info_list_);
+  LOG_INFO("Mouse controller initialization: ret={}, displays={}", init_ret,
+           display_info_list_.size());
  if (init_ret != 0) {
    LOG_INFO("Destroy mouse controller");
    mouse_controller_->Destroy();
@@ -632,11 +634,12 @@ bool SessionDeviceManager::SendKeyboardCommand(int key_code, bool is_down,
                                   key_code, is_down, scan_code, extended) == 0;
 }

-void SessionDeviceManager::SendMouseCommand(const RemoteAction &action,
+int SessionDeviceManager::SendMouseCommand(const RemoteAction &action,
                                            int selected_display) {
  if (mouse_controller_) {
-    mouse_controller_->SendMouseCommand(action, selected_display);
+    return mouse_controller_->SendMouseCommand(action, selected_display);
  }
+  return -2;
 }

 int SessionDeviceManager::SwitchDisplay(int display_id) {
@@ -70,7 +70,8 @@ public:

  bool SendKeyboardCommand(int key_code, bool is_down, uint32_t scan_code,
                           bool extended);
-  void SendMouseCommand(const RemoteAction &action, int selected_display);
+  // -2 means the mouse controller has not been initialized.
+  int SendMouseCommand(const RemoteAction &action, int selected_display);
  int SwitchDisplay(int display_id);
  void ResetToInitialDisplay();

@@ -0,0 +1,88 @@
+#ifndef CROSSDESK_MOUSE_INPUT_TRACE_H_
+#define CROSSDESK_MOUSE_INPUT_TRACE_H_
+
+#include <minirtc_mouse_trace.h>
+
+#include <string>
+
+#include "rd_log.h"
+
+namespace crossdesk {
+using MouseTraceState = minirtc::diagnostics::MouseTraceState;
+
+// Log entry before any potentially blocking check, and report each stage's
+// duration. Steady-clock timestamps are comparable only within one process.
+class MouseInputTrace {
+ public:
+  MouseInputTrace(MouseTraceState* state, const std::string& peer,
+                  const char* scope, const void* data = nullptr,
+                  size_t size = 0)
+      : state_(state), peer_(peer), scope_(scope) {
+    if (!state_) return;
+    ticket_ = state_->Next();
+    stage_started_us_ = ticket_.started_us;
+    if (data) tag_ = minirtc::diagnostics::MousePayloadTag(data, size);
+    Log("begin", 0, false);
+    stage_started_us_ = minirtc::diagnostics::MouseTraceNowUs();
+  }
+  MouseInputTrace(const MouseInputTrace&) = delete;
+  MouseInputTrace& operator=(const MouseInputTrace&) = delete;
+  ~MouseInputTrace() {
+    if (state_)
+      Log("end", minirtc::diagnostics::MouseTraceNowUs() - stage_started_us_,
+          failed_);
+  }
+
+  void Stage(const char* stage) {
+    if (!state_) return;
+    const auto now = minirtc::diagnostics::MouseTraceNowUs();
+    Log("stage_done", now - stage_started_us_, false);
+    stage_ = stage;
+    stage_started_us_ = minirtc::diagnostics::MouseTraceNowUs();
+    Log("stage_begin", 0, false);
+    // Exclude synchronous logger flush time from the measured operation.
+    stage_started_us_ = minirtc::diagnostics::MouseTraceNowUs();
+  }
+  void Payload(const void* data, size_t size) {
+    tag_ = minirtc::diagnostics::MousePayloadTag(data, size);
+  }
+  void Result(const char* outcome, int result = 0, bool failed = false) {
+    outcome_ = outcome;
+    result_ = result;
+    failed_ = failed;
+  }
+
+ private:
+  void Log(const char* phase, int64_t stage_us, bool failed) {
+    const bool problem =
+        failed || stage_us >= minirtc::diagnostics::kSlowMouseTraceUs;
+    const bool warn = problem && state_->Problem();
+    if (!ticket_.sampled && !warn) return;
+    const auto now = minirtc::diagnostics::MouseTraceNowUs();
+    if (warn) {
+      LOG_WARN(
+          "Mouse trace: scope={} peer=[{}] event={} tag={:016x} phase={} "
+          "stage={} stage_us={} total_us={} mono_us={} outcome={} ret={}",
+          scope_, peer_, ticket_.event, tag_, phase, stage_, stage_us,
+          now - ticket_.started_us, now, outcome_, result_);
+    } else {
+      LOG_INFO(
+          "Mouse trace: scope={} peer=[{}] event={} tag={:016x} phase={} "
+          "stage={} stage_us={} total_us={} mono_us={} outcome={} ret={}",
+          scope_, peer_, ticket_.event, tag_, phase, stage_, stage_us,
+          now - ticket_.started_us, now, outcome_, result_);
+    }
+  }
+  MouseTraceState* state_;
+  std::string peer_;
+  const char* scope_;
+  const char* stage_ = "entry";
+  const char* outcome_ = "pending";
+  minirtc::diagnostics::MouseTraceTicket ticket_{};
+  int64_t stage_started_us_ = 0;
+  uint64_t tag_ = 0;
+  int result_ = 0;
+  bool failed_ = false;
+};
+}  // namespace crossdesk
+#endif
@@ -21,6 +21,7 @@
 #include "rd_log.h"
 #include "runtime/gui_runtime.h"
 #include "runtime/remote_action_codec.h"
+#include "runtime/mouse_input_trace.h"

 #if _WIN32
 #include "interactive_state.h"
@@ -88,6 +89,18 @@ void PeerEventHandler::OnReceiveDataBuffer(
  }

  std::string source_id = std::string(src_id, src_id_size);
+  std::shared_ptr<MouseTraceState> mouse_trace_state;
+  if (source_id == runtime->mouse_label_) {
+    std::lock_guard lock(handler->mouse_traces_mutex_);
+    auto& state = handler->mouse_traces_[std::string(user_id, user_id_size)];
+    if (!state) state = std::make_shared<MouseTraceState>();
+    mouse_trace_state = state;
+  }
+  // Before JSON parsing, authorization, or Windows session queries. An entry
+  // without a matching stage completion pinpoints a blocked callback.
+  MouseInputTrace mouse_trace(mouse_trace_state.get(),
+                              std::string(user_id, user_id_size),
+                              "receive", data, size);
  if (source_id == runtime->file_label_) {
    std::string remote_user_id = std::string(user_id, user_id_size);

@@ -141,7 +154,9 @@ void PeerEventHandler::OnReceiveDataBuffer(

  std::string json_str(data, size);
  RemoteAction remote_action{};
+  mouse_trace.Stage("parse");
  if (!remote_action.from_json(json_str)) {
+    mouse_trace.Result("invalid_payload", -1, true);
    LOG_ERROR("Failed to parse RemoteAction JSON payload");
    return;
  }
@@ -174,7 +189,12 @@ void PeerEventHandler::OnReceiveDataBuffer(
      remote_action.type == ControlType::service_command || remote_action.type == ControlType::display_id ||
      remote_action.type == ControlType::audio_capture;
  if (operates_host) {
-    if (!runtime->IsAuthorizedController(remote_id)) return;
+    mouse_trace.Stage("authorize");
+    if (!runtime->IsAuthorizedController(remote_id)) {
+      mouse_trace.Result("unauthorized", -1, true);
+      return;
+    }
+    mouse_trace.Stage("desktop_check");
 #ifdef _WIN32
    // KeyboardController checks the desktop immediately before each native
    // key injection, including state reconciliation and cleanup. Avoid a
@@ -186,6 +206,7 @@ void PeerEventHandler::OnReceiveDataBuffer(
      runtime->privacy_.Fail("Secure desktop or lock screen; privacy screen will turn off");
    }
 #endif
+    mouse_trace.Stage("dispatch");
  }
  if (remote_action.type == ControlType::service_status) {
    if (auto props = runtime->FindRemoteSession(remote_id)) {
@@ -324,6 +345,7 @@ void PeerEventHandler::OnReceiveDataBuffer(
                                        runtime->selected_display_,
                                        remote_action.m.x, remote_action.m.y,
                                        &absolute_x, &absolute_y)) {
+          mouse_trace.Result("invalid_display", -1, true);
          LOG_WARN("Secure desktop mouse injection skipped, invalid display "
                   "mapping: display_index={}, x={}, y={}",
                   runtime->selected_display_, remote_action.m.x,
@@ -331,10 +353,14 @@ void PeerEventHandler::OnReceiveDataBuffer(
          return;
        }

+        mouse_trace.Stage("secure_desktop_inject");
        const std::string response = SendCrossDeskSecureDesktopMouseInput(
            absolute_x, absolute_y, remote_action.m.s,
            static_cast<int>(remote_action.m.flag), 1000);
        auto json = nlohmann::json::parse(response, nullptr, false);
+        const bool submitted = !json.is_discarded() && json.value("ok", false);
+        mouse_trace.Result(submitted ? "submitted" : "secure_inject_failed",
+                           submitted ? 0 : -1, !submitted);
        if (json.is_discarded() || !json.value("ok", false)) {
          LogSecureDesktopInputBlocked(
              &runtime->last_local_secure_input_block_log_tick_, "local",
@@ -350,8 +376,11 @@ void PeerEventHandler::OnReceiveDataBuffer(
    }
 #endif
    if (remote_action.type == ControlType::mouse) {
-      runtime->devices_.SendMouseCommand(remote_action,
-                                        runtime->selected_display_);
+      mouse_trace.Stage("normal_desktop_inject");
+      const int ret = runtime->devices_.SendMouseCommand(
+          remote_action, runtime->selected_display_);
+      mouse_trace.Result(ret == -2 ? "no_controller" :
+                        ret != 0 ? "inject_failed" : "submitted", ret, ret != 0);
    } else if (remote_action.type == ControlType::audio_capture) {
      if (remote_action.a)
        runtime->devices_.StartSpeakerCapturer();
@@ -242,6 +242,13 @@ void PeerEventHandler::OnConnectionStatus(ConnectionStatus status,

  std::string remote_id(user_id, user_id_size);
  std::shared_ptr<GuiRuntime::RemoteSession> props;
+  LOG_INFO("Input connection status: peer=[{}], status={}", remote_id,
+           static_cast<int>(status));
+  if (status == ConnectionStatus::Disconnected ||
+      status == ConnectionStatus::Failed || status == ConnectionStatus::Closed) {
+    std::lock_guard lock(handler->mouse_traces_mutex_);
+    handler->mouse_traces_.erase(remote_id);
+  }
  {
    std::shared_lock lock(runtime->remote_sessions_mutex_);
    auto it = runtime->remote_sessions_.find(remote_id);
@@ -9,6 +9,10 @@

 #include <cstddef>
 #include <string>
+#include <memory>
+#include <mutex>
+#include <unordered_map>
+#include <minirtc_mouse_trace.h>

 #include "minirtc.h"
 #include "runtime/session_lifecycle.h"
@@ -54,9 +58,12 @@ private:
  static void SendClientInfo(PeerPtr *peer, const std::string &client_id);

  GuiRuntime &owner_;
+  std::mutex mouse_traces_mutex_;
+  std::unordered_map<std::string,
+      std::shared_ptr<minirtc::diagnostics::MouseTraceState>> mouse_traces_;
  gui_detail::SessionCallbackGate callbacks_;
 };

 } // namespace crossdesk

-#endif
+#endif
@@ -24,6 +24,7 @@
 #include "display_info.h"
 #include "cursor_presentation.h"
 #include "minirtc.h"
+#include <minirtc_mouse_trace.h>

 namespace crossdesk { class PeerEventHandler; }

@@ -68,6 +69,8 @@ struct FileTransferState {
 // Runtime state for one connected or connecting remote endpoint. It groups the
 // connection, media, input, window and transfer data that share one lifetime.
 struct RemoteSession {
+  minirtc::diagnostics::MouseTraceState mouse_ui_trace_;
+  minirtc::diagnostics::MouseTraceState mouse_send_trace_;
  Params params_;
  PeerPtr* peer_ = nullptr;
  std::shared_ptr<PeerEventHandler> peer_events_;
@@ -189,6 +189,7 @@ export component StreamWindow inherits Window {
    callback toggle-maximize-stream-window;
    callback close-stream-window;
    callback pointer-input(PointerEventButton, PointerEventKind, length, length);
+    callback pointer-observed(PointerEventButton, PointerEventKind, bool, bool, bool);
    callback scroll-input(length, length, length, length);
    callback key-input(string, bool, bool, bool, bool, bool);
    callback keyboard-focus-changed(bool);
@@ -639,6 +640,9 @@ export component StreamWindow inherits Window {
                            root.suppress-next-remote-pointer-release
                            && (event.kind == PointerEventKind.up
                                || event.kind == PointerEventKind.cancel);
+                        root.pointer-observed(event.button, event.kind,
+                            over-local-ui, root.control-dragging,
+                            suppress-remote-release);
                        if event.kind == PointerEventKind.down && !over-local-ui {
                            // Discard a stale marker if a popup consumed the
                            // whole previous gesture, including its release.
@@ -0,0 +1,45 @@
+# 鼠标输入启动诊断
+
+控制端和被控端都需要重新编译 CrossDesk 及 `deps/submodules/minirtc`。
+诊断默认使用 INFO/WARN 日志。连接后立即在远端画面内持续移动鼠标，
+保留两端同一次运行的 `crossdesk-*.log` 和 `minirtc-*.log`。
+
+## 记录顺序
+
+| 日志 | 所在端 | 含义 |
+| --- | --- | --- |
+| `Input connection status` | 两端 CrossDesk | 上层连接状态变化 |
+| `Mouse UI stream window shown` / `Mouse UI selected` | 控制端 CrossDesk | 窗口显示和当前会话选择 |
+| `Mouse UI event` | 控制端 CrossDesk | Slint 视频输入区域收到事件，包含本地 UI 遮挡、拖动和释放抑制状态 |
+| `Mouse trace: scope=pointer` / `scope=scroll` | 控制端 CrossDesk | 转发入口、过滤原因、调用发送 API 的时间和返回值 |
+| `Mouse transport dispatch` | 控制端 MiniRTC | 连接与 ICE 就绪检查及传输层返回值 |
+| `Mouse RTP enqueue` | 控制端 MiniRTC | 实际入队结果，队列满时明确记录 |
+| `Mouse RTP send begin` / `send end` | 控制端 MiniRTC | 队列等待、底层发送调用耗时及真实返回值 |
+| `Mouse RTP receive` | 被控端 MiniRTC | RTP 包进入鼠标数据通道，位于应用回调之前 |
+| `Mouse trace: scope=receive` | 被控端 CrossDesk | 应用回调入口及各检查、提交阶段 |
+| `Mouse RTP callback complete` | 被控端 MiniRTC | 应用回调的总耗时 |
+
+应用接收阶段依次为 `parse`、`authorize`、`desktop_check`、`dispatch`，
+随后是 `normal_desktop_inject` 或 `secure_desktop_inject`。
+`phase=stage_begin` 在调用前记录，`phase=stage_done` 或 `phase=end`
+报告该阶段耗时。若某阶段开始后长时间没有结束，可以确定阻塞区间。
+`outcome=no_controller`、`unauthorized`、`inject_failed` 等说明具体处理结果；
+`submitted` 表示操作系统提交调用成功，不是目标应用已执行的确认。
+
+## 关联与限频
+
+- `tag` 是鼠标消息原始字节的 FNV-1a 64 位摘要，可关联发送和接收；相同消息
+  会有相同摘要，因此重复消息应同时结合 RTP 的 `ssrc` / `seq` 和时间判断。
+- `event` 是各阶段本地计数，不应视为跨端共同序号。会话/通道重建后重新计数。
+- `mono_us` 是进程所在机器的单调时钟，只用于该端的耗时判断。
+  两端日志的墙钟可能不同，不能直接相减当作网络时延。
+- `queue_us`、`send_us`、`stage_us`、`dispatch_us` 和 `total_us` 单位均为微秒。
+  `stage_us` 和 `send_us` 排除本阶段入口日志写入时间；总耗时仍包含诊断开销。
+- 每个采样器记录前 3 次事件，此后最多每 5 秒选取一次事件。
+  失败和耗时达到 100 毫秒的调用使用独立限频，前 3 次记录，此后每 5 秒一次。
+- 发送 API 的返回值不等于网络送达确认，应检查传输层、RTP 发送和远端接收记录。
+
+如果有 UI 事件而没有发送入口，先看 `local_ui`、`dragging`、`suppressed`；
+如果已入队却迟迟没有实际发送，查看 `queue_us`；如果远端已有 RTP 记录，
+但应用处理耗时很长，查看接收阶段。仅当两端相关阶段都及时完成时，
+才进一步检查 Windows 注入后的钩子或目标应用行为。