UPnP leases issue (#3298)

* Inverted logic for refreshing upnp port mapping

* Refresh logic for UPnP lease to consider more than one protocol

* mapping_protocol pretty print function to_string()

Preparatory change for better logging in portmapping

* Remove extraneous and needless call to check_mapping_loop

There is no need for the call to check_mapping_loop because there is
an outer check that will work every time as long as it tickets fast enough.

* Remove extraneous and needless logging

* Pretty print function for port_mapping and upnp_state classes

* Check for missing mappings, renewals or gateway changes every health check period

We currently check every health check period for renewals but every
5 minutes for devices. It is too complicated to have 2 different setting
and there is no need. It is harder to code, document and to understand
and there is not much benefit from it.

So, use health check period for all checks. Nice and simple.

* Improve logging regarding remaining upnp lease

The logging before didn't make it clear if it was remaining lease or
total lease time.

* Always print all upnp logs if unpn logging is enabled

Some upnp logs are throttle controlled so that users are not swamped by
upnp messages, if upnp is not working.

However, when upnp logging is explicitly enabled then it makes no sense
to throttle them.

Co-authored-by: Dimitrios Siganos <[email protected]>

nano/node/portmapping.cpp

@@ -7,6 +7,14 @@
 #include <boost/format.hpp>
 #include <boost/range/adaptor/filtered.hpp>
 
+std::string nano::mapping_protocol::to_string ()
+{
+	std::stringstream ss;
+	ss << name << " " << external_address << ":" << external_port;
+	ss << (enabled ? " (enabled)" : " (disabled)");
+	return ss.str ();
+};
+
 nano::port_mapping::port_mapping (nano::node & node_a) :
 	node (node_a),
 	protocols ({ { { "TCP", boost::asio::ip::address_v4::any (), 0, true }, { "UDP", boost::asio::ip::address_v4::any (), 0, !node_a.flags.disable_udp } } })
@@ -26,6 +34,20 @@ std::string nano::port_mapping::get_config_port (std::string const & node_port_a
 	return node.config.external_port != 0 ? std::to_string (node.config.external_port) : node_port_a;
 }
 
+std::string nano::port_mapping::to_string ()
+{
+	std::stringstream ss;
+
+	ss << "port_mapping is " << (on ? "on" : "off") << std::endl;
+	for (auto & protocol : protocols)
+	{
+		ss << protocol.to_string () << std::endl;
+	}
+	ss << upnp.to_string ();
+
+	return ss.str ();
+};
+
 void nano::port_mapping::refresh_devices ()
 {
 	if (!network_params.network.is_dev_network ())
@@ -36,7 +58,7 @@ void nano::port_mapping::refresh_devices ()
 		std::array<char, 64> local_address_l;
 		local_address_l.fill (0);
 		auto igd_error_l (UPNP_GetValidIGD (upnp_l.devices, &upnp_l.urls, &upnp_l.data, local_address_l.data (), sizeof (local_address_l)));
-		if (check_count % 15 == 0)
+		if (check_count % 15 == 0 || node.config.logging.upnp_details_logging ())
 		{
 			node.logger.always_log (boost::str (boost::format ("UPnP local address: %1%, discovery: %2%, IGD search: %3%") % local_address_l.data () % discover_error_l % igd_error_l));
 			if (node.config.logging.upnp_details_logging ())
@@ -86,34 +108,28 @@ void nano::port_mapping::refresh_mapping ()
 		{
 			auto upnp_description = std::string ("Nano Node (") + network_params.network.get_current_network_as_string () + ")";
 			auto add_port_mapping_error_l (UPNP_AddPortMapping (upnp.urls.controlURL, upnp.data.first.servicetype, config_port_l.c_str (), node_port_l.c_str (), address.to_string ().c_str (), upnp_description.c_str (), protocol.name, nullptr, std::to_string (network_params.portmapping.lease_duration.count ()).c_str ()));
-			if (node.config.logging.upnp_details_logging ())
-			{
-				node.logger.always_log (boost::str (boost::format ("UPnP %1% port mapping response: %2%") % protocol.name % add_port_mapping_error_l));
-			}
+
 			if (add_port_mapping_error_l == UPNPCOMMAND_SUCCESS)
 			{
 				protocol.external_port = static_cast<uint16_t> (std::atoi (config_port_l.data ()));
-				node.logger.always_log (boost::str (boost::format ("UPnP %1%:%2% mapped to %3%") % protocol.external_address % config_port_l % node_port_l));
-
-				// Refresh mapping before the leasing ends
-				node.workers.add_timed_task (std::chrono::steady_clock::now () + network_params.portmapping.lease_duration - std::chrono::seconds (10), [node_l = node.shared ()] () {
-					node_l->port_mapping.refresh_mapping ();
-				});
+				auto fmt = boost::format ("UPnP %1% %2%:%3% mapped to %4%") % protocol.name % protocol.external_address % config_port_l % node_port_l;
+				node.logger.always_log (boost::str (fmt));
 			}
 			else
 			{
 				protocol.external_port = 0;
-				node.logger.always_log (boost::str (boost::format ("UPnP failed %1%: %2%") % add_port_mapping_error_l % strupnperror (add_port_mapping_error_l)));
+				auto fmt = boost::format ("UPnP %1% %2%:%3% FAILED") % protocol.name % add_port_mapping_error_l % strupnperror (add_port_mapping_error_l);
+				node.logger.always_log (boost::str (fmt));
 			}
 		}
 	}
 }
 
-bool nano::port_mapping::check_mapping ()
+bool nano::port_mapping::check_lost_or_old_mapping ()
 {
 	// Long discovery time and fast setup/teardown make this impractical for testing
 	debug_assert (!network_params.network.is_dev_network ());
-	bool result_l (true);
+	bool result_l (false);
 	nano::lock_guard<nano::mutex> guard_l (mutex);
 	auto node_port_l (std::to_string (node.network.endpoint ().port ()));
 	auto config_port_l (get_config_port (node_port_l));
@@ -124,13 +140,19 @@ bool nano::port_mapping::check_mapping ()
 		std::array<char, 16> remaining_mapping_duration_l;
 		remaining_mapping_duration_l.fill (0);
 		auto verify_port_mapping_error_l (UPNP_GetSpecificPortMappingEntry (upnp.urls.controlURL, upnp.data.first.servicetype, config_port_l.c_str (), protocol.name, nullptr, int_client_l.data (), int_port_l.data (), nullptr, nullptr, remaining_mapping_duration_l.data ()));
-		if (verify_port_mapping_error_l == UPNPCOMMAND_SUCCESS || atoi (remaining_mapping_duration_l.data ()) <= (network_params.portmapping.lease_duration.count () / 2))
+		auto remaining_from_port_mapping = std::atoi (remaining_mapping_duration_l.data ());
+		auto lease_duration = network_params.portmapping.lease_duration.count ();
+		auto lease_duration_divided_by_two = (lease_duration / 2);
+		auto recent_lease = (remaining_from_port_mapping >= lease_duration_divided_by_two);
+		if (verify_port_mapping_error_l != UPNPCOMMAND_SUCCESS)
 		{
-			result_l = false;
+			result_l = true;
+			node.logger.always_log (boost::str (boost::format ("UPNP_GetSpecificPortMappingEntry failed %1%: %2%") % verify_port_mapping_error_l % strupnperror (verify_port_mapping_error_l)));
 		}
-		else
+		if (!recent_lease)
 		{
-			node.logger.always_log (boost::str (boost::format ("UPNP_GetSpecificPortMappingEntry failed %1%: %2%") % verify_port_mapping_error_l % strupnperror (verify_port_mapping_error_l)));
+			result_l = true;
+			node.logger.always_log (boost::str (boost::format ("UPnP leasing time getting old, remaining time: %1%, lease time: %2%, below the threshold: %3%") % remaining_from_port_mapping % lease_duration % lease_duration_divided_by_two));
 		}
 		std::array<char, 64> external_address_l;
 		external_address_l.fill (0);
@@ -148,39 +170,44 @@ bool nano::port_mapping::check_mapping ()
 		}
 		if (node.config.logging.upnp_details_logging ())
 		{
-			node.logger.always_log (boost::str (boost::format ("UPnP %1% mapping verification response: %2%, external ip response: %3%, external ip: %4%, internal ip: %5%, lease: %6%") % protocol.name % verify_port_mapping_error_l % external_ip_error_l % external_address_l.data () % address.to_string () % remaining_mapping_duration_l.data ()));
+			node.logger.always_log (boost::str (boost::format ("UPnP %1% mapping verification response: %2%, external ip response: %3%, external ip: %4%, internal ip: %5%, remaining lease: %6%") % protocol.name % verify_port_mapping_error_l % external_ip_error_l % external_address_l.data () % address.to_string () % remaining_mapping_duration_l.data ()));
 		}
 	}
 	return result_l;
 }
 
 void nano::port_mapping::check_mapping_loop ()
 {
+	auto health_check_period = network_params.portmapping.health_check_period;
+
 	refresh_devices ();
+
 	if (upnp.devices != nullptr)
 	{
 		// If the mapping is lost, refresh it
-		if (check_mapping ())
+		if (check_lost_or_old_mapping ())
 		{
 			// Schedules a mapping refresh just before the leasing ends
 			refresh_mapping ();
 		}
-		// Check for mapping health frequently
-		node.workers.add_timed_task (std::chrono::steady_clock::now () + network_params.portmapping.health_check_period, [node_l = node.shared ()] () {
-			node_l->port_mapping.check_mapping_loop ();
-		});
+		else
+		{
+			node.logger.always_log (boost::str (boost::format ("UPnP No need to refresh the mapping")));
+		}
 	}
 	else
 	{
-		if (check_count < 10)
+		if (check_count < 10 || node.config.logging.upnp_details_logging ())
 		{
 			node.logger.always_log (boost::str (boost::format ("UPnP No IGD devices found")));
 		}
-		// Check for new devices later
-		node.workers.add_timed_task (std::chrono::steady_clock::now () + std::chrono::minutes (5), [node_l = node.shared ()] () {
-			node_l->port_mapping.check_mapping_loop ();
-		});
 	}
+
+	// Check for new devices or after health_check_period
+	node.workers.add_timed_task (std::chrono::steady_clock::now () + health_check_period, [node_l = node.shared ()] () {
+		node_l->port_mapping.check_mapping_loop ();
+	});
+
 	++check_count;
 }
 
