Merge lp:~widelands-dev/widelands/bug-net-error-game-connect into lp:widelands

[Notabilis]

Fixes on the communication between widelands and the metaserver:
- Permit answering PING requests even while logging in
- Printing current time to console when logging in.
  Eases finding the corresponding log entry on the metaserver when debugging
- Re-enabling and fixing unused code for whisper message to nonexisting player
- Handling error message when trying to join a non-existing game
- Avoid hanging client even after being notified about the non-existing game
- Removed no longer needed error messages

A bunch of smaller fixes regarding the metaserver. Nothing that should change anything in the "normal" case, but offers better / more correct handling of some errors.

[bunnybot (widelandsofficial)]

Continuous integration builds have changed state:

Travis build 4157. State: passed. Details: https://travis-ci.org/widelands/widelands/builds/444116111.
Appveyor build 3954. State: success. Details: https://ci.appveyor.com/project/widelands-dev/widelands/build/_widelands_dev_widelands_bug_net_error_game_connect-3954.

[GunChleoc (gunchleoc)]

Code LGTM, not tested.

This should to into Build20, because it affects server load.

review: Approve

[Klaus Halfmann (klaus-halfmann)]

Complied this and did a "poor mans coverage" in the debugger.
I was able to hit about 50% of the changed code.

Hitting the rest would need tweaking of the metaserver or such.
But this is all reasonable for me.

@bunnybot mergre

review: Approve (review, compile, debug, test)

[GunChleoc (gunchleoc)]

Thanks for testing!

Let Notabilis take care of the merging, because there is also a Metaserver change.

[Notabilis (notabilis27)]

Thanks for the reviews!
This branch can be merged immediately, the changes to the metaserver are no requirement.

@bunnybot merge

=== modified file 'src/network/internet_gaming.cc'
--- src/network/internet_gaming.cc	2018-08-24 07:58:04 +0000
+++ src/network/internet_gaming.cc	2018-10-20 15:50:44 +0000
@@ -353,6 +353,14 @@
 			}
 		}
 		return;
+	} else if (cmd == IGPCMD_PING) {
+		// Client received a PING and should immediately PONG as requested
+		SendPacket s;
+		s.string(IGPCMD_PONG);
+		net->send(s);
+
+		lastping_ = time(nullptr);
+		return;
 	}
 
 	// Are we already online?
@@ -389,7 +397,10 @@
 			format_and_add_chat("", "", true, _("For reporting bugs, visit:"));
 			format_and_add_chat("", "", true, "https://wl.widelands.org/wiki/ReportingBugs/");
 			state_ = LOBBY;
-			log("InternetGaming: Client %s logged in.\n", clientname_.c_str());
+			// Append UTC time to login message to ease linking between client output and
+			// metaserver logs. The string returned by asctime is terminated by \n
+			const time_t now = time(nullptr);
+			log("InternetGaming: Client %s logged in at UTC %s", clientname_.c_str(), asctime(gmtime(&now)));
 			return;
 
 		} else if (cmd == IGPCMD_ERROR) {
@@ -408,8 +419,7 @@
 			logout();
 			set_error();
 			log("InternetGaming: Expected a LOGIN, PWD_CHALLENGE or ERROR packet from server, but "
-			    "received "
-			    "command %s. Maybe the metaserver is using a different protocol version?",
+			    "received command %s. Maybe the metaserver is using a different protocol version?\n",
 			    cmd.c_str());
 			throw WLWarning(
 			   _("Unexpected packet"),
@@ -443,15 +453,6 @@
 			format_and_add_chat("", "", true, temp);
 		}
 
-		else if (cmd == IGPCMD_PING) {
-			// Client received a PING and should immediately PONG as requested
-			SendPacket s;
-			s.string(IGPCMD_PONG);
-			net->send(s);
-
-			lastping_ = time(nullptr);
-		}
-
 		else if (cmd == IGPCMD_CHAT) {
 			// Client received a chat message
 			std::string sender = packet.string();
@@ -617,11 +618,11 @@
 			if (subcmd == IGPCMD_CHAT) {
 				// Something went wrong with the chat message the user sent.
 				message += _("Chat message could not be sent.");
-				if (reason == "NO_SUCH_USER")
+				if (reason == "NO_SUCH_USER") {
 					message = (boost::format("%s %s") % message %
-					           (boost::format(InternetGamingMessages::get_message(reason)) %
-					            packet.string().c_str()))
+					           InternetGamingMessages::get_message(reason))
 					             .str();
+				}
 			}
 
 			else if (subcmd == IGPCMD_GAME_OPEN) {
@@ -630,17 +631,30 @@
 				// we got our answer, so no need to wait anymore
 				waitcmd_ = "";
 			}
-			message = (boost::format(_("ERROR: %s")) % message).str();
+
+			else if (subcmd == IGPCMD_GAME_CONNECT && reason == "NO_SUCH_GAME") {
+				log("InternetGaming: The game no longer exists, maybe it has just been closed\n");
+				message = InternetGamingMessages::get_message(reason);
+				assert(waitcmd_ == IGPCMD_GAME_CONNECT);
+				waitcmd_ = "";
+			}
+			if (!message.empty()) {
+				message = (boost::format(_("ERROR: %s")) % message).str();
+			} else {
+				message = (boost::format(_("An unexpected error message has been received about command %1%: %2%"))
+							% subcmd % reason).str();
+			}
 
 			// Finally send the error message as system chat to the client.
 			format_and_add_chat("", "", true, message);
 		}
 
