improve packet error logging and handling

This commit is contained in:
p2r3
2025-08-23 01:50:14 +03:00
parent 313c31bf7d
commit 4a90979e2f
5 changed files with 74 additions and 65 deletions

View File

@@ -38,6 +38,13 @@
// player counts. For very many players, makes movement look jittery. // player counts. For very many players, makes movement look jittery.
#define SCALE_MOVEMENT_UPDATES_TO_PLAYER_COUNT #define SCALE_MOVEMENT_UPDATES_TO_PLAYER_COUNT
// If defined, logs unrecognized packet IDs
// #define DEV_LOG_UNKNOWN_PACKETS
// If defined, logs cases when packet length doesn't match parsed byte count
#define DEV_LOG_LENGTH_DISCREPANCY
// If defined, log chunk generation events
#define DEV_LOG_CHUNK_GENERATION
#define STATE_NONE 0 #define STATE_NONE 0
#define STATE_STATUS 1 #define STATE_STATUS 1
#define STATE_LOGIN 2 #define STATE_LOGIN 2

View File

@@ -13,6 +13,7 @@ inline int div_floor (int a, int b) {
return a % b < 0 ? (a - b) / b : a / b; return a % b < 0 ? (a - b) / b : a / b;
} }
extern uint64_t total_bytes_received;
ssize_t recv_all (int client_fd, void *buf, size_t n, uint8_t require_first); ssize_t recv_all (int client_fd, void *buf, size_t n, uint8_t require_first);
ssize_t send_all (int client_fd, const void *buf, ssize_t len); ssize_t send_all (int client_fd, const void *buf, ssize_t len);

View File

