JsonRpcConnection#Send*(): discard messages ASAP once shutting down #9991

Al2Klimov · 2024-02-07T13:05:01Z

Especially ApiListener#ReplayLog() enqueued lots of messages into
JsonRpcConnection#{m_IoStrand,m_OutgoingMessagesQueue} (RAM) even if
the connection was shut(ting) down. Now #Disconnect() takes effect ASAP.

fixes #9985

julianbrost · 2024-02-07T15:57:58Z

Now #Disconnect() takes effect ASAP.

Which - with the current state of the PR - means that the messages are discarded instead of enqueued.

Especially ApiListener#ReplayLog() enqueued lots of messages into JsonRpcConnection#{m_IoStrand,m_OutgoingMessagesQueue} (RAM) even if the connection was shut(ting) down.

However, ApiListener#ReplayLog() will still generate messages for a dead connection that will be discarded anyways as it has no way to tell that the connection is dead. How much effort would it take to improve this?

lib/remote/apilistener.cpp

yhabteab

[2024-02-09 15:26:01 +0100] warning/JsonRpcConnection: Error while sending JSON-RPC message for identity 'master2'
Error: Broken pipe [system:32 at /opt/homebrew/include/boost/asio/detail/reactive_socket_send_op.hpp:137:37 in function 'do_complete']

Stacktrace:
 0# __cxa_throw in /Users/yhabteab/Workspace/icinga2/prefix/lib/icinga2/sbin/icinga2
 1# void boost::throw_exception<boost::system::system_error>(boost::system::system_error const&, boost::source_location const&) in /Users/yhabteab/Workspace/icinga2/prefix/lib/icinga2/sbin/icinga2
 2# boost::asio::detail::do_throw_error(boost::system::error_code const&, boost::source_location const&) in /Users/yhabteab/Workspace/icinga2/prefix/lib/icinga2/sbin/icinga2
---

[2024-02-09 15:26:01 +0100] information/ApiListener: Endpoint 'master2' disconnected while replaying log.
[2024-02-09 15:26:01 +0100] warning/JsonRpcConnection: API client disconnected for identity 'master2'
[2024-02-09 15:26:19 +0100] warning/ApiListener: Removing API client for endpoint 'master2'. 0 API clients left.
[2024-02-09 15:26:19 +0100] information/ApiListener: Replayed 6694 messages.

yhabteab · 2024-02-09T17:00:46Z

[2024-02-09 17:55:57 +0100] information/ApiListener: Sending config updates for endpoint 'master2' in zone 'master'.
[2024-02-09 17:55:57 +0100] information/JsonRpcConnection: Received certificate request for CN 'master2' signed by our CA.
[2024-02-09 17:55:57 +0100] information/ApiListener: Syncing configuration files for global zone 'global-templates' to endpoint 'master2'.
[2024-02-09 17:55:57 +0100] information/JsonRpcConnection: The certificates for CN 'master2' and its root CA are valid and uptodate. Skipping automated renewal.
[2024-02-09 17:55:57 +0100] information/ApiListener: Finished sending config file updates for endpoint 'master2' in zone 'master'.
[2024-02-09 17:55:57 +0100] information/ApiListener: Syncing runtime objects to endpoint 'master2'.
[2024-02-09 17:55:57 +0100] warning/JsonRpcConnection: API client disconnected for identity 'master2'
[2024-02-09 17:55:57 +0100] information/ApiListener: Endpoint 'master2' disconnected while syncing runtime objects.
[2024-02-09 17:55:57 +0100] warning/ApiListener: Removing API client for endpoint 'master2'. 0 API clients left.
[2024-02-09 17:55:57 +0100] information/ApiListener: Finished sending runtime config updates for endpoint 'master2' in zone 'master'.

lib/remote/apilistener.cpp

by checking the now atomic #m_ShuttingDown outside of it.

Especially ApiListener#ReplayLog() enqueued lots of messages into JsonRpcConnection#{m_IoStrand,m_OutgoingMessagesQueue} (RAM) even if the connection was shut(ting) down. Now #Disconnect() takes effect ASAP.

lib/remote/apilistener-configsync.cpp

lib/remote/apilistener.cpp

julianbrost · 2024-02-21T12:59:58Z

lib/remote/jsonrpcconnection.cpp

