fix(opcua,#386): replace std::cerr traces with RCLCPP_DEBUG_STREAM (bburda review)

mfaferek93 · mfaferek93 · commit 8b3ee9d99195 · 2026-04-26T22:22:42.000+02:00
Per bburda review on PR #387: env-var-gated ``std::cerr`` (Copilot fix round) was the wrong observability primitive. It bypasses the gateway's log-level controls (``--log-level opcua.client:=debug``, ``RCUTILS_LOGGING_USE_STDOUT``, /rosout aggregation) and floods raw container stderr instead of integrating with the rest of the plugin's log_info / log_warn plumbing. All 18 trace sites switched to ``RCLCPP_DEBUG_STREAM`` against named loggers - ``opcua.client`` (trampoline, add_event_monitored_item, createEvent result, call_method status), ``opcua.poller`` (on_event, captured EventId hex, state-machine inputs, dispatching action), and ``opcua.plugin`` (acknowledge_fault / confirm_fault EventId hex). Three places kept a manual pre-gate via per-logger ``debug_enabled()`` helpers because the trace builds an ``std::ostringstream`` whose construction RCLCPP_DEBUG_STREAM does NOT short-circuit (the macro constructs a stringstream unconditionally and only the underlying RCUTILS log emission is level-gated). Pre-gating keeps the per-event formatting cost off the hot path at INFO. The ``Level`` enum class is compared via ``static_cast<int>`` because it has no defined ``operator<=``. Removed the ``opcua_trace_enabled()`` env-var helpers and their duplicated definitions across all three .cpp files; the env-var ``ROS2_MEDKIT_OPCUA_TRACE`` is replaced by the standard ROS log-level flow. Operators now toggle traces with: ros2 launch ... --log-level opcua.client:=debug ros2 launch ... --log-level opcua.poller:=debug ros2 launch ... --log-level opcua.plugin:=debug The ``[opcua_poller WARN] ConditionRefresh rejected`` fallback (when PollerConfig.log_warn is not wired) now goes through ``RCLCPP_WARN`` instead of raw stderr, again routing the message through /rosout. CMakeLists.txt: ``test_opcua_client`` gains ``rclcpp`` as a target dependency because ``opcua_client.cpp`` now includes ``rclcpp/logging.hpp``. The unit tests do not call ``rclcpp::init`` so this is link-only. Local verify: 27/27 test_opcua_client + 27/27 test_alarm_state_machine + 32/32 test_node_map.
diff --git a/src/ros2_medkit_plugins/ros2_medkit_opcua/CMakeLists.txt b/src/ros2_medkit_plugins/ros2_medkit_opcua/CMakeLists.txt
@@ -194,8 +194,13 @@ if(BUILD_TESTING)
   target_include_directories(test_opcua_client PRIVATE
     ${CMAKE_CURRENT_SOURCE_DIR}/include
   )
+  # rclcpp needed because opcua_client.cpp uses RCLCPP_DEBUG_STREAM for the
+  # per-event diagnostics (bburda review on PR #387). The unit tests only
+  # call public methods that never touch the trace path under test, so the
+  # dep is link-only - no rclcpp::init / Node spin-up in the suite.
   medkit_target_dependencies(test_opcua_client
     ros2_medkit_gateway
+    rclcpp
   )
   target_link_libraries(test_opcua_client
     open62541pp::open62541pp
diff --git a/src/ros2_medkit_plugins/ros2_medkit_opcua/src/opcua_client.cpp b/src/ros2_medkit_plugins/ros2_medkit_opcua/src/opcua_client.cpp
@@ -16,33 +16,39 @@
 
 #include <algorithm>
 #include <atomic>
-#include <cstdlib>
 #include <cstring>
 #include <deque>
-#include <iostream>
+#include <sstream>
 #include <thread>
 #include <type_traits>
 #include <unordered_map>
 #include <utility>
 
 #include <open62541/client_subscriptions.h>
 #include <open62541/types.h>
+#include <rclcpp/logging.hpp>
 
 namespace ros2_medkit_gateway {
 
-// Env-var gate for verbose per-event / per-method-call diagnostics.
-// Set ``ROS2_MEDKIT_OPCUA_TRACE=1`` to enable trampoline / EventId /
-// call_method stderr logging. Off by default to keep production logs sane
-// (Copilot review on PR #387: per-event std::cerr would flood under high
-// alarm rates and bypass the gateway's normal logging path). Resolved once
-// at process start so toggling requires a restart.
-inline bool opcua_trace_enabled() {
-  static const bool enabled = []() {
-    const char * v = std::getenv("ROS2_MEDKIT_OPCUA_TRACE");
-    return v != nullptr && v[0] != '\0' && std::string(v) != "0";
-  }();
-  return enabled;
+// Per-event / per-method-call traces use a named logger so they integrate
+// with the gateway's normal log level controls (e.g. RCUTILS_LOGGING_USE_STDOUT,
+// ros2 launch --log-level opcua.client:=debug). Off at INFO by default; an
+// operator turns them on without rebuilding (bburda review on PR #387).
+namespace {
+inline rclcpp::Logger opcua_client_logger() {
+  static auto logger = rclcpp::get_logger("opcua.client");
+  return logger;
+}
+
+// Pre-gate for traces whose stream-build cost is non-trivial (e.g. per-arg
+// loops). RCLCPP_DEBUG_STREAM constructs the std::stringstream
+// unconditionally, so for hot paths we check the effective level first.
+// ``Level`` is an enum class - cast to int for the ordered comparison.
+inline bool client_debug_enabled() {
+  return static_cast<int>(opcua_client_logger().get_effective_level()) <=
+         static_cast<int>(rclcpp::Logger::Level::Debug);
 }
+}  // namespace
 
 // Forward declaration - defined after Impl so the trampoline can call back into
 // the client. Static linkage keeps the symbol private to this translation unit.
@@ -614,15 +620,11 @@ UA_EventFilter make_event_filter(const std::vector<OpcuaClient::EventFieldSpec>
 // Defined at namespace scope so its address is a stable function pointer.
 static void on_event_trampoline_c(UA_Client * /*client*/, UA_UInt32 sub_id, void * /*sub_ctx*/, UA_UInt32 mon_id,
                                   void * mon_ctx, size_t n_fields, UA_Variant * fields) {
-  if (opcua_trace_enabled()) {
-    std::cerr << "[opcua_client] TRAMPOLINE FIRED sub=" << sub_id << " mon=" << mon_id << " n_fields=" << n_fields
-              << std::endl;
-  }
+  RCLCPP_DEBUG_STREAM(opcua_client_logger(),
+                      "TRAMPOLINE FIRED sub=" << sub_id << " mon=" << mon_id << " n_fields=" << n_fields);
   auto * ctx = static_cast<EventCallbackContext *>(mon_ctx);
   if (ctx == nullptr || ctx->owner == nullptr) {
-    if (opcua_trace_enabled()) {
-      std::cerr << "[opcua_client] TRAMPOLINE: ctx null" << std::endl;
-    }
+    RCLCPP_DEBUG(opcua_client_logger(), "TRAMPOLINE: ctx null");
     return;
   }
   // Stale callback from a defunct subscription - ctx is still valid (we only
@@ -729,13 +731,13 @@ uint32_t OpcuaClient::add_event_monitored_item(uint32_t subscription_id, const o
   item.requestedParameters.queueSize = 100;
   UA_ExtensionObject_setValueNoDelete(&item.requestedParameters.filter, &filter, &UA_TYPES[UA_TYPES_EVENTFILTER]);
 
-  // Trace-level diagnostic gated by ROS2_MEDKIT_OPCUA_TRACE so integration
-  // test failures can surface the exact NodeId / select-clause count we
-  // hand to the server, without flooding production stderr.
-  if (opcua_trace_enabled()) {
-    std::cerr << "[opcua_client] add_event_monitored_item: subId=" << subscription_id
-              << " nodeId=" << source_node.toString() << " selectClauses=" << (select_specs.size() + 3) << std::endl;
-  }
+  // Debug-level diagnostic so integration-test failures can surface the
+  // exact NodeId / select-clause count we hand to the server. Quiet at
+  // INFO; ``ros2 launch --log-level opcua.client:=debug`` (or env var
+  // RCUTILS_CONSOLE_OUTPUT_FORMAT) re-enables it.
+  RCLCPP_DEBUG_STREAM(opcua_client_logger(),
+                      "add_event_monitored_item: subId=" << subscription_id << " nodeId=" << source_node.toString()
+                                                         << " selectClauses=" << (select_specs.size() + 3));
 
   UA_MonitoredItemCreateResult result =
       UA_Client_MonitoredItems_createEvent(impl_->client.handle(), subscription_id, UA_TIMESTAMPSTORETURN_BOTH, item,
@@ -752,10 +754,8 @@ uint32_t OpcuaClient::add_event_monitored_item(uint32_t subscription_id, const o
   UA_MonitoredItemCreateRequest_clear(&item);
   UA_EventFilter_clear(&filter);
 
-  if (opcua_trace_enabled()) {
-    std::cerr << "[opcua_client] createEvent result: status=" << UA_StatusCode_name(result.statusCode)
-              << " miId=" << result.monitoredItemId << std::endl;
-  }
+  RCLCPP_DEBUG_STREAM(opcua_client_logger(), "createEvent result: status=" << UA_StatusCode_name(result.statusCode)
+                                                                           << " miId=" << result.monitoredItemId);
 
   if (result.statusCode != UA_STATUSCODE_GOOD) {
     UA_MonitoredItemCreateResult_clear(&result);
@@ -864,13 +864,16 @@ OpcuaClient::call_method(const opcua::NodeId & object_id, const opcua::NodeId &
     for (size_t i = 0; i < arg_results.size(); ++i) {
       arg_codes.push_back(arg_results[i].get());
     }
-    if (opcua_trace_enabled()) {
-      std::cerr << "[opcua_client] call_method object=" << object_id.toString() << " method=" << method_id.toString()
-                << " statusCode=" << UA_StatusCode_name(code);
+    if (client_debug_enabled()) {
+      // RCLCPP_DEBUG_STREAM constructs its std::stringstream unconditionally,
+      // so build the per-arg suffix only when DEBUG is actually active.
+      std::ostringstream args_oss;
       for (size_t i = 0; i < arg_codes.size(); ++i) {
-        std::cerr << " arg" << i << "=" << UA_StatusCode_name(arg_codes[i]);
+        args_oss << " arg" << i << "=" << UA_StatusCode_name(arg_codes[i]);
       }
-      std::cerr << std::endl;
+      RCLCPP_DEBUG_STREAM(opcua_client_logger(),
+                          "call_method object=" << object_id.toString() << " method=" << method_id.toString()
+                                                << " statusCode=" << UA_StatusCode_name(code) << args_oss.str());
     }
 
     auto classified = classify_call_result(code, arg_codes);
diff --git a/src/ros2_medkit_plugins/ros2_medkit_opcua/src/opcua_plugin.cpp b/src/ros2_medkit_plugins/ros2_medkit_opcua/src/opcua_plugin.cpp
@@ -27,22 +27,23 @@
 #include <cmath>
 #include <cstdio>
 #include <cstdlib>
-#include <iostream>
+#include <sstream>
 
 namespace ros2_medkit_gateway {
 
 namespace {
 
-// Env-var gate for verbose per-event / per-method-call diagnostics.
-// See opcua_client.cpp for rationale (Copilot review on PR #387). Duplicated
-// to keep traces local to their dispatch sites; promoting to a public header
-// would expose an internal trace knob.
-inline bool opcua_trace_enabled() {
-  static const bool enabled = []() {
-    const char * v = std::getenv("ROS2_MEDKIT_OPCUA_TRACE");
-    return v != nullptr && v[0] != '\0' && std::string(v) != "0";
-  }();
-  return enabled;
+// Named logger so per-operation traces respect ROS log level filtering
+// (bburda review on PR #387). Quiet at INFO; ``--log-level
+// opcua.plugin:=debug`` re-enables for diagnostics.
+inline rclcpp::Logger opcua_plugin_logger() {
+  static auto logger = rclcpp::get_logger("opcua.plugin");
+  return logger;
+}
+
+inline bool plugin_debug_enabled() {
+  return static_cast<int>(opcua_plugin_logger().get_effective_level()) <=
+         static_cast<int>(rclcpp::Logger::Level::Debug);
 }
 
 /// Parse a JSON "value" field, coerce to the node's declared data_type, and
@@ -923,16 +924,17 @@ OpcuaPlugin::execute_operation(const std::string & entity_id, const std::string
     args.push_back(opcua::Variant::fromScalar(runtime->latest_event_id));
     args.push_back(opcua::Variant::fromScalar(opcua::LocalizedText("", comment)));
 
-    if (opcua_trace_enabled()) {
+    if (plugin_debug_enabled()) {
+      std::ostringstream hex_oss;
       const auto * bytes = runtime->latest_event_id.data();
-      std::cerr << "[opcua_plugin] " << operation_name << " EventId len=" << runtime->latest_event_id.length()
-                << " hex=";
       for (size_t i = 0; i < std::min<size_t>(runtime->latest_event_id.length(), 16); ++i) {
         char buf[3];
         std::snprintf(buf, sizeof(buf), "%02x", static_cast<unsigned>(bytes[i]) & 0xffu);
-        std::cerr << buf;
+        hex_oss << buf;
       }
-      std::cerr << " conditionId=" << runtime->condition_id.toString() << std::endl;
+      RCLCPP_DEBUG_STREAM(opcua_plugin_logger(), operation_name << " EventId len=" << runtime->latest_event_id.length()
+                                                                << " hex=" << hex_oss.str()
+                                                                << " conditionId=" << runtime->condition_id.toString());
     }
 
     auto result = client_->call_method(runtime->condition_id, method_id, args);
diff --git a/src/ros2_medkit_plugins/ros2_medkit_opcua/src/opcua_poller.cpp b/src/ros2_medkit_plugins/ros2_medkit_opcua/src/opcua_poller.cpp
@@ -17,26 +17,25 @@
 #include <algorithm>
 #include <cmath>
 #include <cstdio>
-#include <cstdlib>
-#include <iostream>
 #include <optional>
+#include <sstream>
 #include <stdexcept>
 #include <utility>
 
 #include <open62541/types.h>
+#include <rclcpp/logging.hpp>
 
 namespace ros2_medkit_gateway {
 
 namespace {
-// See opcua_client.cpp for the canonical helper. Duplicated here so the
-// poller's per-event traces stay together with the dispatch they describe;
-// promoting to a public header would expose an internal trace knob.
-inline bool opcua_trace_enabled() {
-  static const bool enabled = []() {
-    const char * v = std::getenv("ROS2_MEDKIT_OPCUA_TRACE");
-    return v != nullptr && v[0] != '\0' && std::string(v) != "0";
-  }();
-  return enabled;
+inline rclcpp::Logger opcua_poller_logger() {
+  static auto logger = rclcpp::get_logger("opcua.poller");
+  return logger;
+}
+
+inline bool poller_debug_enabled() {
+  return static_cast<int>(opcua_poller_logger().get_effective_level()) <=
+         static_cast<int>(rclcpp::Logger::Level::Debug);
 }
 }  // namespace
 
@@ -299,7 +298,10 @@ void OpcuaPoller::condition_refresh() {
       if (config_.log_warn) {
         config_.log_warn(msg);
       } else {
-        std::cerr << "[opcua_poller WARN] " << msg << std::endl;
+        // Fallback when the plugin did not wire log_warn through PollerConfig
+        // (e.g., direct unit tests). RCLCPP_WARN goes to /rosout instead of
+        // raw stderr so the warn integrates with normal log filtering.
+        RCLCPP_WARN(opcua_poller_logger(), "%s", msg.c_str());
       }
       condition_refresh_warned_ = true;
     }
@@ -314,10 +316,9 @@ void OpcuaPoller::condition_refresh() {
 void OpcuaPoller::on_event(const AlarmEventConfig & cfg, const std::vector<opcua::Variant> & values,
                            const opcua::NodeId & /*source_node*/, const opcua::NodeId & event_type,
                            const opcua::NodeId & condition_id) {
-  if (opcua_trace_enabled()) {
-    std::cerr << "[opcua_poller] on_event fault=" << cfg.fault_code << " event_type=" << event_type.toString()
-              << " condition=" << condition_id.toString() << " values=" << values.size() << std::endl;
-  }
+  RCLCPP_DEBUG_STREAM(opcua_poller_logger(),
+                      "on_event fault=" << cfg.fault_code << " event_type=" << event_type.toString()
+                                        << " condition=" << condition_id.toString() << " values=" << values.size());
   // Detect ConditionRefresh bracketing per Part 9 §5.5.7. The flag is for
   // diagnostics only; the state machine itself does not need to know
   // because RefreshStart / RefreshEnd notifications carry no condition
@@ -402,28 +403,28 @@ void OpcuaPoller::on_event(const AlarmEventConfig & cfg, const std::vector<opcua
     // Track the latest EventId for spec-compliant Acknowledge calls.
     if (values[kFieldEventId].isType<opcua::ByteString>()) {
       it->second.latest_event_id = values[kFieldEventId].getScalarCopy<opcua::ByteString>();
-      if (opcua_trace_enabled()) {
-        std::cerr << "[opcua_poller] captured EventId len=" << it->second.latest_event_id.length() << " hex=";
+      if (poller_debug_enabled()) {
+        std::ostringstream hex_oss;
         const auto * bytes = it->second.latest_event_id.data();
         for (size_t i = 0; i < std::min<size_t>(it->second.latest_event_id.length(), 16); ++i) {
           char buf[3];
           std::snprintf(buf, sizeof(buf), "%02x", static_cast<unsigned>(bytes[i]) & 0xffu);
-          std::cerr << buf;
+          hex_oss << buf;
         }
-        std::cerr << std::endl;
+        RCLCPP_DEBUG_STREAM(opcua_poller_logger(),
+                            "captured EventId len=" << it->second.latest_event_id.length() << " hex=" << hex_oss.str());
       }
-    } else if (opcua_trace_enabled()) {
-      std::cerr << "[opcua_poller] EventId field not a ByteString" << std::endl;
+    } else {
+      RCLCPP_DEBUG(opcua_poller_logger(), "EventId field not a ByteString");
     }
 
     auto outcome = AlarmStateMachine::compute(prev_status, input);
-    if (opcua_trace_enabled()) {
-      std::cerr << "[opcua_poller] state machine: enabled=" << input.enabled_state << " active=" << input.active_state
-                << " acked=" << input.acked_state << " confirmed=" << input.confirmed_state
-                << " shelved=" << input.shelved << " branch=" << input.branch_id_present
-                << " prev=" << static_cast<int>(prev_status) << " action=" << static_cast<int>(outcome.action)
-                << std::endl;
-    }
+    RCLCPP_DEBUG_STREAM(opcua_poller_logger(),
+                        "state machine: enabled="
+                            << input.enabled_state << " active=" << input.active_state << " acked=" << input.acked_state
+                            << " confirmed=" << input.confirmed_state << " shelved=" << input.shelved
+                            << " branch=" << input.branch_id_present << " prev=" << static_cast<int>(prev_status)
+                            << " action=" << static_cast<int>(outcome.action));
     it->second.last_status = outcome.next_status;
     runtime_snapshot = it->second;
 
@@ -456,10 +457,8 @@ void OpcuaPoller::on_event(const AlarmEventConfig & cfg, const std::vector<opcua
       std::lock_guard cb_lock(event_alarm_callback_mutex_);
       cb_copy = event_alarm_callback_;
     }
-    if (opcua_trace_enabled()) {
-      std::cerr << "[opcua_poller] dispatching action=" << static_cast<int>(delivery.action)
-                << " cb_set=" << (cb_copy ? 1 : 0) << std::endl;
-    }
+    RCLCPP_DEBUG_STREAM(opcua_poller_logger(),
+                        "dispatching action=" << static_cast<int>(delivery.action) << " cb_set=" << (cb_copy ? 1 : 0));
     if (cb_copy) {
       cb_copy(delivery);
     }

Original file line number	Diff line number	Diff line change
`@@ -194,8 +194,13 @@ if(BUILD_TESTING)`
`194`	`194`	`target_include_directories(test_opcua_client PRIVATE`
`195`	`195`	`${CMAKE_CURRENT_SOURCE_DIR}/include`
`196`	`196`	`)`
	`197`	`+ # rclcpp needed because opcua_client.cpp uses RCLCPP_DEBUG_STREAM for the`
	`198`	`+ # per-event diagnostics (bburda review on PR #387). The unit tests only`
	`199`	`+ # call public methods that never touch the trace path under test, so the`
	`200`	`+ # dep is link-only - no rclcpp::init / Node spin-up in the suite.`
`197`	`201`	`medkit_target_dependencies(test_opcua_client`
`198`	`202`	`ros2_medkit_gateway`
	`203`	`+ rclcpp`
`199`	`204`	`)`
`200`	`205`	`target_link_libraries(test_opcua_client`
`201`	`206`	`open62541pp::open62541pp`