@@ -35,40 +35,34 @@
void handlePacket (int client_fd, int length, int packet_id) { void handlePacket (int client_fd, int length, int packet_id) {
int state = getClientState(client_fd); int state = getClientState(client_fd);
uint64_t bytes_received_start = total_bytes_received;
switch (packet_id) { switch (packet_id) {
case 0x00: case 0x00:
if (state == STATE_NONE) { if (state == STATE_NONE) {
if (cs_handshake(client_fd)) break; if (cs_handshake(client_fd)) break;
return;
} else if (state == STATE_LOGIN) { } else if (state == STATE_LOGIN) {
uint8_t uuid[16]; uint8_t uuid[16];
char name[16]; char name[16];
if (cs_loginStart(client_fd, uuid, name)) break; if (cs_loginStart(client_fd, uuid, name)) break;
if (reservePlayerData(client_fd, uuid, name)) break; if (reservePlayerData(client_fd, uuid, name)) break;
if (sc_loginSuccess(client_fd, uuid, name)) break; if (sc_loginSuccess(client_fd, uuid, name)) break;
return;
} else if (state == STATE_CONFIGURATION) { } else if (state == STATE_CONFIGURATION) {
if (cs_clientInformation(client_fd)) break; if (cs_clientInformation(client_fd)) break;
if (sc_knownPacks(client_fd)) break; if (sc_knownPacks(client_fd)) break;
if (sc_registries(client_fd)) break; if (sc_registries(client_fd)) break;
return;
} }
break; break;
case 0x02: case 0x02:
if (state == STATE_CONFIGURATION) { if (state == STATE_CONFIGURATION) cs_pluginMessage(client_fd);
if (cs_pluginMessage(client_fd)) break;
return;
}
break; break;
case 0x03: case 0x03:
if (state == STATE_LOGIN) { if (state == STATE_LOGIN) {
printf("Client Acknowledged Login\n\n"); printf("Client Acknowledged Login\n\n");
setClientState(client_fd, STATE_CONFIGURATION); setClientState(client_fd, STATE_CONFIGURATION);
return;
} else if (state == STATE_CONFIGURATION) { } else if (state == STATE_CONFIGURATION) {
printf("Client Acknowledged Configuration\n\n"); printf("Client Acknowledged Configuration\n\n");
@@ -111,7 +105,6 @@ void handlePacket (int client_fd, int length, int packet_id) {
); );
} }
return;
} }
break; break;
@@ -124,53 +117,33 @@ void handlePacket (int client_fd, int length, int packet_id) {
break; break;
case 0x08: case 0x08:
if (state == STATE_PLAY) { if (state == STATE_PLAY) cs_chat(client_fd);
cs_chat(client_fd);
return;
}
break; break;
case 0x0B: case 0x0B:
if (state == STATE_PLAY) { if (state == STATE_PLAY) cs_clientStatus(client_fd);
if (cs_clientStatus(client_fd)) break;
return;
}
break; break;
case 0x0C: case 0x0C: // Client tick (ignored)
if (state == STATE_PLAY) {
// client tick
return;
}
break; break;
case 0x11: case 0x11:
if (state == STATE_PLAY) { if (state == STATE_PLAY) cs_clickContainer(client_fd);
cs_clickContainer(client_fd);
return;
}
break; break;
case 0x12: case 0x12:
if (state == STATE_PLAY) { if (state == STATE_PLAY) cs_closeContainer(client_fd);
cs_closeContainer(client_fd);
return;
}
break; break;
case 0x1B: case 0x1B:
if (state == STATE_PLAY) { if (state == STATE_PLAY) {
// Serverbound keep-alive (ignored) // Serverbound keep-alive (ignored)
recv_all(client_fd, recv_buffer, 8, false); recv_all(client_fd, recv_buffer, length, false);
return;
} }
break; break;
case 0x19: case 0x19:
if (state == STATE_PLAY) { if (state == STATE_PLAY) cs_interact(client_fd);
if (cs_interact(client_fd)) break;
return;
}
break; break;
case 0x1D: case 0x1D:
@@ -202,7 +175,7 @@ void handlePacket (int client_fd, int length, int packet_id) {
} }
// Don't continue if all we got were flags // Don't continue if all we got were flags
if (packet_id == 0x20) return; if (packet_id == 0x20) break;
// Update rotation in player data (if applicable) // Update rotation in player data (if applicable)
if (packet_id != 0x1D) { if (packet_id != 0x1D) {
@@ -241,7 +214,7 @@ void handlePacket (int client_fd, int length, int packet_id) {
} }
// Don't continue if all we got was rotation data // Don't continue if all we got was rotation data
if (packet_id == 0x1F) return; if (packet_id == 0x1F) break;
// Cast the values to short to get integer position // Cast the values to short to get integer position
short cx = x, cy = y, cz = z; short cx = x, cy = y, cz = z;
@@ -257,7 +230,7 @@ void handlePacket (int client_fd, int length, int packet_id) {
player->z = cz; player->z = cz;
// Exit early if no chunk borders were crossed // Exit early if no chunk borders were crossed
if (dx == 0 && dz == 0) return; if (dx == 0 && dz == 0) break;
// Check if the player has recently been in this chunk // Check if the player has recently been in this chunk
int found = false; int found = false;
@@ -267,7 +240,7 @@ void handlePacket (int client_fd, int length, int packet_id) {
break; break;
} }
} }
if (found) return; if (found) break;
// Update player's recently visited chunks // Update player's recently visited chunks
for (int i = 0; i < VISITED_HISTORY - 1; i ++) { for (int i = 0; i < VISITED_HISTORY - 1; i ++) {
@@ -277,12 +250,14 @@ void handlePacket (int client_fd, int length, int packet_id) {
player->visited_x[VISITED_HISTORY - 1] = _x; player->visited_x[VISITED_HISTORY - 1] = _x;
player->visited_z[VISITED_HISTORY - 1] = _z; player->visited_z[VISITED_HISTORY - 1] = _z;
printf("sending new chunks (%d, %d)\n", _x, _z);
sc_setCenterChunk(client_fd, _x, _z); sc_setCenterChunk(client_fd, _x, _z);
int count = 0; int count = 0;
clock_t start, end; #ifdef DEV_LOG_CHUNK_GENERATION
start = clock(); printf("Sending new chunks (%d, %d)\n", _x, _z);
clock_t start, end;
start = clock();
#endif
uint32_t r = fast_rand(); uint32_t r = fast_rand();
// One in every 4 new chunks spawns a mob // One in every 4 new chunks spawns a mob
@@ -331,42 +306,60 @@ void handlePacket (int client_fd, int length, int packet_id) {
dz += dz > 0 ? -1 : 1; dz += dz > 0 ? -1 : 1;
} }
end = clock(); #ifdef DEV_LOG_CHUNK_GENERATION
double total_ms = (double)(end - start) / CLOCKS_PER_SEC * 1000; end = clock();
printf("generated %d chunks in %.0f ms (%.2f ms per chunk)\n", count, total_ms, total_ms / (double)count); double total_ms = (double)(end - start) / CLOCKS_PER_SEC * 1000;
printf("Generated %d chunks in %.0f ms (%.2f ms per chunk)\n", count, total_ms, total_ms / (double)count);
#endif
return;
} }
break; break;
case 0x34: case 0x34:
if (state == STATE_PLAY) { if (state == STATE_PLAY) cs_setHeldItem(client_fd);
cs_setHeldItem(client_fd);
return;
}
break; break;
case 0x28: case 0x28:
if (state == STATE_PLAY) { if (state == STATE_PLAY) cs_playerAction(client_fd);
cs_playerAction(client_fd);
return;
}
break; break;
case 0x3F: case 0x3F:
if (state == STATE_PLAY) { if (state == STATE_PLAY) cs_useItemOn(client_fd);
cs_useItemOn(client_fd);
return;
}
break; break;
default: break; default:
#ifdef DEV_LOG_UNKNOWN_PACKETS
printf("Unknown packet: 0x");
if (packet_id < 16) printf("0");
printf("%X, length: %d, state: %d\n\n", packet_id, length, state);
#endif
recv_all(client_fd, recv_buffer, length, false);
break;
} }
// if (packet_id < 16) printf("Unknown/bad packet: 0x0%X, length: %d, state: %d\n\n", packet_id, length, state); // Detect and fix incorrectly parsed packets
// else printf("Unknown/bad packet: 0x%X, length: %d, state: %d\n\n", packet_id, length, state); int processed_length = total_bytes_received - bytes_received_start;
recv_count = recv(client_fd, recv_buffer, length, 0); if (processed_length == length) return;
if (length > processed_length) {
recv_all(client_fd, recv_buffer, length - processed_length, false);
}
#ifdef DEV_LOG_LENGTH_DISCREPANCY
if (processed_length != 0) {
printf("WARNING: Packet 0x");
if (packet_id < 16) printf("0");
printf("%X parsed incorrectly!\n Expected: %d, parsed: %d\n\n", packet_id, length, processed_length);
}
#endif
#ifdef DEV_LOG_UNKNOWN_PACKETS
if (processed_length == 0) {
printf("Unknown packet: 0x");
if (packet_id < 16) printf("0");
printf("%X, length: %d, state: %d\n\n", packet_id, length, state);
}
#endif
} }

