Possible race condition with Boost.ASIO cancel() in timeout handling

[julianbrost]

We had a customer report an issue where the master would cease to attempt to connect to some agents randomly.

14:24:55 critical/ApiListener: Timeout while reconnecting to endpoint 'agent-123' via host 'agent-123.example.com' and port '5665', cancelling attempt
14:24:55 information/ApiListener: New client connection for identity 'agent-123.example' to [10.20.30.40]:5665

However, there we no following log messages for that agent with an "Operation canceled" error as it should happen in case of a timeout, suggesting some problem with the timeout mechanism.

My current theory is that cancel() doesn't really do what we'd need it to do here:

icinga2/lib/remote/apilistener.cpp

Lines 588 to 598 in 894d6aa

	Timeout::Ptr timeout(new Timeout(strand->context(), *strand, boost::posix_time::microseconds(int64_t(GetConnectTimeout() * 1e6)),
	[sslConn, endpoint, host, port](asio::yield_context yc) {
	Log(LogCritical, "ApiListener")
	<< "Timeout while reconnecting to endpoint '" << endpoint->GetName() << "' via host '" << host
	<< "' and port '" << port << "', cancelling attempt";
	boost::system::error_code ec;
	sslConn->lowest_layer().cancel(ec);
	}
	));
	Defer cancelTimeout([&timeout]() { timeout->Cancel(); });

Note that the documentation for cancel() says (emphasis by me):

This function causes all outstanding asynchronous connect, send and receive operations to finish immediately, and the handlers for cancelled operations will be passed the boost::asio::error::operation_aborted error.

What happens if there's progress happening on the connection right when the timeout fires? Might there be no outstanding operation that could be cancelled, rendering the timeout ineffective?

Customer seems to be happy since increasing the related timeout and reported no more issues, so that seems to confirm the issue being related to the timeout.

Possible fix: call shutdown() on the TCP layer instead.

ref/IP/44784
ref/IP/58522
ref/IP/63825

[jschmidt-icinga]

This can be reproduced quite easily, just by reducing the timeout in AddConnection to something like 10ms. I actually had much more difficulty reproducing where the timeout actually did cancel the handshake, resulting in an operation_canceled error, which happened in a few instances.

To me it doesn't seem to be as much of a race condition but more boost asio weirdness. From printing the microsecond timestamps before and after the handshake and inside the timeout callback, it looks like the timeout callback will always only be run after async_handshake, even if it expired long before going into async_handshake, probably as long as there is immediate progress when the handshake is started.

Here I've set the timeout to 10000 microseconds which expires well inside async_handshake and fires right before the timestamp after it:

[2025-06-12 09:05:20 +0000] critical/ApiListener: started timeout: 300752
[2025-06-12 09:05:20 +0000] critical/ApiListener: before handshake: 303325
[2025-06-12 09:05:20 +0000] critical/ApiListener: Timeout while reconnecting to endpoint 'satellite-1' via host 'satellite-1' and port '5665', cancelling attempt
[2025-06-12 09:05:20 +0000] critical/ApiListener: timeout time: 316977
[2025-06-12 09:05:20 +0000] critical/ApiListener: after handshake: 317007
[2025-06-12 09:05:20 +0000] information/ApiListener: New client connection for identity 'satellite-1' to [172.18.0.8]:5665

What I can't reproduce is some weird in-between state where the connection fails but no more attempts are being made. And I can't see from the code how that could even happen, at least not like the situation from your log snippet, where the timeout fires before the "New client connection" message.

Edit: It seems the timeout will also fire in the middle of async_handshake, but rarely get to actually cancel it.

[jschmidt-icinga]

I've looked into using shutdown instead of cancel here and it doesn't work when the handshake is not yet done. It just throws an error (or returns an error_code) and the handshake continues normally.

The error string is shutdown while in init, but the error code is some ssl error value (167772567 on my system) passed on by boost and I can't find where it is defined.

A shutdown on the TCP connection or closing the socket works as intended however. Or we can use AsioTlsConnection::GracefulDisconnect().

However, since this timeout can currently still fire when the JsonRpcConnection or HttpServerConnection is already constructed/started, it would then call the shutdown or close operations on a connection that has been handed over to a different strand/thread.

My suggestion would be to hand the strand over to the connection object, since it's not used anymore anyway and then the timeout can still fire as long as NewClientHandler is still running. The alternative would be cancelling the timer, which lives in a different scope from where we'd need to cancel it.

I'd also look at handshakeTimeout in NewClientHandlerInternal, since that probably has the same issue.

[julianbrost]

There was another report of this. Additional piece of information this time: it happened with a connection to a Windows agent (v2.15.2) that logged the following for that connection atttempt:

critical/ApiListener: Client TLS handshake failed (from ...): The I/O operation has been aborted because of either a thread exit or an application request

[julianbrost]

I think I was finally able to reproduce the issue, see #10833 for the details.

Summary: If the following writes fail with something like "connection reset by peer" (i.e. a TCP reset) roughly when the timeout fires ...

icinga2/lib/remote/apilistener.cpp

Lines 814 to 823 in 75361cb

	JsonRpc::SendMessage(client, new Dictionary({
	{ "jsonrpc", "2.0" },
	{ "method", "icinga::Hello" },
	{ "params", new Dictionary({
	{ "version", (double)l_AppVersionInt },
	{ "capabilities", (double)ApiCapabilities::MyCapabilities }
	}) }
	}), yc);
	client->async_flush(yc);

The following async_shutdown() inside an automatically executing Defer block may block indefinetly:

icinga2/lib/remote/apilistener.cpp

Lines 751 to 759 in 75361cb

	Defer shutdownSslConn ([&sslConn, &yc]() {
	// Ignore the error, but do not throw an exception being swallowed at all cost.
	// https://github.com/Icinga/icinga2/issues/7351
	boost::system::error_code ec;
	// Using async_shutdown() instead of AsioTlsStream::GracefulDisconnect() as this whole function
	// is already guarded by a timeout based on the connect timeout.
	sslConn.async_shutdown(yc[ec]);
	});