commit 31accc834d768a8a6431a20fa1895f4f01f24442
Author: Simon Howard <fraggle@soulsphere.org>
AuthorDate: Sun Jan 27 23:36:50 2019 -0500
Commit: Simon Howard <fraggle@soulsphere.org>
CommitDate: Sun Jan 27 23:36:50 2019 -0500
net: Add logging of server events.
---
src/net_server.c | 158 +++++++++++++++++++++++++++++++++++++++----------------
1 file changed, 114 insertions(+), 44 deletions(-)
diff --git a/src/net_server.c b/src/net_server.c
index 238e247a..695e3b98 100644
--- a/src/net_server.c
+++ b/src/net_server.c
@@ -483,7 +483,7 @@ static void NET_SV_AdvanceWindow(void)
// Advance the recv window until it catches up with lowtic
while (recvwindow_start < lowtic)
- {
+ {
boolean should_advance;
// Check we have tics from all players for first tic in
@@ -520,8 +520,7 @@ static void NET_SV_AdvanceWindow(void)
sizeof(*recvwindow) * (BACKUPTICS - 1));
memset(&recvwindow[BACKUPTICS-1], 0, sizeof(*recvwindow));
++recvwindow_start;
-
- //printf("SV: advanced to %i\n", recvwindow_start);
+ NET_Log("server: advanced receive window to %d", recvwindow_start);
}
}
@@ -550,6 +549,8 @@ static void NET_SV_SendReject(net_addr_t *addr, const char *msg)
{
net_packet_t *packet;
+ NET_Log("server: sending reject to %s", NET_AddrToString(addr));
+
packet = NET_NewPacket(10);
NET_WriteInt16(packet, NET_PACKET_TYPE_REJECTED);
NET_WriteString(packet, msg);
@@ -576,6 +577,8 @@ static void NET_SV_InitNewClient(net_client_t *client, net_addr_t *addr,
client->last_gamedata_time = 0;
memset(client->sendqueue, 0xff, sizeof(client->sendqueue));
+
+ NET_Log("server: initialized new client from %s", NET_AddrToString(addr));
}
// parse a SYN from a client(initiating a connection)
@@ -592,9 +595,12 @@ static void NET_SV_ParseSYN(net_packet_t *packet, net_client_t *client,
int num_players;
int i;
+ NET_Log("server: processing SYN packet");
+
// Read the magic number and check it is the expected one.
if (!NET_ReadInt32(packet, &magic))
{
+ NET_Log("server: error: no magic number for SYN");
return;
}
@@ -604,12 +610,14 @@ static void NET_SV_ParseSYN(net_packet_t *packet, net_client_t *client,
break;
case NET_OLD_MAGIC_NUMBER:
+ NET_Log("server: error: client using old magic number: %d", magic);
NET_SV_SendReject(addr,
"You are using an old client version that is not supported by "
"this server. This server is running " PACKAGE_STRING ".");
return;
default:
+ NET_Log("server: error: wrong magic number: %d", magic);
return;
}
@@ -619,6 +627,7 @@ static void NET_SV_ParseSYN(net_packet_t *packet, net_client_t *client,
client_version = NET_ReadString(packet);
if (client_version == NULL)
{
+ NET_Log("server: error: no version from client");
return;
}
@@ -635,15 +644,24 @@ static void NET_SV_ParseSYN(net_packet_t *packet, net_client_t *client,
"client is: %s. No common compatible protocol could be "
"negotiated.", client_version);
NET_SV_SendReject(addr, reject_msg);
+ NET_Log("server: error: no common protocol");
return;
}
// Read connect data, and check that the game mode/mission are valid
// and the max_players value is in a sensible range.
- if (!NET_ReadConnectData(packet, &data)
- || !D_ValidGameMode(data.gamemission, data.gamemode)
+ if (!NET_ReadConnectData(packet, &data))
+ {
+ NET_Log("server: error: failed to read connect data");
+ return;
+ }
+
+ if (!D_ValidGameMode(data.gamemission, data.gamemode)
|| data.max_players > NET_MAXPLAYERS)
{
+ NET_Log("server: error: invalid connect data, max_players=%d, "
+ "gamemission=%d, gamemode=%d",
+ data.max_players, data.gamemission, data.gamemode);
return;
}
@@ -651,6 +669,7 @@ static void NET_SV_ParseSYN(net_packet_t *packet, net_client_t *client,
player_name = NET_ReadString(packet);
if (player_name == NULL)
{
+ NET_Log("server: error: failed to read player name");
return;
}
@@ -659,6 +678,8 @@ static void NET_SV_ParseSYN(net_packet_t *packet, net_client_t *client,
// Not accepting new connections?
if (server_state != SERVER_WAITING_LAUNCH)
{
+ NET_Log("server: error: not in waiting launch state, server_state=%d",
+ server_state);
NET_SV_SendReject(addr,
"Server is not currently accepting connections");
return;
@@ -671,6 +692,8 @@ static void NET_SV_ParseSYN(net_packet_t *packet, net_client_t *client,
if ((!data.drone && num_players >= NET_SV_MaxPlayers())
|| NET_SV_NumClients() >= MAXNETNODES)
{
+ NET_Log("server: no more players, num_players=%d, max=%d",
+ num_players, NET_SV_MaxPlayers());
NET_SV_SendReject(addr, "Server is full!");
return;
}
@@ -684,6 +707,8 @@ static void NET_SV_ParseSYN(net_packet_t *packet, net_client_t *client,
{
sv_gamemode = data.gamemode;
sv_gamemission = data.gamemission;
+ NET_Log("server: new game, mode=%d, mission=%d",
+ sv_gamemode, sv_gamemission);
}
// Check the connecting client is playing the same game as all
@@ -691,6 +716,8 @@ static void NET_SV_ParseSYN(net_packet_t *packet, net_client_t *client,
if (data.gamemode != sv_gamemode || data.gamemission != sv_gamemission)
{
char msg[128];
+ NET_Log("server: wrong mode/mission, %d != %d || %d != %d",
+ data.gamemode, sv_gamemode, data.gamemission, sv_gamemission);
M_snprintf(msg, sizeof(msg),
"Game mismatch: server is %s (%s), client is %s (%s)",
D_GameMissionString(sv_gamemission),
@@ -735,6 +762,7 @@ static void NET_SV_ParseSYN(net_packet_t *packet, net_client_t *client,
// Client already connected?
if (client->active)
{
+ NET_Log("server: client is already initialized (duplicate SYN?)");
return;
}
@@ -767,10 +795,14 @@ static void NET_SV_ParseLaunch(net_packet_t *packet, net_client_t *client)
int num_players;
unsigned int i;
+ NET_Log("server: processing launch packet");
+
// Only the controller can launch the game.
if (client != NET_SV_Controller())
{
+ NET_Log("server: error: this client isn't the controller, %d != %d",
+ client, NET_SV_Controller());
return;
}
@@ -778,11 +810,13 @@ static void NET_SV_ParseLaunch(net_packet_t *packet, net_client_t *client)
if (server_state != SERVER_WAITING_LAUNCH)
{
+ NET_Log("server: error: not in waiting launch state, state=%d",
+ server_state);
return;
}
// Forward launch on to all clients.
-
+ NET_Log("server: sending launch to all clients");
NET_SV_AssignPlayers();
num_players = NET_SV_NumPlayers();
@@ -863,7 +897,7 @@ static void StartGame(void)
}
// Change server state
-
+ NET_Log("server: beginning game state");
server_state = SERVER_IN_GAME;
memset(recvwindow, 0, sizeof(recvwindow));
@@ -891,10 +925,14 @@ static boolean AllNodesReady(void)
static void CheckStartGame(void)
{
- if (AllNodesReady())
+ if (!AllNodesReady())
{
- StartGame();
+ NET_Log("server: not all clients ready to start yet");
+ return;
}
+
+ NET_Log("server: all clients ready, starting game");
+ StartGame();
}
// Send waiting data with current status to all nodes that are ready to
@@ -919,10 +957,14 @@ static void NET_SV_ParseGameStart(net_packet_t *packet, net_client_t *client)
{
net_gamesettings_t settings;
+ NET_Log("server: processing game start packet");
+
// Can only start a game if we are in the waiting start state.
if (server_state != SERVER_WAITING_START)
{
+ NET_Log("server: error: not in waiting start state, server_state=%d",
+ server_state);
return;
}
@@ -931,7 +973,7 @@ static void NET_SV_ParseGameStart(net_packet_t *packet, net_client_t *client)
if (!NET_ReadSettings(packet, &settings))
{
// Malformed packet
-
+ NET_Log("server: error: no settings from controller");
return;
}
@@ -939,6 +981,7 @@ static void NET_SV_ParseGameStart(net_packet_t *packet, net_client_t *client)
if (!NET_ValidGameSettings(sv_gamemode, sv_gamemission, &settings))
{
+ NET_Log("server: error: invalid game settings");
return;
}
@@ -966,7 +1009,8 @@ static void NET_SV_SendResendRequest(net_client_t *client, int start, int end)
unsigned int nowtime;
int index;
- //printf("SV: send resend for %i-%i\n", start, end);
+ NET_Log("server: send resend to %s for tics %d-%d",
+ NET_AddrToString(client->addr), start, end);
packet = NET_NewPacket(20);
@@ -1030,33 +1074,36 @@ static void NET_SV_CheckResends(net_client_t *client)
if (need_resend)
{
// Start a new run of resend tics?
-
if (resend_start < 0)
{
resend_start = i;
}
-
resend_end = i;
}
- else
+ else if (resend_start >= 0)
{
- if (resend_start >= 0)
- {
- // End of a run of resend tics
-
- //printf("SV: resend request timed out: %i-%i\n", resend_start, resend_end);
- NET_SV_SendResendRequest(client,
- recvwindow_start + resend_start,
- recvwindow_start + resend_end);
-
- resend_start = -1;
- }
+ // End of a run of resend tics
+ NET_Log("server: resend request to %s timed out for %d-%d (%d)",
+ NET_AddrToString(client->addr),
+ recvwindow_start + resend_start,
+ recvwindow_start + resend_end,
+ &recvwindow[resend_start][player].resend_time);
+ NET_SV_SendResendRequest(client,
+ recvwindow_start + resend_start,
+ recvwindow_start + resend_end);
+
+ resend_start = -1;
}
}
if (resend_start >= 0)
{
- NET_SV_SendResendRequest(client,
+ NET_Log("server: resend request to %s timed out for %d-%d (%d)",
+ NET_AddrToString(client->addr),
+ recvwindow_start + resend_start,
+ recvwindow_start + resend_end,
+ &recvwindow[resend_start][player].resend_time);
+ NET_SV_SendResendRequest(client,
recvwindow_start + resend_start,
recvwindow_start + resend_end);
}
@@ -1078,32 +1125,36 @@ static void NET_SV_ParseGameData(net_packet_t *packet, net_client_t *client)
if (server_state != SERVER_IN_GAME)
{
+ NET_Log("server: error: not in game state: server_state=%d",
+ server_state);
return;
}
if (client->drone)
{
// Drones do not contribute any game data.
+ NET_Log("server: error: game data from a drone?");
return;
}
player = client->player_number;
// Read header
-
if (!NET_ReadInt8(packet, &ackseq)
|| !NET_ReadInt8(packet, &seq)
|| !NET_ReadInt8(packet, &num_tics))
{
+ NET_Log("server: error: failed to read header");
return;
}
- // Get the current time
+ NET_Log("server: got game data, seq=%d, num_tics=%d, ackseq=%d",
+ seq, num_tics, ackseq);
+ // Get the current time
nowtime = I_GetTimeMS();
// Expand 8-bit values to the full sequence number
-
ackseq = NET_SV_ExpandTicNum(ackseq);
seq = NET_SV_ExpandTicNum(seq);
@@ -1141,6 +1192,7 @@ static void NET_SV_ParseGameData(net_packet_t *packet, net_client_t *client)
if (ackseq > client->acknowledged)
{
+ NET_Log("server: acknowledged up to %d", ackseq);
client->acknowledged = ackseq;
}
@@ -1184,15 +1236,11 @@ static void NET_SV_ParseGameData(net_packet_t *packet, net_client_t *client)
}
// Possibly send a resend request
-
if (resend_start < resend_end)
{
- /*
- printf("missed %i-%i before %i, send resend\n",
- recvwindow_start + resend_start,
- recvwindow_start + resend_end - 1,
- seq);
- */
+ NET_Log("server: request resend for %d-%d before %d",
+ recvwindow_start + resend_start,
+ recvwindow_start + resend_end - 1, seq);
NET_SV_SendResendRequest(client,
recvwindow_start + resend_start,
recvwindow_start + resend_end - 1);
@@ -1203,8 +1251,12 @@ static void NET_SV_ParseGameDataACK(net_packet_t *packet, net_client_t *client)
{
unsigned int ackseq;
+ NET_Log("server: processing game data ack packet");
+
if (server_state != SERVER_IN_GAME)
{
+ NET_Log("server: error: not in game state, server_state=%d",
+ server_state);
return;
}
@@ -1212,6 +1264,7 @@ static void NET_SV_ParseGameDataACK(net_packet_t *packet, net_client_t *client)
if (!NET_ReadInt8(packet, &ackseq))
{
+ NET_Log("server: error: missing acknowledgement field");
return;
}
@@ -1223,6 +1276,7 @@ static void NET_SV_ParseGameDataACK(net_packet_t *packet, net_client_t *client)
if (ackseq > client->acknowledged)
{
+ NET_Log("server: acknowledged up to %d", ackseq);
client->acknowledged = ackseq;
}
}
@@ -1275,11 +1329,14 @@ static void NET_SV_ParseResendRequest(net_packet_t *packet, net_client_t *client
unsigned int num_tics;
unsigned int i;
+ NET_Log("server: processing resend request");
+
// Read the starting tic and number of tics
if (!NET_ReadInt32(packet, &start)
|| !NET_ReadInt8(packet, &num_tics))
{
+ NET_Log("server: error: missing fields for resend");
return;
}
@@ -1301,13 +1358,14 @@ static void NET_SV_ParseResendRequest(net_packet_t *packet, net_client_t *client
// This is pretty fatal. We could disconnect the client,
// but then again this could be a spoofed packet. Just
// ignore it.
-
+ NET_Log("server: error: don't have tic %d any more, "
+ "can't resend", i);
return;
}
}
// Resend those tics
-
+ NET_Log("server: resending tics %d-%d", start, last);
NET_SV_SendTics(client, start, last);
}
@@ -1356,7 +1414,7 @@ void NET_SV_SendQueryResponse(net_addr_t *addr)
}
// Send it and we're done.
-
+ NET_Log("server: sending query response to %s", NET_AddrToString(addr));
reply = NET_NewPacket(64);
NET_WriteInt16(reply, NET_PACKET_TYPE_QUERY_RESPONSE);
NET_WriteQueryData(reply, &querydata);
@@ -1392,6 +1450,10 @@ static void NET_SV_Packet(net_packet_t *packet, net_addr_t *addr)
return;
}
+ NET_Log("server: packet from %s; type %d", NET_AddrToString(addr),
+ packet_type & ~NET_RELIABLE_PACKET);
+ NET_LogPacket(packet);
+
if (packet_type == NET_PACKET_TYPE_SYN)
{
NET_SV_ParseSYN(packet, client, addr);
@@ -1512,8 +1574,6 @@ static void NET_SV_PumpSendQueue(net_client_t *client)
return;
}
- //printf("SV: have complete ticcmd for %i\n", client->sendseq);
-
// We have all data we need to generate a command for this tic.
cmd.seq = client->sendseq;
@@ -1564,6 +1624,8 @@ static void NET_SV_PumpSendQueue(net_client_t *client)
if (starttic < 0)
starttic = 0;
+ NET_Log("server: send tics %d-%d to %s", starttic, endtic,
+ NET_AddrToString(client->addr));
NET_SV_SendTics(client, starttic, endtic);
++client->sendseq;
@@ -1594,6 +1656,10 @@ void NET_SV_CheckDeadlock(net_client_t *client)
if (nowtime - client->last_gamedata_time > 1000)
{
+ NET_Log("server: no gamedata from %s since %d - deadlock?",
+ NET_AddrToString(client->addr),
+ client->last_gamedata_time);
+
// Search the receive window for the first tic we are expecting
// from this player.
@@ -1601,7 +1667,8 @@ void NET_SV_CheckDeadlock(net_client_t *client)
{
if (!recvwindow[client->player_number][i].active)
{
- //printf("Possible deadlock: Sending resend request\n");
+ NET_Log("server: deadlock: sending resend request for %d-%d",
+ recvwindow_start + i, recvwindow_start + i + 5);
// Found a tic we haven't received. Send a resend request.
@@ -1642,14 +1709,16 @@ static void NET_SV_RunClient(net_client_t *client)
// Run common code
NET_Conn_Run(&client->connection);
-
+
if (client->connection.state == NET_CONN_STATE_DISCONNECTED
&& client->connection.disconnect_reason == NET_DISCONNECT_TIMEOUT)
{
+ NET_Log("server: client at %s timed out",
+ NET_AddrToString(client->addr));
NET_SV_BroadcastMessage("Client '%s' timed out and disconnected",
client->name);
}
-
+
// Is this client disconnected?
if (client->connection.state == NET_CONN_STATE_DISCONNECTED)
@@ -1677,6 +1746,7 @@ static void NET_SV_RunClient(net_client_t *client)
if (NET_SV_NumPlayers() <= 0)
{
+ NET_Log("server: no player clients left, game ended");
NET_SV_GameEnded();
}
}