ref: 31accc834d768a8a6431a20fa1895f4f01f24442
parent: 124ca83db41b79b2fb48509e548a9d1205429390
author: Simon Howard <fraggle@soulsphere.org>
date: Sun Jan 27 18:36:50 EST 2019
net: Add logging of server events.
--- a/src/net_server.c
+++ b/src/net_server.c
@@ -483,7 +483,7 @@
// 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 @@
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 @@
{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 @@
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 @@
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,6 +610,7 @@
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 ".");
@@ -610,6 +617,7 @@
return;
default:
+ NET_Log("server: error: wrong magic number: %d", magic);return;
}
@@ -619,6 +627,7 @@
client_version = NET_ReadString(packet);
if (client_version == NULL)
{+ NET_Log("server: error: no version from client");return;
}
@@ -635,15 +644,24 @@
"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 @@
player_name = NET_ReadString(packet);
if (player_name == NULL)
{+ NET_Log("server: error: failed to read player name");return;
}
@@ -659,6 +678,8 @@
// 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 @@
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 @@
{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 @@
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 @@
// Client already connected?
if (client->active)
{+ NET_Log("server: client is already initialized (duplicate SYN?)");return;
}
@@ -767,10 +795,14 @@
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 @@
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 @@
}
// Change server state
-
+ NET_Log("server: beginning game state");server_state = SERVER_IN_GAME;
memset(recvwindow, 0, sizeof(recvwindow));
@@ -891,10 +925,14 @@
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 @@
{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 @@
if (!NET_ReadSettings(packet, &settings))
{// Malformed packet
-
+ NET_Log("server: error: no settings from controller");return;
}
@@ -939,6 +981,7 @@
if (!NET_ValidGameSettings(sv_gamemode, sv_gamemission, &settings))
{+ NET_Log("server: error: invalid game settings");return;
}
@@ -966,7 +1009,8 @@
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 @@
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
+ // 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);
- //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;
- }
+ 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,6 +1125,8 @@
if (server_state != SERVER_IN_GAME)
{+ NET_Log("server: error: not in game state: server_state=%d",+ server_state);
return;
}
@@ -1084,6 +1133,7 @@
if (client->drone)
{// Drones do not contribute any game data.
+ NET_Log("server: error: game data from a drone?");return;
}
@@ -1090,20 +1140,21 @@
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 @@
if (ackseq > client->acknowledged)
{+ NET_Log("server: acknowledged up to %d", ackseq);client->acknowledged = ackseq;
}
@@ -1184,15 +1236,11 @@
}
// 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 @@
{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 @@
if (!NET_ReadInt8(packet, &ackseq))
{+ NET_Log("server: error: missing acknowledgement field");return;
}
@@ -1223,6 +1276,7 @@
if (ackseq > client->acknowledged)
{+ NET_Log("server: acknowledged up to %d", ackseq);client->acknowledged = ackseq;
}
}
@@ -1275,11 +1329,14 @@
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 @@
// 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 @@
}
// 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 @@
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 @@
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 @@
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 @@
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 @@
{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 @@
// 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 @@
if (NET_SV_NumPlayers() <= 0)
{+ NET_Log("server: no player clients left, game ended");NET_SV_GameEnded();
}
}