Cut log noise: duplicate UDP warnings, global-destination RTS, non-section clients

include/udp_connections.hpp

@@ -10,7 +10,9 @@
 #pragma once
 
 #include <boost/asio.hpp>
+#include <chrono>
 #include <span>
+#include <string>
 #include "settings.hpp"
 
 using boost::asio::ip::udp;
@@ -92,7 +94,16 @@ class UdpConnections
       */
 	std::uint8_t calculate_crc(std::span<std::uint8_t> data);
 
+	/**
+	  * @brief Log a packet that does not start with PACKET_START, once even if both sockets receive it
+	  * @param sender The endpoint the packet came from
+	  * @param data The bytes from the unexpected start onwards
+	  */
+	void log_unknown_start(const udp::endpoint &sender, std::span<const std::uint8_t> data);
+
 	PacketCallback packetCallback = nullptr;
+	std::string lastUnknownStartSignature; ///< Sender and leading bytes of the last logged unknown start
+	std::chrono::steady_clock::time_point lastUnknownStartTime;
 	std::shared_ptr<Settings> settings;
 	udp::socket udpConnection;
 	udp::socket udpConnectionAddressDetection;

src/app.cpp

@@ -27,6 +27,8 @@
 #include "logging_utils.hpp"
 
 #include <algorithm>
+#include <array>
+#include <atomic>
 #include <iomanip>
 #include <iostream>
 #include <span>
@@ -44,6 +46,42 @@ static std::string format_hex_address(std::uint8_t address)
 	return value.str();
 }
 
+// Requests to Send with a global destination are invalid and ignored by the stack. Its per-message warning
+// has no source address, so count them per source here (CAN thread) and report once per minute from update().
+static std::array<std::atomic<std::uint32_t>, 256> globalRtsCountBySource{};
+
+static void count_global_rts(const isobus::CANMessageFrame &frame)
+{
+	constexpr std::uint8_t TP_CONNECTION_MANAGEMENT_PF = 0xEC;
+	constexpr std::uint8_t TP_REQUEST_TO_SEND = 16;
+	if (frame.isExtendedFrame && (frame.dataLength > 0) &&
+	    (((frame.identifier >> 16) & 0xFF) == TP_CONNECTION_MANAGEMENT_PF) &&
+	    (((frame.identifier >> 8) & 0xFF) == 0xFF) &&
+	    (frame.data[0] == TP_REQUEST_TO_SEND))
+	{
+		globalRtsCountBySource[frame.identifier & 0xFF]++;
+	}
+}
+
+static void report_global_rts_counts()
+{
+	std::ostringstream sources;
+	std::uint32_t total = 0;
+	for (std::size_t source = 0; source < globalRtsCountBySource.size(); source++)
+	{
+		const std::uint32_t count = globalRtsCountBySource[source].exchange(0);
+		if (count > 0)
+		{
+			sources << (total > 0 ? ", " : "") << format_hex_address(static_cast<std::uint8_t>(source)) << " (" << count << ")";
+			total += count;
+		}
+	}
+	if (total > 0)
+	{
+		log("TP") << "Ignored " << total << " Request to Send message(s) with a global destination in the last minute, from source address(es) " << sources.str() << std::endl;
+	}
+}
+
 // Enumerate and log all Control Functions on the bus
 static void enumerate_bus_control_functions(const std::string &context)
 {
@@ -194,6 +232,7 @@ bool Application::setup_can_hardware()
 	}
 	isobus::CANHardwareInterface::set_number_of_can_channels(1);
 	isobus::CANHardwareInterface::assign_can_channel_frame_handler(0, canDriver);
+	isobus::CANHardwareInterface::get_can_frame_received_event_dispatcher().add_listener(count_global_rts);
 
 	canHardwareStarted = isobus::CANHardwareInterface::start();
 	if ((!canHardwareStarted) || (!canDriver->get_is_valid()))
@@ -627,6 +666,13 @@ bool Application::update()
 		lastConflictCheck = isobus::SystemTiming::get_timestamp_ms();
 	}
 
+	static std::uint32_t lastGlobalRtsReportMs = 0;
+	if (isobus::SystemTiming::time_expired_ms(lastGlobalRtsReportMs, 60000))
+	{
+		report_global_rts_counts();
+		lastGlobalRtsReportMs = isobus::SystemTiming::get_timestamp_ms();
+	}
+
 	// Diff active implement clients once per second so disconnect messages retain prior metadata.
 	static std::uint32_t lastImplementScanMs = 0;
 	if (isobus::SystemTiming::time_expired_ms(lastImplementScanMs, 1000))

