Add debug output to find bug in PerfdataWriterConnection

Author: jschmidt-icinga

Containerfile

@@ -128,7 +128,7 @@ RUN --mount=type=bind,source=.,target=/icinga2,readonly \
         -DICINGA2_WITH_LIVESTATUS=OFF && \
     make -j$([ "$MAKE_JOBS" = auto ] && nproc || echo "$MAKE_JOBS") && \
     if [ "${ICINGA2_BUILD_TESTING}" = ON ]; then \
-        ctest -j$([ "$MAKE_JOBS" = auto ] && nproc || echo "$MAKE_JOBS") --output-on-failure; \
+        ctest -j$([ "$MAKE_JOBS" = auto ] && nproc || echo "$MAKE_JOBS") --verbose; \
     fi && \
     make install DESTDIR=/icinga2-install
 

lib/base/tcpsocket.hpp

@@ -83,6 +83,7 @@ void Connect(Socket& socket, const String& node, const String& service, boost::a
 
 			break;
 		} catch (const std::exception& ex) {
+			Log(LogDebug, "Connect") << "Execption: " << ex.what();
 			auto se (dynamic_cast<const boost::system::system_error*>(&ex));
 
 			if ((se && se->code() == boost::asio::error::operation_aborted) || ++current == result.end()) {

lib/perfdata/perfdatawriterconnection.cpp

@@ -69,6 +69,7 @@ void PerfdataWriterConnection::Disconnect()
 	std::promise<void> promise;
 
 	IoEngine::SpawnCoroutine(m_Strand, [&](boost::asio::yield_context yc) {
+		Log(LogDebug, m_LogFacility) << "PerfdataWriterConnection::Disconnect::1";
 		try {
 			/* Cancel any outstanding operations of the other coroutine.
 			 * Since we're on the same strand we're hopefully guaranteed that all cancellations
@@ -85,9 +86,12 @@ void PerfdataWriterConnection::Disconnect()
 			);
 			m_ReconnectTimer.cancel();
 
+			Log(LogDebug, m_LogFacility) << "PerfdataWriterConnection::Disconnect::3";
 			Disconnect(std::move(yc));
+			Log(LogDebug, m_LogFacility) << "PerfdataWriterConnection::Disconnect::4";
 			promise.set_value();
 		} catch (const std::exception& ex) {
+			Log(LogDebug, m_LogFacility) << "PerfdataWriterConnection::Disconnect::5";
 			promise.set_exception(std::current_exception());
 		}
 	});
@@ -130,12 +134,16 @@ void PerfdataWriterConnection::EnsureConnected(const boost::asio::yield_context&
 
 	std::visit(
 		[&](auto& stream) {
+			Log(LogDebug, m_LogFacility) << "PerfdataWriterConnection::EnsureConnected::1";
 			::Connect(stream->lowest_layer(), m_Host, m_Port, yc);
+			Log(LogDebug, m_LogFacility) << "PerfdataWriterConnection::EnsureConnected::2";
 
 			if constexpr (std::is_same_v<std::decay_t<decltype(stream)>, Shared<AsioTlsStream>::Ptr>) {
+				Log(LogDebug, m_LogFacility) << "PerfdataWriterConnection::EnsureConnected::3";
 				using type = boost::asio::ssl::stream_base::handshake_type;
 
 				stream->next_layer().async_handshake(type::client, yc);
+				Log(LogDebug, m_LogFacility) << "PerfdataWriterConnection::EnsureConnected::4";
 
 				if (m_VerifyPeerCertificate) {
 					if (!stream->next_layer().IsVerifyOK()) {

lib/perfdata/perfdatawriterconnection.hpp

@@ -61,20 +61,28 @@ class PerfdataWriterConnection final : public Object
 	template<typename Buffer>
 	auto Send(Buffer&& buf)
 	{
+		Log(LogDebug, m_LogFacility) << "PerfdataWriterConnection::Send::1";
 		if (m_Stopped) {
+			Log(LogDebug, m_LogFacility) << "PerfdataWriterConnection::Send::1.1";
 			BOOST_THROW_EXCEPTION(Stopped{});
 		}
+		Log(LogDebug, m_LogFacility) << "PerfdataWriterConnection::Send::2";
 
 		using RetType = decltype(WriteMessage(std::declval<Buffer>(), std::declval<boost::asio::yield_context>()));
 		std::promise<RetType> promise;
 
 		IoEngine::SpawnCoroutine(m_Strand, [&](boost::asio::yield_context yc) {
+			Log(LogDebug, m_LogFacility) << "PerfdataWriterConnection::Send::3";
+
 			while (true) {
 				try {
+					Log(LogDebug, m_LogFacility) << "PerfdataWriterConnection::Send::5";
 					EnsureConnected(yc);
+					Log(LogDebug, m_LogFacility) << "PerfdataWriterConnection::Send::6";
 
 					if constexpr (std::is_void_v<RetType>) {
 						WriteMessage(std::forward<Buffer>(buf), yc);
+						Log(LogDebug, m_LogFacility) << "PerfdataWriterConnection::Send::7";
 						promise.set_value();
 					} else {
 						promise.set_value(WriteMessage(std::forward<Buffer>(buf), yc));
@@ -83,7 +91,9 @@ class PerfdataWriterConnection final : public Object
 					m_RetryTimeout = InitialRetryWait;
 					return;
 				} catch (const std::exception& ex) {
+					Log(LogDebug, m_LogFacility) << "PerfdataWriterConnection::Send::8";
 					if (m_Stopped) {
+						Log(LogDebug, m_LogFacility) << "PerfdataWriterConnection::Send::8.1";
 						promise.set_exception(std::make_exception_ptr(Stopped{}));
 						return;
 					}
@@ -96,8 +106,11 @@ class PerfdataWriterConnection final : public Object
 					m_Connected = false;
 
 					try {
+						Log(LogDebug, m_LogFacility) << "PerfdataWriterConnection::Send::9";
 						BackoffWait(yc);
+						Log(LogDebug, m_LogFacility) << "PerfdataWriterConnection::Send::10";
 					} catch (const std::exception&) {
+						Log(LogDebug, m_LogFacility) << "PerfdataWriterConnection::Send::11";
 						promise.set_exception(std::make_exception_ptr(Stopped{}));
 						return;
 					}

test/perfdata-perfdatawriterconnection.cpp

@@ -130,19 +130,29 @@ BOOST_AUTO_TEST_CASE(finish_during_timeout)
  */
 BOOST_AUTO_TEST_CASE(stuck_in_handshake)
 {
+	Logger::SetConsoleLogSeverity(LogDebug);
+	Logger::EnableConsoleLog();
+	Log(LogDebug, "stuck_in_handshake") << "1";
 	std::promise<void> p;
 	TestThread timeoutThread{[&]() {
+		Log(LogDebug, "stuck_in_handshake") << "2";
 		Accept();
+		Log(LogDebug, "stuck_in_handshake") << "3";
 		auto f = p.get_future();
 		GetConnection().CancelAfterTimeout(f, 50ms);
+		Log(LogDebug, "stuck_in_handshake") << "4";
 		BOOST_REQUIRE(f.wait_for(0ms) == std::future_status::timeout);
+		Log(LogDebug, "stuck_in_handshake") << "5";
 	}};
 
+	Log(LogDebug, "stuck_in_handshake") << "6";
 	BOOST_REQUIRE_THROW(
 		GetConnection().Send(boost::asio::const_buffer{"foobar", 7}), PerfdataWriterConnection::Stopped
 	);
+	Log(LogDebug, "stuck_in_handshake") << "7";
 
 	REQUIRE_JOINS_WITHIN(timeoutThread, 1s);
+	Log(LogDebug, "stuck_in_handshake") << "8";
 }
 
 /* When the disconnect timeout runs out while sending something to a slow or blocking server, we