-		else
+		else {
 			// Inform the client about the unknown command
 			format_and_add_chat(
 			   "", "", true,
 			   (boost::format(_("Received an unknown command from the metaserver: %s")) % cmd).str());
+		}
 
 	} catch (WLWarning& e) {
 		format_and_add_chat("", "", true, e.what());
@@ -653,6 +667,28 @@
 	return gameips_;
 }
 
+bool InternetGaming::wait_for_ips() {
+	// Wait until the metaserver provided us with an IP address
+	uint32_t const secs = time(nullptr);
+	const bool is_waiting_for_connect = (waitcmd_ == IGPCMD_GAME_CONNECT);
+	while (!gameips_.first.is_valid()) {
+		if (error()) {
+			return false;
+		}
+		if (is_waiting_for_connect && waitcmd_.empty()) {
+			// Was trying to join a game but failed.
+            // It probably means that the game is no longer available
+            return false;
+		}
+		handle_metaserver_communication();
+		// give some time for the answer + for a relogin, if a problem occurs.
+		if ((kInternetGamingTimeout * 5 / 3) < time(nullptr) - secs) {
+			return false;
+		}
+	}
+	return true;
+}
+
 const std::string InternetGaming::relay_password() {
 	return relay_password_;
 }

=== modified file 'src/network/internet_gaming.h'
--- src/network/internet_gaming.h	2018-04-21 14:48:54 +0000
+++ src/network/internet_gaming.h	2018-10-20 15:50:44 +0000
@@ -107,6 +107,13 @@
 	const std::pair<NetAddress, NetAddress>& ips();
 
 	/**
+	 * Blocks for some time until either the ips() method is able to return the IPs of the relay
+	 * or an error occurred or the timeout is met.
+	 * @return \c True iff ips() can return something.
+	 */
+	bool wait_for_ips();
+
+	/**
 	 * Returns the password required to connect to the relay server as host.
 	 */
 	const std::string relay_password();

=== modified file 'src/network/internet_gaming_messages.cc'
--- src/network/internet_gaming_messages.cc	2018-04-07 16:59:00 +0000
+++ src/network/internet_gaming_messages.cc	2018-10-20 15:50:44 +0000
@@ -40,7 +40,8 @@
 void InternetGamingMessages::fill_map() {
 	// Messages from the metaserver (https://github.com/widelands/widelands_metaserver) to the
 	// clients.
-	igmessages["NO_SUCH_USER"] = _("There is no user with the name %s logged in!");
+	igmessages["NO_SUCH_USER"] = _("There is no user with this name logged in.");
+	igmessages["NO_SUCH_GAME"] = _("The game no longer exists, maybe it has just been closed.");
 	igmessages["WRONG_PASSWORD"] = _("The sent password was incorrect!");
 	igmessages["UNSUPPORTED_PROTOCOL"] = _("The protocol version you are using is not supported!");
 	igmessages["ALREADY_LOGGED_IN"] = _("You are already logged in!");
@@ -53,12 +54,4 @@
 	igmessages["NO_ANSWER"] = _("Metaserver did not answer");
 	igmessages["CLIENT_TIMEOUT"] =
 	   _("You got disconnected from the metaserver, as you did not answer a PING request in time.");
-	igmessages["GAME_TIMEOUT"] =
-	   _("The metaserver was unable to connect to your game. Most likely it can’t be connected to "
-	     "from the "
-	     "internet! Please take a look at http://wl.widelands.org/wiki/InternetGaming to learn how "
-	     "to set up "
-	     "your internet connection for hosting a game online.");
-	igmessages["NOT_LOGGED_IN"] = _(
-	   "You tried to log back in, but the server has no knowledge of your previous state anymore.");
 }

=== modified file 'src/ui_fsmenu/internet_lobby.cc'
--- src/ui_fsmenu/internet_lobby.cc	2018-05-07 05:35:32 +0000
+++ src/ui_fsmenu/internet_lobby.cc	2018-10-20 15:50:44 +0000
@@ -362,23 +362,19 @@
 }
 
 bool FullscreenMenuInternetLobby::wait_for_ip() {
-	// Wait until the metaserver provided us with an IP address
-	uint32_t const secs = time(nullptr);
-	while (!InternetGaming::ref().ips().first.is_valid()) {
-		InternetGaming::ref().handle_metaserver_communication();
-		// give some time for the answer + for a relogin, if a problem occurs.
-		if ((kInternetGamingTimeout * 5 / 3) < time(nullptr) - secs) {
+	if (!InternetGaming::ref().wait_for_ips()) {
+		// Only display a message box if a network error occurred
+		if (InternetGaming::ref().error()) {
 			// Show a popup warning message
 			const std::string warning(
 			   _("Widelands was unable to get the IP address of the server in time. "
-			     "There seems to be a network problem, either on your side or on the side "
-			     "of the server.\n"));
+				 "There seems to be a network problem, either on your side or on the side "
+				 "of the server.\n"));
 			UI::WLMessageBox mmb(this, _("Connection Timed Out"), warning,
-			                     UI::WLMessageBox::MBoxType::kOk, UI::Align::kLeft);
+								 UI::WLMessageBox::MBoxType::kOk, UI::Align::kLeft);
 			mmb.run<UI::Panel::Returncodes>();
-			InternetGaming::ref().set_error();
-			return false;
 		}
+		return false;
 	}
 	return true;
 }
@@ -422,8 +418,9 @@
 		// Tell the metaserver about it
 		InternetGaming::ref().open_game();
 
-		// Wait for his response with the IPs of the relay server
+		// Wait for the response with the IPs of the relay server
 		if (!wait_for_ip()) {
+			InternetGaming::ref().set_error();
 			return;
 		}