View File

@@ -256,10 +256,11 @@ int sc_playerAbilities (int client_fd, uint8_t flags) {
// S->C Update Time // S->C Update Time
int sc_updateTime (int client_fd, uint64_t ticks) { int sc_updateTime (int client_fd, uint64_t ticks) {
writeVarInt(client_fd, sizeVarInt(0x6A) + 17); writeVarInt(client_fd, 18);
writeVarInt(client_fd, 0x6A); writeVarInt(client_fd, 0x6A);
writeUint64(client_fd, get_program_time() / 50000); uint64_t world_age = get_program_time() / 50000;
writeUint64(client_fd, world_age);
writeUint64(client_fd, ticks); writeUint64(client_fd, ticks);
writeByte(client_fd, true); writeByte(client_fd, true);

View File

@@ -29,6 +29,10 @@ static uint64_t htonll (uint64_t value) {
#endif #endif
} }
// Keep track of the total amount of bytes received with recv_all
// Helps notice misread packets and clean up after errors
uint64_t total_bytes_received = 0;
ssize_t recv_all (int client_fd, void *buf, size_t n, uint8_t require_first) { ssize_t recv_all (int client_fd, void *buf, size_t n, uint8_t require_first) {
char *p = buf; char *p = buf;
size_t total = 0; size_t total = 0;
@@ -52,15 +56,18 @@ ssize_t recv_all (int client_fd, void *buf, size_t n, uint8_t require_first) {
task_yield(); task_yield();
continue; continue;
} else { } else {
total_bytes_received += total;
return -1; // real error return -1; // real error
} }
} else if (r == 0) { } else if (r == 0) {
// connection closed before full read // connection closed before full read
total_bytes_received += total;
return total; return total;
} }
total += r; total += r;
} }
total_bytes_received += total;
return total; // got exactly n bytes return total; // got exactly n bytes
} }