src/logging.cpp

@@ -78,6 +78,18 @@ class CustomLogger : public isobus::CANStackLogger
 
 	void sink_CAN_stack_log(CANStackLogger::LoggingLevel level, const std::string &text) override
 	{
+		// Some bus devices send these continuously. The stack's text has no source address; the application
+		// reports them per source once per minute instead (see report_global_rts_counts in app.cpp).
+		if ((LoggingLevel::Warning == level) &&
+		    (text == "[TP]: Received a Request to Send (RTS) message with a global destination, ignoring"))
+		{
+			level = LoggingLevel::Debug;
+			if (get_log_level() > LoggingLevel::Debug)
+			{
+				return;
+			}
+		}
+
 		std::ostream &out = async_log::stream();
 		out << "[" << get_timestamp() << "] ";
 		switch (level)

src/task_controller.cpp

@@ -597,6 +597,11 @@ bool MyTCServer::activate_object_pool(std::shared_ptr<isobus::ControlFunction> p
 				log() << "  Section " << static_cast<int>(i) << " -> element " << sectionElementNumbers[i] << std::endl;
 			}
 		}
+		else if (0 == numberOfSections)
+		{
+			// e.g. a tractor ECU describing hitch or GNSS geometry: nothing to control, nothing wrong
+			log("TC Server") << "Non-section client: the DDOP has no section elements, section control not applicable." << std::endl;
+		}
 		else
 		{
 			log("TC Server") << "WARNING: No supported section control method detected! "

src/udp_connections.cpp

@@ -8,8 +8,11 @@
  */
 
 #include "udp_connections.hpp"
+#include <algorithm>
 #include <cassert>
+#include <iomanip>
 #include <iostream>
+#include <sstream>
 #include "logging_utils.hpp"
 
 #if !defined(_WIN32)
@@ -153,6 +156,34 @@ std::uint8_t UdpConnections::calculate_crc(std::span<std::uint8_t> data)
 	return static_cast<std::uint8_t>(result & 0xFF);
 }
 
+void UdpConnections::log_unknown_start(const udp::endpoint &sender, std::span<const std::uint8_t> data)
+{
+	// Both sockets listen on port 8888 (one on the AOG subnet address, one on all interfaces), so a
+	// broadcast packet usually arrives on both. Only log it once.
+	static constexpr std::size_t MAX_LOGGED_BYTES = 16;
+	static constexpr auto DUPLICATE_WINDOW = std::chrono::milliseconds(50);
+
+	std::ostringstream signature;
+	signature << sender.address().to_string() << ":" << sender.port() << " " << std::hex << std::setfill('0');
+	for (std::size_t i = 0; i < std::min(data.size(), MAX_LOGGED_BYTES); i++)
+	{
+		signature << (i ? " " : "") << std::setw(2) << static_cast<int>(data[i]);
+	}
+	if (data.size() > MAX_LOGGED_BYTES)
+	{
+		signature << " ...";
+	}
+
+	const auto now = std::chrono::steady_clock::now();
+	if ((signature.str() == lastUnknownStartSignature) && (now - lastUnknownStartTime < DUPLICATE_WINDOW))
+	{
+		return;
+	}
+	lastUnknownStartSignature = signature.str();
+	lastUnknownStartTime = now;
+	log() << "Unknown start of message from " << lastUnknownStartSignature << " (" << std::dec << data.size() << " bytes)" << std::endl;
+}
+
 void UdpConnections::handle_incoming_packets()
 {
 	static std::array<std::uint8_t, 512> rxBuffer;
@@ -200,7 +231,7 @@ void UdpConnections::handle_incoming_packets()
 			else
 			{
 				// Unknown start of message, reset buffer
-				log() << "Unknown start of message: 0x" << std::hex << start << std::dec << std::endl;
+				log_unknown_start(sender_endpoint, { rxBuffer.data() + index - 2, rxIndex - (index - 2) });
 				rxIndex = 0;
 			}
 
@@ -288,7 +319,7 @@ void UdpConnections::handle_address_detection()
 			else
 			{
 				// Unknown start of message, reset buffer
-				log() << "Unknown start of message: 0x" << std::hex << start << std::dec << std::endl;
+				log_unknown_start(sender_endpoint, { rxBuffer.data() + index - 2, rxIndex - (index - 2) });
 				rxIndex = 0;
 			}