+	if (m_ShuttingDown) {
+		BOOST_THROW_EXCEPTION(std::runtime_error("Cannot send message to already disconnected endpoint '" + GetIdentity() + "'!"));
+	}
+
 	Ptr keepAlive (this);

 	m_IoStrand.post([this, keepAlive, message]() { SendMessageInternal(message); });
 }

 void JsonRpcConnection::SendRawMessage(const String& message)
 {
+	if (m_ShuttingDown) {
+		BOOST_THROW_EXCEPTION(std::runtime_error("Cannot send message to already disconnected endpoint '" + GetIdentity() + "'!"));
+	}


JSON-RPC connections don't necessarily have an identity set (anonymous connections, like for initial certificate requests).

JSON-RPC connections do always have an identity (a connection is considered to be anonymous if there can't be found a local endpoint matching a given identity).

…cted clients

julianbrost · 2024-02-22T13:42:51Z

@yhabteab When should those new log messages you added appear? At least I didn't see them when simply restarting individual nodes in the cluster. Judging just from the message, they should probably have severity warning, I'm wondering though when/how often they might appear (so if this is something that can regularly appear during a restart, the severity probably shouldn't be too high).

yhabteab · 2024-02-22T14:00:26Z

@yhabteab When should those new log messages you added appear?

The first one is triggered by the timer handler, which gets scheduled every 5 seconds and is trying to send the SetLogPosition message. The second one actually applies to every communication attempt initiated with ApiListener::Relay* or directly with ApiListener::SyncSendMessage(), which can be quite a lot but also quite hard to trigger them manually.

julianbrost · 2024-02-22T14:12:40Z

So it's possible that those messages appear during a normal reload depending on the timing, but it's rather unlikely?

yhabteab · 2024-02-22T14:27:49Z

So it's possible that those messages appear during a normal reload depending on the timing, but it's rather unlikely?

Yes, depending on the number of disconnected endpoints and on how busy m_RelayQueue was, it could result into a bunch of warnings.

yhabteab · 2024-02-22T14:46:12Z

So it's possible that those messages appear during a normal reload depending on the timing, but it's rather unlikely?

Yes, depending on the number of disconnected endpoints and on how busy m_RelayQueue was, it could result into a bunch of warnings.

Actually, the endpoint is dropped off the list as soon as it is disconnected, so there will be no attempts via the ApiListener::Relay*() methods after that.

julianbrost · 2024-02-22T16:23:48Z

The implementation should be fine. Main remaining question for me is the log level of the new messages, like should they be downgraded to notice (if that's something that can just legitimately happen during a disconnect) or maybe promoted to warning (if that's actually something problematic).

@Al2Klimov: please also review the current state of this PR.

Al2Klimov

So I opt for getting the anti-memory-leak ready w/o changing too much for now. It shouldn't depend on the exceptions part.

Al2Klimov · 2024-03-04T11:49:19Z

lib/remote/jsonrpcconnection.cpp

@@ -163,23 +163,39 @@ ConnectionRole JsonRpcConnection::GetRole() const

 void JsonRpcConnection::SendMessage(const Dictionary::Ptr& message)
 {
+	if (m_ShuttingDown) {
+		BOOST_THROW_EXCEPTION(std::runtime_error("Cannot send message to already disconnected API client '" + GetIdentity() + "'!"));


I'm not a big friend of this tbh. All callers catch exceptions – ex. SyncSendMessage() which I didn't finish checking, yet. But so far I see that SyncSendMessage() is called by RelayMessageOne() which is called by SyncRelayMessage(). The latter misses PersistMessage() if RelayMessageOne() throws. Not good.

But so far I see that SyncSendMessage() is called by RelayMessageOne() which is called by SyncRelayMessage(). The latter misses PersistMessage() if RelayMessageOne() throws.

This is never going happen! Nothing has changed in the previous synchronisation behaviour. The only thing that has changed is that we have added an error handling here.

icinga2/lib/remote/apilistener.cpp

Lines 1203 to 1208 in 3bb5baa

try {

client->SendMessage(message);

} catch (const std::runtime_error& ex) {

Log(LogInformation, "ApiListener")

<< "Error while sending message to endpoint '" << endpoint->GetName() << "': " << DiagnosticInformation(ex, false);

}

Al2Klimov requested a review from yhabteab February 7, 2024 13:05

cla-bot bot added the cla/signed label Feb 7, 2024

icinga-probot bot added area/distributed Distributed monitoring (master, satellites, clients) bug Something isn't working ref/IP labels Feb 7, 2024

yhabteab reviewed Feb 8, 2024

View reviewed changes