@@ -206,6 +233,23 @@ void nano::port_mapping::stop ()
 	}
 }
 
+std::string nano::upnp_state::to_string ()
+{
+	std::stringstream ss;
+	ss << "Discovered UPnP devices:" << std::endl;
+	for (UPNPDev * p = devices; p; p = p->pNext)
+	{
+		debug_assert (p->descURL);
+		debug_assert (p->st);
+		debug_assert (p->usn);
+		ss << "  " << p->descURL << std::endl;
+		ss << "  " << p->st << std::endl;
+		ss << "  " << p->usn << std::endl;
+	}
+	ss << "  scope_id: " << std::endl;
+	return ss.str ();
+}
+
 nano::upnp_state::~upnp_state ()
 {
 	if (devices)

nano/node/portmapping.hpp

@@ -17,6 +17,7 @@ class mapping_protocol
 	boost::asio::ip::address_v4 external_address;
 	uint16_t external_port;
 	bool enabled;
+	std::string to_string ();
 };
 
 /** Collection of discovered UPnP devices and state*/
@@ -26,6 +27,7 @@ class upnp_state
 	upnp_state () = default;
 	~upnp_state ();
 	upnp_state & operator= (upnp_state &&);
+	std::string to_string ();
 
 	/** List of discovered UPnP devices */
 	UPNPDev * devices{ nullptr };
@@ -44,14 +46,15 @@ class port_mapping
 	void stop ();
 	void refresh_devices ();
 	nano::endpoint external_address ();
+	std::string to_string ();
 
 private:
 	/** Add port mappings for the node port (not RPC). Refresh when the lease ends. */
 	void refresh_mapping ();
 	/** Check occasionally to refresh in case router loses mapping */
 	void check_mapping_loop ();
 	/** Returns false if mapping still exists */
-	bool check_mapping ();
+	bool check_lost_or_old_mapping ();
 	std::string get_config_port (std::string const &);
 	upnp_state upnp;
 	nano::node & node;