Change: make -dnet=9 give traces of the details of the network protocol (#11931)

2024-01-31 19:36:41 +01:00
parent bbae16574a
commit 363e251a10
6 changed files with 225 additions and 2 deletions
--- a/src/network/network_server.cpp
+++ b/src/network/network_server.cpp
@@ -215,6 +215,8 @@ ServerNetworkGameSocketHandler::ServerNetworkGameSocketHandler(SOCKET s) : Netwo
 	this->client_id = _network_client_id++;
 	this->receive_limit = _settings_client.network.bytes_per_frame_burst;

+	Debug(net, 9, "client[{}] status = INACTIVE", this->client_id);
+
 	/* The Socket and Info pools need to be the same in size. After all,
 	 * each Socket will be associated with at most one Info object. As
 	 * such if the Socket was allocated the Info object can as well. */
@@ -345,6 +347,8 @@ static void NetworkHandleCommandQueue(NetworkClientSocket *cs);
 */
 NetworkRecvStatus ServerNetworkGameSocketHandler::SendClientInfo(NetworkClientInfo *ci)
 {
+	Debug(net, 9, "client[{}] SendClientInfo(): client_id={}", this->client_id, ci->client_id);
+
 	if (ci->client_id != INVALID_CLIENT_ID) {
 		Packet *p = new Packet(PACKET_SERVER_CLIENT_INFO);
 		p->Send_uint32(ci->client_id);
@@ -359,6 +363,8 @@ NetworkRecvStatus ServerNetworkGameSocketHandler::SendClientInfo(NetworkClientIn
 /** Send the client information about the server. */
 NetworkRecvStatus ServerNetworkGameSocketHandler::SendGameInfo()
 {
+	Debug(net, 9, "client[{}] SendGameInfo()", this->client_id);
+
 	Packet *p = new Packet(PACKET_SERVER_GAME_INFO, TCP_MTU);
 	SerializeNetworkGameInfo(p, GetCurrentNetworkServerGameInfo());

@@ -374,6 +380,8 @@ NetworkRecvStatus ServerNetworkGameSocketHandler::SendGameInfo()
 */
 NetworkRecvStatus ServerNetworkGameSocketHandler::SendError(NetworkErrorCode error, const std::string &reason)
 {
+	Debug(net, 9, "client[{}] SendError(): error={}", this->client_id, error);
+
 	Packet *p = new Packet(PACKET_SERVER_ERROR);

 	p->Send_uint8(error);
@@ -417,6 +425,8 @@ NetworkRecvStatus ServerNetworkGameSocketHandler::SendError(NetworkErrorCode err
 /** Send the check for the NewGRFs. */
 NetworkRecvStatus ServerNetworkGameSocketHandler::SendNewGRFCheck()
 {
+	Debug(net, 9, "client[{}] SendNewGRFCheck()", this->client_id);
+
 	Packet *p = new Packet(PACKET_SERVER_CHECK_NEWGRFS, TCP_MTU);
 	const GRFConfig *c;
 	uint grf_count = 0;
@@ -437,9 +447,12 @@ NetworkRecvStatus ServerNetworkGameSocketHandler::SendNewGRFCheck()
 /** Request the game password. */
 NetworkRecvStatus ServerNetworkGameSocketHandler::SendNeedGamePassword()
 {
+	Debug(net, 9, "client[{}] SendNeedGamePassword()", this->client_id);
+
 	/* Invalid packet when status is STATUS_AUTH_GAME or higher */
 	if (this->status >= STATUS_AUTH_GAME) return this->CloseConnection(NETWORK_RECV_STATUS_MALFORMED_PACKET);

+	Debug(net, 9, "client[{}] status = AUTH_GAME", this->client_id);
 	this->status = STATUS_AUTH_GAME;
 	/* Reset 'lag' counters */
 	this->last_frame = this->last_frame_server = _frame_counter;
@@ -452,9 +465,12 @@ NetworkRecvStatus ServerNetworkGameSocketHandler::SendNeedGamePassword()
 /** Request the company password. */
 NetworkRecvStatus ServerNetworkGameSocketHandler::SendNeedCompanyPassword()
 {
+	Debug(net, 9, "client[{}] SendNeedCompanyPassword()", this->client_id);
+
 	/* Invalid packet when status is STATUS_AUTH_COMPANY or higher */
 	if (this->status >= STATUS_AUTH_COMPANY) return this->CloseConnection(NETWORK_RECV_STATUS_MALFORMED_PACKET);

+	Debug(net, 9, "client[{}] status = AUTH_COMPANY", this->client_id);
 	this->status = STATUS_AUTH_COMPANY;
 	/* Reset 'lag' counters */
 	this->last_frame = this->last_frame_server = _frame_counter;
@@ -469,11 +485,14 @@ NetworkRecvStatus ServerNetworkGameSocketHandler::SendNeedCompanyPassword()
 /** Send the client a welcome message with some basic information. */
 NetworkRecvStatus ServerNetworkGameSocketHandler::SendWelcome()
 {
+	Debug(net, 9, "client[{}] SendWelcome()", this->client_id);
+
 	Packet *p;

 	/* Invalid packet when status is AUTH or higher */
 	if (this->status >= STATUS_AUTHORIZED) return this->CloseConnection(NETWORK_RECV_STATUS_MALFORMED_PACKET);

+	Debug(net, 9, "client[{}] status = AUTHORIZED", this->client_id);
 	this->status = STATUS_AUTHORIZED;
 	/* Reset 'lag' counters */
 	this->last_frame = this->last_frame_server = _frame_counter;
@@ -499,6 +518,8 @@ NetworkRecvStatus ServerNetworkGameSocketHandler::SendWelcome()
 /** Tell the client that its put in a waiting queue. */
 NetworkRecvStatus ServerNetworkGameSocketHandler::SendWait()
 {
+	Debug(net, 9, "client[{}] SendWait()", this->client_id);
+
 	int waiting = 1; // current player getting the map counts as 1
 	Packet *p;

@@ -516,6 +537,8 @@ NetworkRecvStatus ServerNetworkGameSocketHandler::SendWait()

 void ServerNetworkGameSocketHandler::CheckNextClientToSendMap(NetworkClientSocket *ignore_cs)
 {
+	Debug(net, 9, "client[{}] CheckNextClientToSendMap()", this->client_id);
+
 	/* Find the best candidate for joining, i.e. the first joiner. */
 	NetworkClientSocket *best = nullptr;
 	for (NetworkClientSocket *new_cs : NetworkClientSocket::Iterate()) {
@@ -550,6 +573,8 @@ NetworkRecvStatus ServerNetworkGameSocketHandler::SendMap()
 	}

 	if (this->status == STATUS_AUTHORIZED) {
+		Debug(net, 9, "client[{}] SendMap(): first_packet", this->client_id);
+
 		WaitTillSaved();
 		this->savegame = new PacketWriter(this);

@@ -559,6 +584,7 @@ NetworkRecvStatus ServerNetworkGameSocketHandler::SendMap()
 		this->SendPacket(p);

 		NetworkSyncCommandQueue(this);
+		Debug(net, 9, "client[{}] status = MAP", this->client_id);
 		this->status = STATUS_MAP;
 		/* Mark the start of download */
 		this->last_frame = _frame_counter;
@@ -571,12 +597,15 @@ NetworkRecvStatus ServerNetworkGameSocketHandler::SendMap()
 	if (this->status == STATUS_MAP) {
 		bool last_packet = this->savegame->TransferToNetworkQueue(this);
 		if (last_packet) {
+			Debug(net, 9, "client[{}] SendMap(): last_packet", this->client_id);
+
 			/* Done reading, make sure saving is done as well */
 			this->savegame->Destroy();
 			this->savegame = nullptr;

 			/* Set the status to DONE_MAP, no we will wait for the client
 			 *  to send it is ready (maybe that happens like never ;)) */
+			Debug(net, 9, "client[{}] status = DONE_MAP", this->client_id);
 			this->status = STATUS_DONE_MAP;

 			this->CheckNextClientToSendMap();
@@ -591,6 +620,8 @@ NetworkRecvStatus ServerNetworkGameSocketHandler::SendMap()
 */
 NetworkRecvStatus ServerNetworkGameSocketHandler::SendJoin(ClientID client_id)
 {
+	Debug(net, 9, "client[{}] SendJoin(): client_id={}", this->client_id, client_id);
+
 	Packet *p = new Packet(PACKET_SERVER_JOIN);

 	p->Send_uint32(client_id);
@@ -625,6 +656,8 @@ NetworkRecvStatus ServerNetworkGameSocketHandler::SendFrame()
 /** Request the client to sync. */
 NetworkRecvStatus ServerNetworkGameSocketHandler::SendSync()
 {
+	Debug(net, 9, "client[{}] SendSync(), frame_counter={}, sync_seed_1={}", this->client_id, _frame_counter, _sync_seed_1);
+
 	Packet *p = new Packet(PACKET_SERVER_SYNC);
 	p->Send_uint32(_frame_counter);
 	p->Send_uint32(_sync_seed_1);
@@ -642,6 +675,8 @@ NetworkRecvStatus ServerNetworkGameSocketHandler::SendSync()
 */
 NetworkRecvStatus ServerNetworkGameSocketHandler::SendCommand(const CommandPacket *cp)
 {
+	Debug(net, 9, "client[{}] SendCommand(): cmd={}", this->client_id, cp->cmd);
+
 	Packet *p = new Packet(PACKET_SERVER_COMMAND);

 	this->NetworkGameSocketHandler::SendCommand(p, cp);
@@ -662,6 +697,8 @@ NetworkRecvStatus ServerNetworkGameSocketHandler::SendCommand(const CommandPacke
 */
 NetworkRecvStatus ServerNetworkGameSocketHandler::SendChat(NetworkAction action, ClientID client_id, bool self_send, const std::string &msg, int64_t data)
 {
+	Debug(net, 9, "client[{}] SendChat(): action={}, client_id={}, self_send={}", this->client_id, action, client_id, self_send);
+
 	if (this->status < STATUS_PRE_ACTIVE) return NETWORK_RECV_STATUS_OKAY;

 	Packet *p = new Packet(PACKET_SERVER_CHAT);
@@ -685,6 +722,8 @@ NetworkRecvStatus ServerNetworkGameSocketHandler::SendChat(NetworkAction action,
 */
 NetworkRecvStatus ServerNetworkGameSocketHandler::SendExternalChat(const std::string &source, TextColour colour, const std::string &user, const std::string &msg)
 {
+	Debug(net, 9, "client[{}] SendExternalChat(): source={}", this->client_id, source);
+
 	if (this->status < STATUS_PRE_ACTIVE) return NETWORK_RECV_STATUS_OKAY;

 	Packet *p = new Packet(PACKET_SERVER_EXTERNAL_CHAT);
@@ -705,6 +744,8 @@ NetworkRecvStatus ServerNetworkGameSocketHandler::SendExternalChat(const std::st
 */
 NetworkRecvStatus ServerNetworkGameSocketHandler::SendErrorQuit(ClientID client_id, NetworkErrorCode errorno)
 {
+	Debug(net, 9, "client[{}] SendErrorQuit(): client_id={}, errorno={}", this->client_id, client_id, errorno);
+
 	Packet *p = new Packet(PACKET_SERVER_ERROR_QUIT);

 	p->Send_uint32(client_id);
@@ -720,6 +761,8 @@ NetworkRecvStatus ServerNetworkGameSocketHandler::SendErrorQuit(ClientID client_
 */
 NetworkRecvStatus ServerNetworkGameSocketHandler::SendQuit(ClientID client_id)
 {
+	Debug(net, 9, "client[{}] SendQuit(): client_id={}", this->client_id, client_id);
+
 	Packet *p = new Packet(PACKET_SERVER_QUIT);

 	p->Send_uint32(client_id);
@@ -731,6 +774,8 @@ NetworkRecvStatus ServerNetworkGameSocketHandler::SendQuit(ClientID client_id)
 /** Tell the client we're shutting down. */
 NetworkRecvStatus ServerNetworkGameSocketHandler::SendShutdown()
 {
+	Debug(net, 9, "client[{}] SendShutdown()", this->client_id);
+
 	Packet *p = new Packet(PACKET_SERVER_SHUTDOWN);
 	this->SendPacket(p);
 	return NETWORK_RECV_STATUS_OKAY;
@@ -739,6 +784,8 @@ NetworkRecvStatus ServerNetworkGameSocketHandler::SendShutdown()
 /** Tell the client we're starting a new game. */
 NetworkRecvStatus ServerNetworkGameSocketHandler::SendNewGame()
 {
+	Debug(net, 9, "client[{}] SendNewGame()", this->client_id);
+
 	Packet *p = new Packet(PACKET_SERVER_NEWGAME);
 	this->SendPacket(p);
 	return NETWORK_RECV_STATUS_OKAY;
@@ -751,6 +798,8 @@ NetworkRecvStatus ServerNetworkGameSocketHandler::SendNewGame()
 */
 NetworkRecvStatus ServerNetworkGameSocketHandler::SendRConResult(uint16_t colour, const std::string &command)
 {
+	Debug(net, 9, "client[{}] SendRConResult()", this->client_id);
+
 	Packet *p = new Packet(PACKET_SERVER_RCON);

 	p->Send_uint16(colour);
@@ -766,6 +815,8 @@ NetworkRecvStatus ServerNetworkGameSocketHandler::SendRConResult(uint16_t colour
 */
 NetworkRecvStatus ServerNetworkGameSocketHandler::SendMove(ClientID client_id, CompanyID company_id)
 {
+	Debug(net, 9, "client[{}] SendMove(): client_id={}", this->client_id, client_id);
+
 	Packet *p = new Packet(PACKET_SERVER_MOVE);

 	p->Send_uint32(client_id);
@@ -777,6 +828,8 @@ NetworkRecvStatus ServerNetworkGameSocketHandler::SendMove(ClientID client_id, C
 /** Send an update about the company password states. */
 NetworkRecvStatus ServerNetworkGameSocketHandler::SendCompanyUpdate()
 {
+	Debug(net, 9, "client[{}] SendCompanyUpdate()", this->client_id);
+
 	Packet *p = new Packet(PACKET_SERVER_COMPANY_UPDATE);

 	static_assert(sizeof(_network_company_passworded) <= sizeof(uint16_t));
@@ -788,6 +841,8 @@ NetworkRecvStatus ServerNetworkGameSocketHandler::SendCompanyUpdate()
 /** Send an update about the max company/spectator counts. */
 NetworkRecvStatus ServerNetworkGameSocketHandler::SendConfigUpdate()
 {
+	Debug(net, 9, "client[{}] SendConfigUpdate()", this->client_id);
+
 	Packet *p = new Packet(PACKET_SERVER_CONFIG_UPDATE);

 	p->Send_uint8(_settings_client.network.max_companies);
@@ -803,6 +858,8 @@ NetworkRecvStatus ServerNetworkGameSocketHandler::SendConfigUpdate()

 NetworkRecvStatus ServerNetworkGameSocketHandler::Receive_CLIENT_GAME_INFO(Packet *)
 {
+	Debug(net, 9, "client[{}] Receive_CLIENT_GAME_INFO()", this->client_id);
+
 	return this->SendGameInfo();
 }

@@ -813,6 +870,8 @@ NetworkRecvStatus ServerNetworkGameSocketHandler::Receive_CLIENT_NEWGRFS_CHECKED
 		return this->SendError(NETWORK_ERROR_NOT_EXPECTED);
 	}

+	Debug(net, 9, "client[{}] Receive_CLIENT_NEWGRFS_CHECKED()", this->client_id);
+
 	NetworkClientInfo *ci = this->GetInfo();

 	/* We now want a password from the client else we do not allow them in! */
@@ -842,6 +901,8 @@ NetworkRecvStatus ServerNetworkGameSocketHandler::Receive_CLIENT_JOIN(Packet *p)
 	std::string client_revision = p->Recv_string(NETWORK_REVISION_LENGTH);
 	uint32_t newgrf_version = p->Recv_uint32();

+	Debug(net, 9, "client[{}] Receive_CLIENT_JOIN(): client_revision={}, newgrf_version={}", this->client_id, client_revision, newgrf_version);
+
 	/* Check if the client has revision control enabled */
 	if (!IsNetworkCompatibleVersion(client_revision) || _openttd_newgrf_version != newgrf_version) {
 		/* Different revisions!! */
@@ -892,6 +953,7 @@ NetworkRecvStatus ServerNetworkGameSocketHandler::Receive_CLIENT_JOIN(Packet *p)
 	/* Make sure companies to which people try to join are not autocleaned */
 	if (Company::IsValidID(playas)) _network_company_states[playas].months_empty = 0;

+	Debug(net, 9, "client[{}] status = NEWGRFS_CHECK", this->client_id);
 	this->status = STATUS_NEWGRFS_CHECK;

 	if (_grfconfig == nullptr) {
@@ -908,6 +970,8 @@ NetworkRecvStatus ServerNetworkGameSocketHandler::Receive_CLIENT_GAME_PASSWORD(P
 		return this->SendError(NETWORK_ERROR_NOT_EXPECTED);
 	}

+	Debug(net, 9, "client[{}] Receive_CLIENT_GAME_PASSWORD()", this->client_id);
+
 	std::string password = p->Recv_string(NETWORK_PASSWORD_LENGTH);

 	/* Check game password. Allow joining if we cleared the password meanwhile */
@@ -932,6 +996,8 @@ NetworkRecvStatus ServerNetworkGameSocketHandler::Receive_CLIENT_COMPANY_PASSWOR
 		return this->SendError(NETWORK_ERROR_NOT_EXPECTED);
 	}

+	Debug(net, 9, "client[{}] Receive_CLIENT_COMPANY_PASSWORD()", this->client_id);
+
 	std::string password = p->Recv_string(NETWORK_PASSWORD_LENGTH);

 	/* Check company password. Allow joining if we cleared the password meanwhile.
@@ -955,10 +1021,13 @@ NetworkRecvStatus ServerNetworkGameSocketHandler::Receive_CLIENT_GETMAP(Packet *
 		return this->SendError(NETWORK_ERROR_NOT_AUTHORIZED);
 	}

+	Debug(net, 9, "client[{}] Receive_CLIENT_GETMAP()", this->client_id);
+
 	/* Check if someone else is receiving the map */
 	for (NetworkClientSocket *new_cs : NetworkClientSocket::Iterate()) {
 		if (new_cs->status == STATUS_MAP) {
 			/* Tell the new client to wait */
+			Debug(net, 9, "client[{}] status = MAP_WAIT", this->client_id);
 			this->status = STATUS_MAP_WAIT;
 			return this->SendWait();
 		}
@@ -972,6 +1041,8 @@ NetworkRecvStatus ServerNetworkGameSocketHandler::Receive_CLIENT_MAP_OK(Packet *
 {
 	/* Client has the map, now start syncing */
 	if (this->status == STATUS_DONE_MAP && !this->HasClientQuit()) {
+		Debug(net, 9, "client[{}] Receive_CLIENT_MAP_OK()", this->client_id);
+
 		std::string client_name = this->GetClientName();

 		NetworkTextMessage(NETWORK_ACTION_JOIN, CC_DEFAULT, false, client_name, "", this->client_id);
@@ -981,6 +1052,7 @@ NetworkRecvStatus ServerNetworkGameSocketHandler::Receive_CLIENT_MAP_OK(Packet *

 		/* Mark the client as pre-active, and wait for an ACK
 		 *  so we know it is done loading and in sync with us */
+		Debug(net, 9, "client[{}] status = PRE_ACTIVE", this->client_id);
 		this->status = STATUS_PRE_ACTIVE;
 		NetworkHandleCommandQueue(this);
 		this->SendFrame();
@@ -1027,6 +1099,8 @@ NetworkRecvStatus ServerNetworkGameSocketHandler::Receive_CLIENT_COMMAND(Packet
 		return this->SendError(NETWORK_ERROR_TOO_MANY_COMMANDS);
 	}

+	Debug(net, 9, "client[{}] Receive_CLIENT_COMMAND()", this->client_id);
+
 	CommandPacket cp;
 	const char *err = this->ReceiveCommand(p, &cp);

@@ -1086,6 +1160,8 @@ NetworkRecvStatus ServerNetworkGameSocketHandler::Receive_CLIENT_ERROR(Packet *p
 	 *  to us. Display the error and report it to the other clients */
 	NetworkErrorCode errorno = (NetworkErrorCode)p->Recv_uint8();

+	Debug(net, 9, "client[{}] Receive_CLIENT_ERROR(): errorno={}", this->client_id, errorno);
+
 	/* The client was never joined.. thank the client for the packet, but ignore it */
 	if (this->status < STATUS_DONE_MAP || this->HasClientQuit()) {
 		return this->CloseConnection(NETWORK_RECV_STATUS_CLIENT_QUIT);
@@ -1116,6 +1192,8 @@ NetworkRecvStatus ServerNetworkGameSocketHandler::Receive_CLIENT_QUIT(Packet *)
 		return this->CloseConnection(NETWORK_RECV_STATUS_CLIENT_QUIT);
 	}

+	Debug(net, 9, "client[{}] Receive_CLIENT_QUIT()", this->client_id);
+
 	/* The client wants to leave. Display this and report it to the other clients. */
 	std::string client_name = this->GetClientName();
 	NetworkTextMessage(NETWORK_ACTION_LEAVE, CC_DEFAULT, false, client_name, "", STR_NETWORK_MESSAGE_CLIENT_LEAVING);
@@ -1140,12 +1218,15 @@ NetworkRecvStatus ServerNetworkGameSocketHandler::Receive_CLIENT_ACK(Packet *p)

 	uint32_t frame = p->Recv_uint32();

+	Debug(net, 9, "client[{}] Receive_CLIENT_ACK(): frame={}", this->client_id, frame);
+
 	/* The client is trying to catch up with the server */
 	if (this->status == STATUS_PRE_ACTIVE) {
 		/* The client is not yet caught up? */
 		if (frame + Ticks::DAY_TICKS < _frame_counter) return NETWORK_RECV_STATUS_OKAY;

 		/* Now it is! Unpause the game */
+		Debug(net, 9, "client[{}] status = ACTIVE", this->client_id);
 		this->status = STATUS_ACTIVE;
 		this->last_token_frame = _frame_counter;

@@ -1324,6 +1405,8 @@ NetworkRecvStatus ServerNetworkGameSocketHandler::Receive_CLIENT_CHAT(Packet *p)
 	DestType desttype = (DestType)p->Recv_uint8();
 	int dest = p->Recv_uint32();

+	Debug(net, 9, "client[{}] Receive_CLIENT_CHAT(): action={}, desttype={}, dest={}", this->client_id, action, desttype, dest);
+
 	std::string msg = p->Recv_string(NETWORK_CHAT_LENGTH);
 	int64_t data = p->Recv_uint64();

@@ -1348,6 +1431,8 @@ NetworkRecvStatus ServerNetworkGameSocketHandler::Receive_CLIENT_SET_PASSWORD(Pa
 		return this->SendError(NETWORK_ERROR_NOT_EXPECTED);
 	}

+	Debug(net, 9, "client[{}] Receive_CLIENT_SET_PASSWORD()", this->client_id);
+
 	std::string password = p->Recv_string(NETWORK_PASSWORD_LENGTH);
 	const NetworkClientInfo *ci = this->GetInfo();

@@ -1362,6 +1447,8 @@ NetworkRecvStatus ServerNetworkGameSocketHandler::Receive_CLIENT_SET_NAME(Packet
 		return this->SendError(NETWORK_ERROR_NOT_EXPECTED);
 	}

+	Debug(net, 9, "client[{}] Receive_CLIENT_SET_NAME()", this->client_id);
+
 	NetworkClientInfo *ci;

 	std::string client_name = p->Recv_string(NETWORK_CLIENT_NAME_LENGTH);
@@ -1393,6 +1480,8 @@ NetworkRecvStatus ServerNetworkGameSocketHandler::Receive_CLIENT_RCON(Packet *p)

 	if (_settings_client.network.rcon_password.empty()) return NETWORK_RECV_STATUS_OKAY;

+	Debug(net, 9, "client[{}] Receive_CLIENT_RCON()", this->client_id);
+
 	std::string password = p->Recv_string(NETWORK_PASSWORD_LENGTH);
 	std::string command = p->Recv_string(NETWORK_RCONCOMMAND_LENGTH);

@@ -1415,6 +1504,8 @@ NetworkRecvStatus ServerNetworkGameSocketHandler::Receive_CLIENT_MOVE(Packet *p)

 	CompanyID company_id = (Owner)p->Recv_uint8();

+	Debug(net, 9, "client[{}] Receive_CLIENT_MOVE(): company_id={}", this->client_id, company_id);
+
 	/* Check if the company is valid, we don't allow moving to AI companies */
 	if (company_id != COMPANY_SPECTATOR && !Company::IsValidHumanID(company_id)) return NETWORK_RECV_STATUS_OKAY;